[SERVER-53525] aggregate $lookup is very slow, it is not equal to the explain() time。 (22244ms:414ms) Created: 28/Dec/20  Updated: 22/Jan/21  Resolved: 22/Jan/21

Status: Closed
Project: Core Server
Component/s: Aggregation Framework, Querying
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: y yz Assignee: Edwin Zhou
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-29421 Aggregation executionStats or allPlan... Closed
Operating System: ALL
Steps To Reproduce:

mongo version: 3.6.13
linux 3.10, centos 7

Participants:

 Description   

If there are no conditions(.explain("executionStats")), it is very slow,the query and slow log as following:
query:

soloop_KdTdfHyZ_shard_2:SECONDARY> 
soloop_KdTdfHyZ_shard_2:SECONDARY> db.getCollection('video_info').aggregate( [{"$lookup": {"from": "user_info", "localField": "soloop_id", "foreignField": "soloop_id", "as": "docs_userTab"}}, {"$lookup": {"from": "video_check", "localField": "feed_id", "foreignField": "_id", "as": "docs_videoCheck"}}, {"$match": {"$and": [{"video_type": 2}, {}, {}, {}]}}, {"$count": "cnt"}])
{ "cnt" : 229671 }
soloop_KdTdfHyZ_shard_2:SECONDARY> 

slowlog:

2020-12-28T18:18:59.219+0800 I COMMAND  [conn187] command soloop_user.video_info appName: "MongoDB Shell" command: aggregate { aggregate: "video_info", pipeline: [ { $lookup: { from: "user_info", localField: "soloop_id", foreignField: "soloop_id", as: "docs_userTab" } }, { $lookup: { from: "video_check", localField: "feed_id", foreignField: "_id", as: "docs_videoCheck" } }, { $match: { $and: [ { video_type: 2.0 }, {}, {}, {} ] } }, { $count: "cnt" } ], cursor: {}, lsid: { id: UUID("15396d73-c647-41f8-8823-5074a58c285f") }, $clusterTime: { clusterTime: Timestamp(1609150708, 27), signature: { hash: BinData(0, 350DC28A151DB4D3B2A9CEF11EE2A7AFD9556ABA), keyId: 6867230734357102603 } }, $readPreference: { mode: "secondaryPreferred" }, $db: "soloop_user" } planSummary: IXSCAN { video_type: 1, status: 1, create_time: 1 } keysExamined:229671 docsExamined:229671 cursorExhausted:1 numYields:1806 nreturned:1 reslen:358 locks:{ Global: { acquireCount: { r: 1841012 }, acquireWaitCount: { r: 1881 }, timeAcquiringMicros: { r: 741652 } }, Database: { acquireCount: { r: 920506 } }, Collection: { acquireCount: { r: 920505 } } } protocol:op_msg 22244ms

If there are conditions(.explain("executionStats")), it is very quic,the query and log as following:
query sql:

 db.getCollection('video_info').explain("executionStats").aggregate( [{"$lookup": {"from": "user_info", "localField": "soloop_id", "foreignField": "soloop_id", "as": "docs_userTab"}}, {"$lookup": {"from": "video_check", "localField": "feed_id", "foreignField": "_id", "as": "docs_videoCheck"}}, {"$match": {"$and": [{"video_type": 2}, {}, {}, {}]}}, {"$count": "cnt"}])

log:

2020-12-28T18:23:41.109+0800 I COMMAND  [conn187] command soloop_user.video_info appName: "MongoDB Shell" command: explain { explain: { aggregate: "video_info", pipeline: [ { $lookup: { from: "user_info", localField: "soloop_id", foreignField: "soloop_id", as: "docs_userTab" } }, { $lookup: { from: "video_check", localField: "feed_id", foreignField: "_id", as: "docs_videoCheck" } }, { $match: { $and: [ { video_type: 2.0 }, {}, {}, {} ] } }, { $count: "cnt" } ], cursor: {} }, verbosity: "executionStats", lsid: { id: UUID("15396d73-c647-41f8-8823-5074a58c285f") }, $clusterTime: { clusterTime: Timestamp(1609150988, 104), signature: { hash: BinData(0, C97A46869BBB3B61A9BD3FD52F538B6A8337A312), keyId: 6867230734357102603 } }, $readPreference: { mode: "secondaryPreferred" }, $db: "soloop_user" } planSummary: IXSCAN { video_type: 1, status: 1, create_time: 1 } numYields:1794 reslen:2569 locks:{ Global: { acquireCount: { r: 3596 }, acquireWaitCount: { r: 31 }, timeAcquiringMicros: { r: 11652 } }, Database: { acquireCount: { r: 1798 } }, Collection: { acquireCount: { r: 1797 } } } protocol:op_msg 414ms

If there are conditions(.explain("executionStats")), it is very slow,the slow log as following:



 Comments   
Comment by Edwin Zhou [ 22/Jan/21 ]

Hi 1147952115@qq.com,

The discrepancy in runtime you've observed in .explain("executionStats") is because only the part of the query listed under the $cursor stage would actually be executed. That means using .explain() and $lookup will not execute the $lookup stage. This issue was fixed in SERVER-29421. SERVER-21784 improved "executionStats" explain for agg to report an "executionTimeMillisEstimate" field for every stage in the pipeline. If you were to run this explain after upgrading to 4.4, you will see time estimates associated with all stages in the pipeline including $lookup.

Best,
Edwin

Generated at Thu Feb 08 05:31:10 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.