Query hit index is quite slow on one replica set node

Working with Data
,
1

hi, I want to report a strange query issue.

we have mongo (3.6.19) replica set. when i query below:

db.scci_detail.find({“cut_commitrepo”: “isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk”,“type”: “sysadapt”,“end”: {“$gte”: 1616860800,“$lte”: 1616947199}}).explain(‘allPlansExecution’)

on hzcoop02(secondary node): query is very fast.
on hzcoop03(another secondary node): query is very slow!

after inspecting, I find the index bounds are different!
on hzcoop02:

"end" : [
   "[1616860800.0, 1616601599.0]"
]

on hzcoop03:

"end" : [
   "[-inf.0, 1616947199.0]"
]

what causes the difference?

2

Hi @111393,

Its possible that not the same index is being used in both nodes and maybe the query plan caches are different.

I will need a getIndexes and full excutionStats explain frim both.

Thanks
Pavel

3

hi, sorry for the late response.

hzcoop02:

{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "pipeline.scci_detail",
		"indexFilterSet" : false,
		"parsedQuery" : {
			"$and" : [
				{
					"cut_commitrepo" : {
						"$eq" : "isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk"
					}
				},
				{
					"type" : {
						"$eq" : "sysadapt"
					}
				},
				{
					"end" : {
						"$lte" : 1616947199
					}
				},
				{
					"end" : {
						"$gte" : 1616860800
					}
				}
			]
		},
		"winningPlan" : {
			"stage" : "FETCH",
			"inputStage" : {
				"stage" : "IXSCAN",
				"keyPattern" : {
					"cut_commitrepo" : 1,
					"type" : 1,
					"end" : 1
				},
				"indexName" : "cut_commitrepo_1_type_1_end_1",
				"isMultiKey" : false,
				"isUnique" : false,
				"isSparse" : false,
				"isPartial" : false,
				"indexVersion" : 1,
				"direction" : "forward",
				"indexBounds" : {
					"cut_commitrepo" : [
						"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
					],
					"type" : [
						"[\"sysadapt\", \"sysadapt\"]"
					],
					"end" : [
						"[1616860800.0, 1616947199.0]"
					]
				}
			}
		},
		"rejectedPlans" : [
			{
				"stage" : "FETCH",
				"filter" : {
					"$and" : [
						{
							"end" : {
								"$lte" : 1616947199
							}
						},
						{
							"end" : {
								"$gte" : 1616860800
							}
						}
					]
				},
				"inputStage" : {
					"stage" : "IXSCAN",
					"keyPattern" : {
						"cut_commitrepo" : 1,
						"type" : 1,
						"revision" : 1,
						"name" : 1,
						"patchset" : 1
					},
					"indexName" : "cut_commitrepo_1_type_1_revision_1_name_1_patchset_1",
					"isMultiKey" : false,
					"isUnique" : false,
					"isSparse" : false,
					"isPartial" : false,
					"indexVersion" : 1,
					"direction" : "forward",
					"indexBounds" : {
						"cut_commitrepo" : [
							"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
						],
						"type" : [
							"[\"sysadapt\", \"sysadapt\"]"
						],
						"revision" : [
							"[MinKey, MaxKey]"
						],
						"name" : [
							"[MinKey, MaxKey]"
						],
						"patchset" : [
							"[MinKey, MaxKey]"
						]
					}
				}
			}
		]
	},
	"executionStats" : {
		"executionSuccess" : true,
		"nReturned" : 0,
		"executionTimeMillis" : 7,
		"totalKeysExamined" : 0,
		"totalDocsExamined" : 0,
		"executionStages" : {
			"stage" : "FETCH",
			"nReturned" : 0,
			"executionTimeMillisEstimate" : 0,
			"works" : 2,
			"advanced" : 0,
			"needTime" : 0,
			"needYield" : 0,
			"saveState" : 0,
			"restoreState" : 0,
			"isEOF" : 1,
			"invalidates" : 0,
			"docsExamined" : 0,
			"alreadyHasObj" : 0,
			"inputStage" : {
				"stage" : "IXSCAN",
				"nReturned" : 0,
				"executionTimeMillisEstimate" : 0,
				"works" : 1,
				"advanced" : 0,
				"needTime" : 0,
				"needYield" : 0,
				"saveState" : 0,
				"restoreState" : 0,
				"isEOF" : 1,
				"invalidates" : 0,
				"keyPattern" : {
					"cut_commitrepo" : 1,
					"type" : 1,
					"end" : 1
				},
				"indexName" : "cut_commitrepo_1_type_1_end_1",
				"isMultiKey" : false,
				"isUnique" : false,
				"isSparse" : false,
				"isPartial" : false,
				"indexVersion" : 1,
				"direction" : "forward",
				"indexBounds" : {
					"cut_commitrepo" : [
						"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
					],
					"type" : [
						"[\"sysadapt\", \"sysadapt\"]"
					],
					"end" : [
						"[1616860800.0, 1616947199.0]"
					]
				},
				"keysExamined" : 0,
				"seeks" : 1,
				"dupsTested" : 0,
				"dupsDropped" : 0,
				"seenInvalidated" : 0
			}
		},
		"allPlansExecution" : [
			{
				"nReturned" : 0,
				"executionTimeMillisEstimate" : 10,
				"totalKeysExamined" : 1,
				"totalDocsExamined" : 1,
				"executionStages" : {
					"stage" : "FETCH",
					"filter" : {
						"$and" : [
							{
								"end" : {
									"$lte" : 1616947199
								}
							},
							{
								"end" : {
									"$gte" : 1616860800
								}
							}
						]
					},
					"nReturned" : 0,
					"executionTimeMillisEstimate" : 10,
					"works" : 1,
					"advanced" : 0,
					"needTime" : 1,
					"needYield" : 0,
					"saveState" : 0,
					"restoreState" : 0,
					"isEOF" : 0,
					"invalidates" : 0,
					"docsExamined" : 1,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 1,
						"executionTimeMillisEstimate" : 10,
						"works" : 1,
						"advanced" : 1,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 0,
						"restoreState" : 0,
						"isEOF" : 0,
						"invalidates" : 0,
						"keyPattern" : {
							"cut_commitrepo" : 1,
							"type" : 1,
							"revision" : 1,
							"name" : 1,
							"patchset" : 1
						},
						"indexName" : "cut_commitrepo_1_type_1_revision_1_name_1_patchset_1",
						"isMultiKey" : false,
						"isUnique" : false,
						"isSparse" : false,
						"isPartial" : false,
						"indexVersion" : 1,
						"direction" : "forward",
						"indexBounds" : {
							"cut_commitrepo" : [
								"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
							],
							"type" : [
								"[\"sysadapt\", \"sysadapt\"]"
							],
							"revision" : [
								"[MinKey, MaxKey]"
							],
							"name" : [
								"[MinKey, MaxKey]"
							],
							"patchset" : [
								"[MinKey, MaxKey]"
							]
						},
						"keysExamined" : 1,
						"seeks" : 1,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0
					}
				}
			},
			{
				"nReturned" : 0,
				"executionTimeMillisEstimate" : 0,
				"totalKeysExamined" : 0,
				"totalDocsExamined" : 0,
				"executionStages" : {
					"stage" : "FETCH",
					"nReturned" : 0,
					"executionTimeMillisEstimate" : 0,
					"works" : 1,
					"advanced" : 0,
					"needTime" : 0,
					"needYield" : 0,
					"saveState" : 0,
					"restoreState" : 0,
					"isEOF" : 1,
					"invalidates" : 0,
					"docsExamined" : 0,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 0,
						"executionTimeMillisEstimate" : 0,
						"works" : 1,
						"advanced" : 0,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 0,
						"restoreState" : 0,
						"isEOF" : 1,
						"invalidates" : 0,
						"keyPattern" : {
							"cut_commitrepo" : 1,
							"type" : 1,
							"end" : 1
						},
						"indexName" : "cut_commitrepo_1_type_1_end_1",
						"isMultiKey" : false,
						"isUnique" : false,
						"isSparse" : false,
						"isPartial" : false,
						"indexVersion" : 1,
						"direction" : "forward",
						"indexBounds" : {
							"cut_commitrepo" : [
								"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
							],
							"type" : [
								"[\"sysadapt\", \"sysadapt\"]"
							],
							"end" : [
								"[1616860800.0, 1616947199.0]"
							]
						},
						"keysExamined" : 0,
						"seeks" : 1,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0
					}
				}
			}
		]
	},
	"serverInfo" : {
		"host" : "hzcoop02.china.nsn-net.net",
		"port" : 27017,
		"version" : "3.6.19",
		"gitVersion" : "41b289ff734a926e784d6ab42c3129f59f40d5b4"
	},
	"ok" : 1,
	"operationTime" : Timestamp(1619509531, 16),
	"$clusterTime" : {
		"clusterTime" : Timestamp(1619509531, 16),
		"signature" : {
			"hash" : BinData(0,"oHDIC9hSlWkXuaWwQQUWV0IdVc0="),
			"keyId" : NumberLong("6894478951775731714")
		}
	}
}
4

indexes:

db.scci_detail.getIndexes()
[
	{
		"v" : 1,
		"key" : {
			"_id" : 1
		},
		"name" : "_id_",
		"ns" : "pipeline.scci_detail"
	},
	{
		"v" : 1,
		"key" : {
			"cut_commitrepo" : 1,
			"type" : 1,
			"end" : 1
		},
		"name" : "cut_commitrepo_1_type_1_end_1",
		"ns" : "pipeline.scci_detail",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"cut_commitrepo" : 1,
			"type" : 1,
			"revision" : 1,
			"name" : 1,
			"patchset" : 1
		},
		"name" : "cut_commitrepo_1_type_1_revision_1_name_1_patchset_1",
		"ns" : "pipeline.scci_detail",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"date" : 1,
			"name" : 1
		},
		"name" : "date_1_name_1",
		"ns" : "pipeline.scci_detail",
		"background" : true
	},
	{
		"v" : 2,
		"key" : {
			"start" : 1,
			"name" : 1
		},
		"name" : "start_1_name_1",
		"background" : true,
		"ns" : "pipeline.scci_detail"
	}
]
5

hzcoop03:

db.scci_detail.find({"cut_commitrepo": "isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk","type": "sysadapt", $and:[{"end":{"$gte": 1616860800}},{"end":{"$lte": 1616947199}}]}).explain('allPlansExecution')
{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "pipeline.scci_detail",
		"indexFilterSet" : false,
		"parsedQuery" : {
			"$and" : [
				{
					"cut_commitrepo" : {
						"$eq" : "isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk"
					}
				},
				{
					"type" : {
						"$eq" : "sysadapt"
					}
				},
				{
					"end" : {
						"$lte" : 1616947199
					}
				},
				{
					"end" : {
						"$gte" : 1616860800
					}
				}
			]
		},
		"winningPlan" : {
			"stage" : "FETCH",
			"filter" : {
				"end" : {
					"$gte" : 1616860800
				}
			},
			"inputStage" : {
				"stage" : "IXSCAN",
				"keyPattern" : {
					"cut_commitrepo" : 1,
					"type" : 1,
					"end" : 1
				},
				"indexName" : "cut_commitrepo_1_type_1_end_1",
				"isMultiKey" : true,
				"multiKeyPaths" : {
					"cut_commitrepo" : [ ],
					"type" : [ ],
					"end" : [
						"end"
					]
				},
				"isUnique" : false,
				"isSparse" : false,
				"isPartial" : false,
				"indexVersion" : 1,
				"direction" : "forward",
				"indexBounds" : {
					"cut_commitrepo" : [
						"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
					],
					"type" : [
						"[\"sysadapt\", \"sysadapt\"]"
					],
					"end" : [
						"[-inf.0, 1616947199.0]"
					]
				}
			}
		},
		"rejectedPlans" : [
			{
				"stage" : "FETCH",
				"filter" : {
					"$and" : [
						{
							"end" : {
								"$lte" : 1616947199
							}
						},
						{
							"end" : {
								"$gte" : 1616860800
							}
						}
					]
				},
				"inputStage" : {
					"stage" : "IXSCAN",
					"keyPattern" : {
						"cut_commitrepo" : 1,
						"type" : 1,
						"revision" : 1,
						"name" : 1,
						"patchset" : 1
					},
					"indexName" : "cut_commitrepo_1_type_1_revision_1_name_1_patchset_1",
					"isMultiKey" : false,
					"multiKeyPaths" : {
						"cut_commitrepo" : [ ],
						"type" : [ ],
						"revision" : [ ],
						"name" : [ ],
						"patchset" : [ ]
					},
					"isUnique" : false,
					"isSparse" : false,
					"isPartial" : false,
					"indexVersion" : 1,
					"direction" : "forward",
					"indexBounds" : {
						"cut_commitrepo" : [
							"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
						],
						"type" : [
							"[\"sysadapt\", \"sysadapt\"]"
						],
						"revision" : [
							"[MinKey, MaxKey]"
						],
						"name" : [
							"[MinKey, MaxKey]"
						],
						"patchset" : [
							"[MinKey, MaxKey]"
						]
					}
				}
			}
		]
	},
	"executionStats" : {
		"executionSuccess" : true,
		"nReturned" : 0,
		"executionTimeMillis" : 177970,
		"totalKeysExamined" : 107760,
		"totalDocsExamined" : 107760,
		"executionStages" : {
			"stage" : "FETCH",
			"filter" : {
				"end" : {
					"$gte" : 1616860800
				}
			},
			"nReturned" : 0,
			"executionTimeMillisEstimate" : 84036,
			"works" : 107762,
			"advanced" : 0,
			"needTime" : 107760,
			"needYield" : 0,
			"saveState" : 8239,
			"restoreState" : 8239,
			"isEOF" : 1,
			"invalidates" : 0,
			"docsExamined" : 107760,
			"alreadyHasObj" : 0,
			"inputStage" : {
				"stage" : "IXSCAN",
				"nReturned" : 107760,
				"executionTimeMillisEstimate" : 360,
				"works" : 107761,
				"advanced" : 107760,
				"needTime" : 0,
				"needYield" : 0,
				"saveState" : 8239,
				"restoreState" : 8239,
				"isEOF" : 1,
				"invalidates" : 0,
				"keyPattern" : {
					"cut_commitrepo" : 1,
					"type" : 1,
					"end" : 1
				},
				"indexName" : "cut_commitrepo_1_type_1_end_1",
				"isMultiKey" : true,
				"multiKeyPaths" : {
					"cut_commitrepo" : [ ],
					"type" : [ ],
					"end" : [
						"end"
					]
				},
				"isUnique" : false,
				"isSparse" : false,
				"isPartial" : false,
				"indexVersion" : 1,
				"direction" : "forward",
				"indexBounds" : {
					"cut_commitrepo" : [
						"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
					],
					"type" : [
						"[\"sysadapt\", \"sysadapt\"]"
					],
					"end" : [
						"[-inf.0, 1616947199.0]"
					]
				},
				"keysExamined" : 107760,
				"seeks" : 1,
				"dupsTested" : 107760,
				"dupsDropped" : 0,
				"seenInvalidated" : 0
			}
		},
		"allPlansExecution" : [
			{
				"nReturned" : 0,
				"executionTimeMillisEstimate" : 92136,
				"totalKeysExamined" : 107761,
				"totalDocsExamined" : 107761,
				"executionStages" : {
					"stage" : "FETCH",
					"filter" : {
						"$and" : [
							{
								"end" : {
									"$lte" : 1616947199
								}
							},
							{
								"end" : {
									"$gte" : 1616860800
								}
							}
						]
					},
					"nReturned" : 0,
					"executionTimeMillisEstimate" : 92136,
					"works" : 107761,
					"advanced" : 0,
					"needTime" : 107761,
					"needYield" : 0,
					"saveState" : 8238,
					"restoreState" : 8238,
					"isEOF" : 0,
					"invalidates" : 0,
					"docsExamined" : 107761,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 107761,
						"executionTimeMillisEstimate" : 262,
						"works" : 107761,
						"advanced" : 107761,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 8238,
						"restoreState" : 8238,
						"isEOF" : 0,
						"invalidates" : 0,
						"keyPattern" : {
							"cut_commitrepo" : 1,
							"type" : 1,
							"revision" : 1,
							"name" : 1,
							"patchset" : 1
						},
						"indexName" : "cut_commitrepo_1_type_1_revision_1_name_1_patchset_1",
						"isMultiKey" : false,
						"multiKeyPaths" : {
							"cut_commitrepo" : [ ],
							"type" : [ ],
							"revision" : [ ],
							"name" : [ ],
							"patchset" : [ ]
						},
						"isUnique" : false,
						"isSparse" : false,
						"isPartial" : false,
						"indexVersion" : 1,
						"direction" : "forward",
						"indexBounds" : {
							"cut_commitrepo" : [
								"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
							],
							"type" : [
								"[\"sysadapt\", \"sysadapt\"]"
							],
							"revision" : [
								"[MinKey, MaxKey]"
							],
							"name" : [
								"[MinKey, MaxKey]"
							],
							"patchset" : [
								"[MinKey, MaxKey]"
							]
						},
						"keysExamined" : 107761,
						"seeks" : 1,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0
					}
				}
			},
			{
				"nReturned" : 0,
				"executionTimeMillisEstimate" : 84036,
				"totalKeysExamined" : 107760,
				"totalDocsExamined" : 107760,
				"executionStages" : {
					"stage" : "FETCH",
					"filter" : {
						"end" : {
							"$gte" : 1616860800
						}
					},
					"nReturned" : 0,
					"executionTimeMillisEstimate" : 84036,
					"works" : 107761,
					"advanced" : 0,
					"needTime" : 107760,
					"needYield" : 0,
					"saveState" : 8238,
					"restoreState" : 8238,
					"isEOF" : 1,
					"invalidates" : 0,
					"docsExamined" : 107760,
					"alreadyHasObj" : 0,
					"inputStage" : {
						"stage" : "IXSCAN",
						"nReturned" : 107760,
						"executionTimeMillisEstimate" : 360,
						"works" : 107761,
						"advanced" : 107760,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 8238,
						"restoreState" : 8238,
						"isEOF" : 1,
						"invalidates" : 0,
						"keyPattern" : {
							"cut_commitrepo" : 1,
							"type" : 1,
							"end" : 1
						},
						"indexName" : "cut_commitrepo_1_type_1_end_1",
						"isMultiKey" : true,
						"multiKeyPaths" : {
							"cut_commitrepo" : [ ],
							"type" : [ ],
							"end" : [
								"end"
							]
						},
						"isUnique" : false,
						"isSparse" : false,
						"isPartial" : false,
						"indexVersion" : 1,
						"direction" : "forward",
						"indexBounds" : {
							"cut_commitrepo" : [
								"[\"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\", \"isource/svnroot/BTS_SC_SYSADAPT_LTE/trunk\"]"
							],
							"type" : [
								"[\"sysadapt\", \"sysadapt\"]"
							],
							"end" : [
								"[-inf.0, 1616947199.0]"
							]
						},
						"keysExamined" : 107760,
						"seeks" : 1,
						"dupsTested" : 107760,
						"dupsDropped" : 0,
						"seenInvalidated" : 0
					}
				}
			}
		]
	},
	"serverInfo" : {
		"host" : "hzcoop03.china.nsn-net.net",
		"port" : 27017,
		"version" : "3.6.19",
		"gitVersion" : "41b289ff734a926e784d6ab42c3129f59f40d5b4"
	},
	"ok" : 1,
	"operationTime" : Timestamp(1619509726, 11),
	"$clusterTime" : {
		"clusterTime" : Timestamp(1619509726, 11),
		"signature" : {
			"hash" : BinData(0,"XOM8Upk05LOfCqav7IlEMcoCDPQ="),
			"keyId" : NumberLong("6894478951775731714")
		}
	}
}
6

Hi @111393,

I noticed that in node 2 the index choosen is considered as not multikey:

 “indexName” : “cut_commitrepo_1_type_1_end_1”,
“isMultiKey” : false,

While on node 3 it is:

“indexName” : “cut_commitrepo_1_type_1_end_1”,
“isMultiKey” : true,

This is most probably a metadata bug which has effected this node in previous versions.

I suggest to either rebuild this index on node 3 or resync the node as there might be additional indexes impacted.

Thanks
Pavel

8

interesting findings.
i will do as you advise.