[SERVER-79702] $lookup subpipeline exectionStats output all 0 Created: 04/Aug/23  Updated: 09/Oct/23  Resolved: 09/Oct/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 6.0.5
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: jing xu Assignee: Alison Rhea Thorne
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

my server is 6.0.5 cluster.
cluster has two shards.now i use $lookup for two tables.when i want to analyze explain for lookup subpipeline.but all output is 0.

totalDocsExamined: Long("0"),
totalKeysExamined: Long("0"),
collectionScans: Long("0"),
indexesUsed: [],

[direct: mongos] datacenter> db.order.aggregate([{$match:{createTime: {$gt:ISODate("2023-08-03T00:00:00")}}},{$lookup:{from:"terminal",localField:"waybillNo",foreignField:"waybillNo",as:"output"}},{$match:{output:{$ne:[]}}}]).itcount()
151
[direct: mongos] datacenter>
[direct: mongos] datacenter> db.order.aggregate([{$match:{createTime: {$gt:ISODate("2023-08-03T00:00:00")}}},{$lookup:{from:"terminal",localField:"waybillNo",foreignField:"waybillNo",as:"output"}},{$match:{output:{$ne:[]}}}],{'explain':"executionStats"})
{
  serverInfo: {
    host: 'xxxx',
    port: 31051,
    version: '6.0.5',
    gitVersion: 'c9a99c120371d4d4c52cbb15dac34a36ce8d3b1d'
  },
  serverParameters: {
    internalQueryFacetBufferSizeBytes: 104857600,
    internalQueryFacetMaxOutputDocSizeBytes: 104857600,
    internalLookupStageIntermediateDocumentMaxSizeBytes: 104857600,
    internalDocumentSourceGroupMaxMemoryBytes: 104857600,
    internalQueryMaxBlockingSortMemoryUsageBytes: 104857600,
    internalQueryProhibitBlockingMergeOnMongoS: 0,
    internalQueryMaxAddToSetBytes: 104857600,
    internalDocumentSourceSetWindowFieldsMaxMemoryBytes: 104857600
  },
  mergeType: 'mongos',
  splitPipeline: {
    shardsPart: [
      {
        '$match': { createTime: { '$gt': ISODate("2023-08-03T00:00:00.000Z") } }
      },
      {
        '$lookup': {
          from: 'terminal',
          as: 'output',
          localField: 'waybillNo',
          foreignField: 'waybillNo'
        }
      },
      {
        '$match': { output: { '$not': { '$eq': [] } } }
      }
    ],
    mergerPart: [
      {
        '$mergeCursors': {
          lsid: {
            id: new UUID("a33d7596-2c08-475c-ab61-b188446698f2"),
            uid: Binary(Buffer.from("3b408cb48548b5037822c10eb0976b3cbf2cee3bf9c708796bf03941fbecd80f", "hex"), 0)
          },
          compareWholeSortKey: false,
          tailableMode: 'normal',
          nss: 'datacenter.order',
          allowPartialResults: false,
          recordRemoteOpWaitTime: false
        }
      }
    ]
  },
  shards: {
    shard1: {
      host: 'host1:31001',
      stages: [
        {
          '$cursor': {
            queryPlanner: {
              namespace: 'datacenter.order',
              indexFilterSet: false,
              parsedQuery: {
                createTime: { '$gt': ISODate("2023-08-03T00:00:00.000Z") }
              },
              queryHash: 'BFA14242',
              planCacheKey: '5D24761B',
              maxIndexedOrSolutionsReached: false,
              maxIndexedAndSolutionsReached: false,
              maxScansToExplodeReached: false,
              winningPlan: {
                stage: 'SHARDING_FILTER',
                inputStage: {
                  stage: 'FETCH',
                  inputStage: {
                    stage: 'IXSCAN',
                    keyPattern: { createTime: 1 },
                    indexName: 'createTime_1',
                    isMultiKey: false,
                    multiKeyPaths: { createTime: [] },
                    isUnique: false,
                    isSparse: false,
                    isPartial: false,
                    indexVersion: 2,
                    direction: 'forward',
                    indexBounds: {
                      createTime: [
                        '(new Date(1691020800000), new Date(9223372036854775807)]'
                      ]
                    }
                  }
                }
              },
              rejectedPlans: []
            },
            executionStats: {
              executionSuccess: true,
              nReturned: 317,
              executionTimeMillis: 196,
              totalKeysExamined: 317,
              totalDocsExamined: 317,
              executionStages: {
                stage: 'SHARDING_FILTER',
                nReturned: 317,
                executionTimeMillisEstimate: 0,
                works: 318,
                advanced: 317,
                needTime: 0,
                needYield: 0,
                saveState: 1,
                restoreState: 1,
                isEOF: 1,
                chunkSkips: 0,
                inputStage: {
                  stage: 'FETCH',
                  nReturned: 317,
                  executionTimeMillisEstimate: 0,
                  works: 318,
                  advanced: 317,
                  needTime: 0,
                  needYield: 0,
                  saveState: 1,
                  restoreState: 1,
                  isEOF: 1,
                  docsExamined: 317,
                  alreadyHasObj: 0,
                  inputStage: {
                    stage: 'IXSCAN',
                    nReturned: 317,
                    executionTimeMillisEstimate: 0,
                    works: 318,
                    advanced: 317,
                    needTime: 0,
                    needYield: 0,
                    saveState: 1,
                    restoreState: 1,
                    isEOF: 1,
                    keyPattern: { createTime: 1 },
                    indexName: 'createTime_1',
                    isMultiKey: false,
                    multiKeyPaths: { createTime: [] },
                    isUnique: false,
                    isSparse: false,
                    isPartial: false,
                    indexVersion: 2,
                    direction: 'forward',
                    indexBounds: {
                      createTime: [
                        '(new Date(1691020800000), new Date(9223372036854775807)]'
                      ]
                    },
                    keysExamined: 317,
                    seeks: 1,
                    dupsTested: 0,
                    dupsDropped: 0
                  }
                }
              }
            }
          },
          nReturned: Long("317"),
          executionTimeMillisEstimate: Long("0")
        },
        {
          '$lookup': {
            from: 'terminal',
            as: 'output',
            localField: 'waybillNo',
            foreignField: 'waybillNo'
          },
          totalDocsExamined: Long("0"),
          totalKeysExamined: Long("0"),
          collectionScans: Long("0"),
          indexesUsed: [],
          nReturned: Long("317"),
          executionTimeMillisEstimate: Long("195")
        },
        {
          '$match': { output: { '$not': { '$eq': [] } } },
          nReturned: Long("0"),
          executionTimeMillisEstimate: Long("195")
        }
      ]
    },
    shard2: {
      host: 'host2:31002',
      stages: [
        {
          '$cursor': {
            queryPlanner: {
              namespace: 'datacenter.order',
              indexFilterSet: false,
              parsedQuery: {
                createTime: { '$gt': ISODate("2023-08-03T00:00:00.000Z") }
              },
              queryHash: 'BFA14242',
              planCacheKey: '5D24761B',
              maxIndexedOrSolutionsReached: false,
              maxIndexedAndSolutionsReached: false,
              maxScansToExplodeReached: false,
              winningPlan: {
                stage: 'SHARDING_FILTER',
                inputStage: {
                  stage: 'FETCH',
                  inputStage: {
                    stage: 'IXSCAN',
                    keyPattern: { createTime: 1 },
                    indexName: 'createTime_1',
                    isMultiKey: false,
                    multiKeyPaths: { createTime: [] },
                    isUnique: false,
                    isSparse: false,
                    isPartial: false,
                    indexVersion: 2,
                    direction: 'forward',
                    indexBounds: {
                      createTime: [
                        '(new Date(1691020800000), new Date(9223372036854775807)]'
                      ]
                    }
                  }
                }
              },
              rejectedPlans: []
            },
            executionStats: {
              executionSuccess: true,
              nReturned: 736,
              executionTimeMillis: 420,
              totalKeysExamined: 736,
              totalDocsExamined: 736,
              executionStages: {
                stage: 'SHARDING_FILTER',
                nReturned: 736,
                executionTimeMillisEstimate: 7,
                works: 737,
                advanced: 736,
                needTime: 0,
                needYield: 0,
                saveState: 1,
                restoreState: 1,
                isEOF: 1,
                chunkSkips: 0,
                inputStage: {
                  stage: 'FETCH',
                  nReturned: 736,
                  executionTimeMillisEstimate: 5,
                  works: 737,
                  advanced: 736,
                  needTime: 0,
                  needYield: 0,
                  saveState: 1,
                  restoreState: 1,
                  isEOF: 1,
                  docsExamined: 736,
                  alreadyHasObj: 0,
                  inputStage: {
                    stage: 'IXSCAN',
                    nReturned: 736,
                    executionTimeMillisEstimate: 4,
                    works: 737,
                    advanced: 736,
                    needTime: 0,
                    needYield: 0,
                    saveState: 1,
                    restoreState: 1,
                    isEOF: 1,
                    keyPattern: { createTime: 1 },
                    indexName: 'createTime_1',
                    isMultiKey: false,
                    multiKeyPaths: { createTime: [] },
                    isUnique: false,
                    isSparse: false,
                    isPartial: false,
                    indexVersion: 2,
                    direction: 'forward',
                    indexBounds: {
                      createTime: [
                        '(new Date(1691020800000), new Date(9223372036854775807)]'
                      ]
                    },
                    keysExamined: 736,
                    seeks: 1,
                    dupsTested: 0,
                    dupsDropped: 0
                  }
                }
              }
            }
          },
          nReturned: Long("736"),
          executionTimeMillisEstimate: Long("7")
        },
        {
          '$lookup': {
            from: 'terminal',
            as: 'output',
            localField: 'waybillNo',
            foreignField: 'waybillNo'
          },
          totalDocsExamined: Long("0"),
          totalKeysExamined: Long("0"),
          collectionScans: Long("0"),
          indexesUsed: [],
          nReturned: Long("736"),
          executionTimeMillisEstimate: Long("420")
        },
        {
          '$match': { output: { '$not': { '$eq': [] } } },
          nReturned: Long("0"),
          executionTimeMillisEstimate: Long("420")
        }
      ]
    }
  },
  command: {
    aggregate: 'order',
    pipeline: [
      {
        '$match': { createTime: { '$gt': ISODate("2023-08-03T00:00:00.000Z") } }
      },
      {
        '$lookup': {
          from: 'terminal',
          localField: 'waybillNo',
          foreignField: 'waybillNo',
          as: 'output'
        }
      },
      { '$match': { output: { '$ne': [] } } }
    ],
    cursor: {}
  },
  ok: 1,
  '$clusterTime': {
    clusterTime: Timestamp({ t: 1691112367, i: 1 }),
    signature: {
      hash: Binary(Buffer.from("2460b999b760d306c2ce2357b7ed59596a224ca6", "hex"), 0),
      keyId: Long("7225447387848769561")
    }
  },
  operationTime: Timestamp({ t: 1691112367, i: 1 })
}



 Comments   
Comment by Alison Rhea Thorne [ 09/Oct/23 ]

We haven’t heard back from you for some time, so I’m going to close this ticket. If this is still an issue for you, please provide additional information and we will reopen the ticket.

Comment by Alison Rhea Thorne [ 25/Sep/23 ]

We still need additional information to diagnose the problem. If this is still an issue for you, would you please the exact steps required to replicate this issue?

Comment by Alison Rhea Thorne [ 05/Sep/23 ]

Hello,

Thank you for report.

Unfortunately, your report does not yet contain enough information for us to act upon. In order to begin diagnosing this problem we would like to request clarification on what behavior that you are observing vs your expected behavior. Additionally, we'd like to further request the steps required to reproduce the behavior that you have observed.

Comment by jing xu [ 04/Aug/23 ]

when inner table is not sharding,subpipeline all statistics is losing.

[direct: mongos] datacenter> db.order.aggregate([{$match:{createTime: {$gt:ISODate("2023-08-03T00:00:00")}}},{$lookup:{from:"terminalNosharding",localField:"waybillNo",foreignField:"waybillNo",as:"output"}},{$match:{output:{$ne:[]}}}],
{'explain':true}
)
{
serverInfo:
{ host: 'host1', port: 31051, version: '6.0.5', gitVersion: 'c9a99c120371d4d4c52cbb15dac34a36ce8d3b1d' }
,
serverParameters:
{ internalQueryFacetBufferSizeBytes: 104857600, internalQueryFacetMaxOutputDocSizeBytes: 104857600, internalLookupStageIntermediateDocumentMaxSizeBytes: 104857600, internalDocumentSourceGroupMaxMemoryBytes: 104857600, internalQueryMaxBlockingSortMemoryUsageBytes: 104857600, internalQueryProhibitBlockingMergeOnMongoS: 0, internalQueryMaxAddToSetBytes: 104857600, internalDocumentSourceSetWindowFieldsMaxMemoryBytes: 104857600 }
,
mergeType: 'primaryShard',
splitPipeline: {
shardsPart: [
{
'$match': { createTime:
{ '$gt': ISODate("2023-08-03T00:00:00.000Z") }
}
}
],
mergerPart: [
{
'$mergeCursors': {
lsid:
{ id: new UUID("84f45838-29f4-4c27-99cd-ad26bd1f943e"), uid: Binary(Buffer.from("3b408cb48548b5037822c10eb0976b3cbf2cee3bf9c708796bf03941fbecd80f", "hex"), 0) }
,
compareWholeSortKey: false,
tailableMode: 'normal',
nss: 'datacenter.order',
allowPartialResults: false,
recordRemoteOpWaitTime: false
}
},
{
'$lookup':
{ from: 'terminalNosharding', as: 'output', localField: 'waybillNo', foreignField: 'waybillNo' }
},
{
'$match': { output: { '$not':
{ '$eq': [] }
} }
}
]
},
shards: {
shard1: {
host: 'host1:31001',
queryPlanner: {
namespace: 'datacenter.order',
indexFilterSet: false,
parsedQuery: { createTime:
{ '$gt': ISODate("2023-08-03T00:00:00.000Z") }
},
queryHash: 'BFA14242',
planCacheKey: '5D24761B',
optimizedPipeline: true,
maxIndexedOrSolutionsReached: false,
maxIndexedAndSolutionsReached: false,
maxScansToExplodeReached: false,
winningPlan: {
stage: 'SHARDING_FILTER',
inputStage: {
stage: 'FETCH',
inputStage: {
stage: 'IXSCAN',
keyPattern:
{ createTime: 1 }
,
indexName: 'createTime_1',
isMultiKey: false,
multiKeyPaths:
{ createTime: [] }
,
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds:
{ createTime: [ '(new Date(1691020800000), new Date(9223372036854775807)]' ] }
}
}
},
rejectedPlans: []
},
executionStats: {
executionSuccess: true,
nReturned: 369,
executionTimeMillis: 2,
totalKeysExamined: 369,
totalDocsExamined: 369,
executionStages: {
stage: 'SHARDING_FILTER',
nReturned: 369,
executionTimeMillisEstimate: 0,
works: 370,
advanced: 369,
needTime: 0,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
chunkSkips: 0,
inputStage: {
stage: 'FETCH',
nReturned: 369,
executionTimeMillisEstimate: 0,
works: 370,
advanced: 369,
needTime: 0,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
docsExamined: 369,
alreadyHasObj: 0,
inputStage: {
stage: 'IXSCAN',
nReturned: 369,
executionTimeMillisEstimate: 0,
works: 370,
advanced: 369,
needTime: 0,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
keyPattern:
{ createTime: 1 }
,
indexName: 'createTime_1',
isMultiKey: false,
multiKeyPaths:
{ createTime: [] }
,
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds:
{ createTime: [ '(new Date(1691020800000), new Date(9223372036854775807)]' ] }
,
keysExamined: 369,
seeks: 1,
dupsTested: 0,
dupsDropped: 0
}
}
},
allPlansExecution: []
}
},
shard2: {
host: 'host2:31002',
queryPlanner: {
namespace: 'datacenter.order',
indexFilterSet: false,
parsedQuery: { createTime:
{ '$gt': ISODate("2023-08-03T00:00:00.000Z") }
},
queryHash: 'BFA14242',
planCacheKey: '5D24761B',
optimizedPipeline: true,
maxIndexedOrSolutionsReached: false,
maxIndexedAndSolutionsReached: false,
maxScansToExplodeReached: false,
winningPlan: {
stage: 'SHARDING_FILTER',
inputStage: {
stage: 'FETCH',
inputStage: {
stage: 'IXSCAN',
keyPattern:
{ createTime: 1 }
,
indexName: 'createTime_1',
isMultiKey: false,
multiKeyPaths:
{ createTime: [] }
,
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds:
{ createTime: [ '(new Date(1691020800000), new Date(9223372036854775807)]' ] }
}
}
},
rejectedPlans: []
},
executionStats: {
executionSuccess: true,
nReturned: 848,
executionTimeMillis: 6,
totalKeysExamined: 848,
totalDocsExamined: 848,
executionStages: {
stage: 'SHARDING_FILTER',
nReturned: 848,
executionTimeMillisEstimate: 0,
works: 849,
advanced: 848,
needTime: 0,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
chunkSkips: 0,
inputStage: {
stage: 'FETCH',
nReturned: 848,
executionTimeMillisEstimate: 0,
works: 849,
advanced: 848,
needTime: 0,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
docsExamined: 848,
alreadyHasObj: 0,
inputStage: {
stage: 'IXSCAN',
nReturned: 848,
executionTimeMillisEstimate: 0,
works: 849,
advanced: 848,
needTime: 0,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
keyPattern:
{ createTime: 1 }
,
indexName: 'createTime_1',
isMultiKey: false,
multiKeyPaths:
{ createTime: [] }
,
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds:
{ createTime: [ '(new Date(1691020800000), new Date(9223372036854775807)]' ] }
,
keysExamined: 848,
seeks: 1,
dupsTested: 0,
dupsDropped: 0
}
}
},
allPlansExecution: []
}
}
},
command: {
aggregate: 'order',
pipeline: [
{
'$match': { createTime:
{ '$gt': ISODate("2023-08-03T00:00:00.000Z") }
}
},
{
'$lookup':
{ from: 'terminalNosharding', localField: 'waybillNo', foreignField: 'waybillNo', as: 'output' }
},
{ '$match': { output:
{ '$ne': [] }
} }
],
cursor: {}
},
ok: 1,
'$clusterTime': {
clusterTime: Timestamp(
{ t: 1691118569, i: 1 }
),
signature:
{ hash: Binary(Buffer.from("00f53df6fd68784a50f00a0d4dd793f3eafe2cf4", "hex"), 0), keyId: Long("7225447387848769561") }
},
operationTime: Timestamp(
{ t: 1691118563, i: 2 }
)
}

 

Comment by jing xu [ 04/Aug/23 ]

i read SERVER-53762 that indicate Report aggregate execution stats in explain for the inner side of $lookup.

Generated at Thu Feb 08 06:41:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.