-
Type: Bug
-
Resolution: Fixed
-
Priority: Major - P3
-
Affects Version/s: None
-
Fully Compatible
-
ALL
-
v5.2, v5.1, v5.0, v4.4, v4.2
-
QE 2021-10-04, QE 2021-10-18, QE 2021-11-01, QE 2021-11-15, QE 2021-11-29, QE 2021-12-13, QE 2021-12-27, QE 2022-01-10, QE 2022-01-24
-
(copied to CRM)
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.