[SERVER-33967] Include executionTimeMillis for each shard in the explain output Created: 19/Mar/18  Updated: 29/Oct/23  Resolved: 19/Jun/19

Status: Closed
Project: Core Server
Component/s: Querying, Sharding
Affects Version/s: None
Fix Version/s: 4.3.1

Type: Improvement Priority: Major - P3
Reporter: Linda Qin Assignee: Anton Korshunov
Resolution: Fixed Votes: 2
Labels: QFB, S2, ch
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Backwards Compatibility: Fully Compatible
Sprint: Query 2019-07-01
Participants:
Case:

 Description   

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 }



 Comments   
Comment by Anton Korshunov [ 19/Jun/19 ]

For each shard we now include additional fields in the explain output.

Before:

"queryPlanner" : {
	...
	},
	"executionStats" : {
	    ...
		"executionStages" : {
		    ...
			"shards" : [
				{
					"shardName" : "shard0",
					"executionSuccess" : true,
					"executionStages" : {
					    ...
					}   
				},
				{
					"shardName" : "shard1",
					"executionSuccess" : true,
					"executionStages" : {
					    ...
					}
				}
			]
		},
		"allPlansExecution" : [
		...
		]
	},
	"ok" : 1
}

 

Now:

"queryPlanner" : {
	...
	},
	"executionStats" : {
	    ...
		"executionStages" : {
		    ...
			"shards" : [
				{
					"shardName" : "shard0",
					"executionSuccess" : true,
					"nReturned" : 10,
                                        "executionTimeMillis" : 10,
	                                "totalKeysExamined" : 15253,
                                        "totalDocsExamined" : 0
					"executionStages" : {
					    ...
					}   
				},
				{
					"shardName" : "shard1",
					"executionSuccess" : true,
					"nReturned" : 12,
                                        "executionTimeMillis" : 8,
	                                "totalKeysExamined" : 14526,
                                        "totalDocsExamined" : 0
					"executionStages" : {
					    ...
					}
				}
			]
		},
		"allPlansExecution" : [
		...
		]
	},
	"ok" : 1
}

 

Comment by Githook User [ 19/Jun/19 ]

Author:

{'name': 'Anton Korshunov', 'email': 'anton.korshunov@mongodb.com', 'username': 'antkorsh'}

Message: SERVER-33967 Include executionTimeMillis for each shard in the explain output
Branch: master
https://github.com/mongodb/mongo/commit/46e086d2093798cdec949eba2919ccac88719166

Generated at Thu Feb 08 04:35:09 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.