Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-53525

aggregate $lookup is very slow, it is not equal to the explain() time。 (22244ms:414ms)

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • None
    • ALL
    • Hide

      mongo version: 3.6.13
      linux 3.10, centos 7

      Show
      mongo version: 3.6.13 linux 3.10, centos 7

      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:

            Assignee:
            edwin.zhou@mongodb.com Edwin Zhou
            Reporter:
            1147952115@qq.com y yz
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: