Major - P3 Currently when we run the explain(true)/explain("allPlansExecution") from the mongos, the output for each shard in executionStats.executionStats.shards doesn't include the executionTimeMillis output.
For example, when I run explain for the count command on the mongos,
- executionTimeMillis (69ms) is showing up at the top level executionStats.
- However, executionTimeMillis is not showing up for each shard in executionStats.executionStats.shards. Instead, executionTimeMillisEstimate is showing up for each shard (31ms/20ms, 14ms/14ms).
- If we compare the executionTimeMillisEstimate output for each shard and the executionTimeMillis output on the top level, it's a bit confusing as there might a big difference, and it's hard to understand where the rest of the time is spent - the execution on the shards, or the merging on the mongos.
- It would be nice if we can include the executionTimeMillis for each shard in the output explain output.
mongos> db.docs.explain(true).count({x:{$gt:1}})
{
"queryPlanner" : {
...
},
"executionStats" : {
"nReturned" : 0,
"executionTimeMillis" : 69,
"totalKeysExamined" : 200996,
"totalDocsExamined" : 0,
"executionStages" : {
"stage" : "SHARD_MERGE",
"nReturned" : 0,
"executionTimeMillis" : 69,
"totalKeysExamined" : 200996,
"totalDocsExamined" : 0,
"totalChildMillis" : NumberLong(89),
"shards" : [
{
"shardName" : "myshard_0",
"executionSuccess" : true,
"executionStages" : {
"stage" : "COUNT",
"nReturned" : 0,
"executionTimeMillisEstimate" : 31,
"works" : 169371,
"advanced" : 0,
"needTime" : 169370,
"needYield" : 0,
"saveState" : 1323,
"restoreState" : 1323,
"isEOF" : 1,
"invalidates" : 0,
"nCounted" : 169370,
"nSkipped" : 0,
"inputStage" : {
"stage" : "COUNT_SCAN",
"nReturned" : 169370,
"executionTimeMillisEstimate" : 20,
"works" : 169371,
"advanced" : 169370,
"needTime" : 0,
"needYield" : 0,
"saveState" : 1323,
"restoreState" : 1323,
"isEOF" : 1,
"invalidates" : 0,
"keysExamined" : 169371,
"keyPattern" : {
"x" : 1
},
"indexName" : "x_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"x" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"indexBounds" : {
"startKey" : {
"x" : 1
},
"startKeyInclusive" : false,
"endKey" : {
"x" : Infinity
},
"endKeyInclusive" : true
}
}
}
},
{
"shardName" : "myshard_1",
"executionSuccess" : true,
"executionStages" : {
"stage" : "COUNT",
"nReturned" : 0,
"executionTimeMillisEstimate" : 14,
"works" : 31625,
"advanced" : 0,
"needTime" : 31624,
"needYield" : 0,
"saveState" : 247,
"restoreState" : 247,
"isEOF" : 1,
"invalidates" : 0,
"nCounted" : 31624,
"nSkipped" : 0,
"inputStage" : {
"stage" : "COUNT_SCAN",
"nReturned" : 31624,
"executionTimeMillisEstimate" : 14,
"works" : 31625,
"advanced" : 31624,
"needTime" : 0,
"needYield" : 0,
"saveState" : 247,
"restoreState" : 247,
"isEOF" : 1,
"invalidates" : 0,
"keysExamined" : 31625,
"keyPattern" : {
"x" : 1
},
"indexName" : "x_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"x" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"indexBounds" : {
"startKey" : {
"x" : 1
},
"startKeyInclusive" : false,
"endKey" : {
"x" : Infinity
},
"endKeyInclusive" : true
}
}
}
}
]
},
"allPlansExecution" : [
{
"shardName" : "myshard_0",
"allPlans" : [ ]
},
{
"shardName" : "myshard_1",
"allPlans" : [ ]
}
]
},
"ok" : 1
}
From the logs for each shard, the execution time for the explain command is 68ms (shard0) and 21ms (shard1):
// shard0
2018-03-19T03:09:39.587-0400 I COMMAND [conn6299] command test.docs appName: "MongoDB Shell" command: explain { explain: { count: "docs", query: { x: { $gt: 1.0 } }, fields: {} }, verbosity: "allPlansExecution" } numYields:1323 reslen:1565 locks:{ Global: { acquireCount: { r: 2648 } }, Database: { acquireCount: { r: 1324 } }, Collection: { acquireCount: { r: 1324 } } } protocol:op_query 68ms
// shard1:
2018-03-19T03:09:39.541-0400 I COMMAND [conn6188] command test.docs appName: "MongoDB Shell" command: explain { explain: { count: "docs", query: { x: { $gt: 1.0 } }, fields: {} }, verbosity: "allPlansExecution" } numYields:247 reslen:1565 locks:{ Global: { acquireCount: { r: 496 } }, Database: { acquireCount: { r: 248 } }, Collection: { acquireCount: { r: 248 } } } protocol:op_query 21ms
From the verbose logs on the mongos, the output from each shard does include the executionTimeMillis output (68ms for shard0 and 21ms for shard1), which matches the above logs on the shards. It would be nice if we can include the executionTimeMillis for each shard in the output explain output.
// shard0
2018-03-19T03:09:39.587-0400 D NETWORK [conn66413] finished on shard myshard_0, current connection state is { state: { conn: "(done)", vinfo: "test.docs @ 5|1||5a9ccb81aaa018536681f2ba", cursor: { queryPlanner: { plannerVersion: 1, namespace: "test.docs", indexFilterSet: false, parsedQuery: { x: { $gt: 1.0 } }, winningPlan: { stage: "COUNT", inputStage: { stage: "COUNT_SCAN", keyPattern: { x: 1.0 }, indexName: "x_1", isMultiKey: false, multiKeyPaths: { x: [] }, isUnique: false, isSparse: false, isPartial: false, indexVersion: 1, indexBounds: { startKey: { x: 1.0 }, startKeyInclusive: false, endKey: { x: inf.0 }, endKeyInclusive: true } } }, rejectedPlans: [] }, executionStats: { executionSuccess: true, nReturned: 0, executionTimeMillis: 68, totalKeysExamined: 169371, totalDocsExamined: 0, executionStages: { stage: "COUNT", nReturned: 0, executionTimeMillisEstimate: 31, works: 169371, advanced: 0, needTime: 169370, needYield: 0, saveState: 1323, restoreState: 1323, isEOF: 1, invalidates: 0, nCounted: 169370, nSkipped: 0, inputStage: { stage: "COUNT_SCAN", nReturned: 169370, executionTimeMillisEstimate: 20, works: 169371, advanced: 169370, needTime: 0, needYield: 0, saveState: 1323, restoreState: 1323, isEOF: 1, invalidates: 0, keysExamined: 169371, keyPattern: { x: 1.0 }, indexName: "x_1", isMultiKey: false, multiKeyPaths: { x: [] }, isUnique: false, isSparse: false, isPartial: false, indexVersion: 1, indexBounds: { startKey: { x: 1.0 }, startKeyInclusive: false, endKey: { x: inf.0 }, endKeyInclusive: true } } }, allPlansExecution: [] }, serverInfo: { host: "myhost", port: 27001, version: "3.4.13", gitVersion: "fbdef2ccc53e0fcc9afb570063633d992b2aae42" }, ok: 1.0, $gleStats: { lastOpTime: Timestamp 0|0, electionId: ObjectId('7fffffff0000000000000004') } }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
// shard1
2018-03-19T03:09:39.587-0400 D NETWORK [conn66413] finished on shard myshard_1, current connection state is { state: { conn: "(done)", vinfo: "test.docs @ 5|1||5a9ccb81aaa018536681f2ba", cursor: { queryPlanner: { plannerVersion: 1, namespace: "test.docs", indexFilterSet: false, parsedQuery: { x: { $gt: 1.0 } }, winningPlan: { stage: "COUNT", inputStage: { stage: "COUNT_SCAN", keyPattern: { x: 1.0 }, indexName: "x_1", isMultiKey: false, multiKeyPaths: { x: [] }, isUnique: false, isSparse: false, isPartial: false, indexVersion: 1, indexBounds: { startKey: { x: 1.0 }, startKeyInclusive: false, endKey: { x: inf.0 }, endKeyInclusive: true } } }, rejectedPlans: [] }, executionStats: { executionSuccess: true, nReturned: 0, executionTimeMillis: 21, totalKeysExamined: 31625, totalDocsExamined: 0, executionStages: { stage: "COUNT", nReturned: 0, executionTimeMillisEstimate: 14, works: 31625, advanced: 0, needTime: 31624, needYield: 0, saveState: 247, restoreState: 247, isEOF: 1, invalidates: 0, nCounted: 31624, nSkipped: 0, inputStage: { stage: "COUNT_SCAN", nReturned: 31624, executionTimeMillisEstimate: 14, works: 31625, advanced: 31624, needTime: 0, needYield: 0, saveState: 247, restoreState: 247, isEOF: 1, invalidates: 0, keysExamined: 31625, keyPattern: { x: 1.0 }, indexName: "x_1", isMultiKey: false, multiKeyPaths: { x: [] }, isUnique: false, isSparse: false, isPartial: false, indexVersion: 1, indexBounds: { startKey: { x: 1.0 }, startKeyInclusive: false, endKey: { x: inf.0 }, endKeyInclusive: true } } }, allPlansExecution: [] }, serverInfo: { host: "myhost", port: 27005, version: "3.4.13", gitVersion: "fbdef2ccc53e0fcc9afb570063633d992b2aae42" }, ok: 1.0, $gleStats: { lastOpTime: Timestamp 0|0, electionId: ObjectId('7fffffff0000000000000004') } }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }