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

Incorrect logging of queryHash/planCacheKey for operations that share the same $lookup shape

    XMLWordPrintable

    Details

    • Operating System:
      ALL
    • Backport Requested:
      v5.0, v4.4, v4.2
    • Sprint:
      QE 2021-10-04, QE 2021-10-18, QE 2021-11-01
    • Case:

      Description

      When multiple aggregation operations with different compositions share an identical $lookup stage, the log entry that is generated for the aggregate command can incorrectly list the queryHash and planCacheKey. It appears to be showing the values from the $lookup collection's plan cache; not the collection the operation was targeting.

      db.setProfilingLevel(0, { slowms: 0 })
       
      db.foo.drop(); db.foo.insert({ a: 1, b: 1, c: 1 }); 
      db.foo.createIndexes([{ a: 1, b: 1 }, { b: 1, a: 1 }]);
      db.bar.drop(); db.bar.insert({ a: 1, b: 1, c: 1 }); 
      db.bar.createIndexes([{ a: 1, b: 1, c: 1 }, { b: 1, a: 1, c: 1 }])
       
       
      db.foo.aggregate([
      {"$match":{ $or: [ { a: 1 }, { b: 1 } ]}},
      {"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}},
      ])
       
      db.foo.aggregate([
      {"$match":{ a: { $in: [ 1, 2, 3, 4, 5 ] } } },
      {"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}},
      ])
       
      db.foo.aggregate([
      {"$match":{ b: 1 }},
      {"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}},
      ])
      

      The output of the above will be similar to the following, which each list those fields as "queryHash":"ABFD1233","planCacheKey":"80A4A233" though the operations are clearly different:

      {"t":{"$date":"2021-09-02T12:19:47.015-04:00"},"s":"I","c":"COMMAND","id":51803,"ctx":"conn4","msg":"Slow query","attr":{"type":"command","ns":"test.foo","command":{"aggregate":"foo","pipeline":[{"$match":{"$or":[{"a":1},{"b":1}]}},{"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}}],"cursor":{},"$db":"test","lsid":{"id":{"$uuid":"8ad43435-01e8-4984-9f78-98cb37c1e463"}}},"planSummary":"IXSCAN { a: 1, b: 1 }, IXSCAN { b: 1, a: 1 }","keysExamined":3,"docsExamined":2,"cursorExhausted":true,"numYields":0,"nreturned":1,"queryHash":"ABFD1233","planCacheKey":"80A4A233","reslen":223,"locks":{"Global":{"acquireCount":{"r":4}},"Mutex":{"acquireCount":{"r":4}}},"storage":{"data":{"bytesRead":412}},"remote":"127.0.0.1:59396","protocol":"op_msg","durationMillis":12}}

      {"t":{"$date":"2021-09-02T12:19:47.450-04:00"},"s":"I","c":"COMMAND","id":51803,"ctx":"conn4","msg":"Slow query","attr":{"type":"command","ns":"test.foo","command":{"aggregate":"foo","pipeline":[{"$match":{"a":{"$in":[1,2,3,4,5]}}},{"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}}],"cursor":{},"$db":"test","lsid":{"id":{"$uuid":"8ad43435-01e8-4984-9f78-98cb37c1e463"}}},"planSummary":"IXSCAN { a: 1, b: 1 }","keysExamined":2,"docsExamined":2,"cursorExhausted":true,"numYields":0,"nreturned":1,"queryHash":"ABFD1233","planCacheKey":"80A4A233","reslen":223,"locks":{"Global":{"acquireCount":{"r":4}},"Mutex":{"acquireCount":{"r":4}}},"storage":{},"remote":"127.0.0.1:59396","protocol":"op_msg","durationMillis":1}}

      {"t":{"$date":"2021-09-02T12:19:47.917-04:00"},"s":"I","c":"COMMAND","id":51803,"ctx":"conn4","msg":"Slow query","attr":{"type":"command","ns":"test.foo","command":{"aggregate":"foo","pipeline":[{"$match":{"b":1}},{"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}}],"cursor":{},"$db":"test","lsid":{"id":{"$uuid":"8ad43435-01e8-4984-9f78-98cb37c1e463"}}},"planSummary":"IXSCAN { b: 1, a: 1 }","keysExamined":2,"docsExamined":2,"cursorExhausted":true,"numYields":0,"nreturned":1,"queryHash":"ABFD1233","planCacheKey":"80A4A233","reslen":223,"locks":{"Global":{"acquireCount":{"r":4}},"Mutex":{"acquireCount":{"r":4}}},"storage":{},"remote":"127.0.0.1:59396","protocol":"op_msg","durationMillis":0}}

      Checking the plan caches for the two collections will show the duplicate values above belong to test.bar; not test.foo. If you run with explain however you get the actual values (and what should likely be logged):

      db.foo.explain().aggregate([
      {"$match":{ $or: [ { a: 1 }, { b: 1 } ]}},
      {"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}},
      ]).stages[0].$cursor.queryPlanner.planCacheKey
      // 070E843B
       
      db.foo.explain().aggregate([
      {"$match":{ a: { $in: [ 1, 2, 3, 4, 5 ] } } },
      {"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}},
      ]).stages[0].$cursor.queryPlanner.planCacheKey
      // 5BD7613D
       
      db.foo.explain().aggregate([
      {"$match":{ b: 1 }},
      {"$lookup":{"from":"bar","let":{"b":{"$ifNull":["$b",null]}},"pipeline":[{"$match":{"$or":[{"a":{"$exists":false}},{"a":1}]}},{"$match":{"$expr":{"$eq":["$b","$$b"]}}}],"as":"bar"}},
      ]).stages[0].$cursor.queryPlanner.planCacheKey
      // 3C84EBC6
      

      This has been tested and verified on 5.0.2-ent and 4.2.15-ent and appears to only affect the logged representation of these values.

        Attachments

          Activity

            People

            Assignee:
            jennifer.peshansky Jennifer Peshansky
            Reporter:
            alex.bevilacqua Alex Bevilacqua
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Dates

              Created:
              Updated: