MongoDB 4.4慢查询
我在Mongos执行了一个查询命令，但是它执行了很长时间。
Mongos＆gt; db.message.find（{“ {“ toid”：123，“ $ or”：[{“ rid”：2}，{“ valivertime”：null}，{“ fromid”：2}，{“ varre time”：{“ varrytime”：{ }}}}）
$ lt“ ：
{
"op" : "command",
"ns" : "sns.message",
"command" : {
"explain" : {
"find" : "message",
"filter" : {
"toid" : 123,
"$or" : [
{
"rid" : 2
},
{
"validtime" : null
},
{
"fromid" : 2
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"limit" : 10,
"singleBatch" : true,
"sort" : {
"sortid" : -1
},
"options" : {
}
},
"verbosity" : "executionStats",
"$db" : "sns"
},
"numYield" : 6477,
"locks" : {
"ReplicationStateTransition" : {
"acquireCount" : {
"w" : NumberLong(6479)
}
},
"Global" : {
"acquireCount" : {
"r" : NumberLong(6479)
}
},
"Database" : {
"acquireCount" : {
"r" : NumberLong(6478)
}
},
"Collection" : {
"acquireCount" : {
"r" : NumberLong(6478)
}
},
"Mutex" : {
"acquireCount" : {
"r" : NumberLong(1)
}
}
},
"flowControl" : {
},
"storage" : {
"data" : {
"bytesRead" : NumberLong(91629495),
"timeReadingMicros" : NumberLong(68943)
}
},
"responseLength" : 5159,
"protocol" : "op_query",
"millis" : 13477,
"ts" : ISODate("2022-04-11T05:46:33.221Z"),
"client" : "127.0.0.1",
"allUsers" : [ ],
"user" : ""
}
1649565335
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "sns.message",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
{
"toid" : {
"$eq" : 123
}
}
]
},
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 10,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
{
"toid" : {
"$eq" : 123
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"sortid" : 1,
"toid" : 1
},
"indexName" : "toid_1_sortid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"sortid" : [ ],
"toid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "backward",
"indexBounds" : {
"sortid" : [
"[MaxKey, MinKey]"
],
"toid" : [
"[MaxKey, MinKey]"
]
}
}
}
},
"rejectedPlans" : [
{
"stage" : "SORT",
"sortPattern" : {
"sortid" : -1
},
"memLimit" : 104857600,
"limitAmount" : 10,
"type" : "simple",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"toid" : 1
},
"indexName" : "toid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"toid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"toid" : [
"[123.0, 123.0]"
]
}
}
}
},
{
"stage" : "SORT",
"sortPattern" : {
"sortid" : -1
},
"memLimit" : 104857600,
"limitAmount" : 10,
"type" : "simple",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"toid" : 1,
"replyid" : 1
},
"indexName" : "toid_1_replyid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"toid" : [ ],
"replyid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "forward",
"indexBounds" : {
"toid" : [
"[123.0, 123.0]"
],
"replyid" : [
"[MinKey, MaxKey]"
]
}
}
}
},
{
"stage" : "SORT",
"sortPattern" : {
"sortid" : -1
},
"memLimit" : 104857600,
"limitAmount" : 10,
"type" : "simple",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"toid" : 1,
"validtime" : 1,
"time" : 1
},
"indexName" : "toid_1_validtime_1_time_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"toid" : [ ],
"validtime" : [ ],
"time" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "forward",
"indexBounds" : {
"toid" : [
"[123.0, 123.0]"
],
"validtime" : [
"[MinKey, MaxKey]"
],
"time" : [
"[MinKey, MaxKey]"
]
}
}
}
},
// omit...
]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 10,
"executionTimeMillis" : 13477,
"totalKeysExamined" : 1295456,
"totalDocsExamined" : 1295456,
"executionStages" : {
"stage" : "LIMIT",
"nReturned" : 10,
"executionTimeMillisEstimate" : 700,
"works" : 1295457,
"advanced" : 10,
"needTime" : 1295446,
"needYield" : 0,
"saveState" : 6477,
"restoreState" : 6477,
"isEOF" : 1,
"limitAmount" : 10,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
{
"toid" : {
"$eq" : 123
}
}
]
},
"nReturned" : 10,
"executionTimeMillisEstimate" : 690,
"works" : 1295456,
"advanced" : 10,
"needTime" : 1295446,
"needYield" : 0,
"saveState" : 6477,
"restoreState" : 6477,
"isEOF" : 0,
"docsExamined" : 1295456,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 1295456,
"executionTimeMillisEstimate" : 188,
"works" : 1295456,
"advanced" : 1295456,
"needTime" : 0,
"needYield" : 0,
"saveState" : 6477,
"restoreState" : 6477,
"isEOF" : 0,
"keyPattern" : {
"sortid" : 1,
"toid" : 1
},
"indexName" : "toid_1_sortid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"sortid" : [ ],
"toid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "backward",
"indexBounds" : {
"sortid" : [
"[MaxKey, MinKey]"
],
"toid" : [
"[MaxKey, MinKey]"
]
},
"keysExamined" : 1295456,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0
}
}
}
},
"serverInfo" : {
"host" : "MongoDB",
"port" : 22005,
"version" : "4.4.13",
"gitVersion" : "df25c71b8674a78e17468f48bcda5285decb9246"
},
"ok" : 1,
"$gleStats" : {
"lastOpTime" : Timestamp(0, 0),
"electionId" : ObjectId("7fffffff0000000000000001")
},
"lastCommittedOpTime" : Timestamp(1649655993, 20),
"$configServerState" : {
"opTime" : {
"ts" : Timestamp(1649655992, 11),
"t" : NumberLong(1)
}
},
"$clusterTime" : {
"clusterTime" : Timestamp(1649655993, 26),
"signature" : {
"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
"keyId" : NumberLong(0)
}
},
"operationTime" : Timestamp(1649655993, 26)
}
。 “极限”阶段及其倒数阶段均小于或等于700ms，但总时间为13477ms。这段时间发生了什么？我如何找到耗时的原因？并期待优化建议。
谢谢
I execute a query command in mongos, but it executes for a long time.
mongos> db.message.find({"toid":123,"$or":[{"rid":2},{"validtime":null},{"fromid":2},{"validtime":{"$lt":1649565335}}]}).sort({sortid:-1}).limit(10)
slow query log like this：
{
"op" : "command",
"ns" : "sns.message",
"command" : {
"explain" : {
"find" : "message",
"filter" : {
"toid" : 123,
"$or" : [
{
"rid" : 2
},
{
"validtime" : null
},
{
"fromid" : 2
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"limit" : 10,
"singleBatch" : true,
"sort" : {
"sortid" : -1
},
"options" : {
}
},
"verbosity" : "executionStats",
"$db" : "sns"
},
"numYield" : 6477,
"locks" : {
"ReplicationStateTransition" : {
"acquireCount" : {
"w" : NumberLong(6479)
}
},
"Global" : {
"acquireCount" : {
"r" : NumberLong(6479)
}
},
"Database" : {
"acquireCount" : {
"r" : NumberLong(6478)
}
},
"Collection" : {
"acquireCount" : {
"r" : NumberLong(6478)
}
},
"Mutex" : {
"acquireCount" : {
"r" : NumberLong(1)
}
}
},
"flowControl" : {
},
"storage" : {
"data" : {
"bytesRead" : NumberLong(91629495),
"timeReadingMicros" : NumberLong(68943)
}
},
"responseLength" : 5159,
"protocol" : "op_query",
"millis" : 13477,
"ts" : ISODate("2022-04-11T05:46:33.221Z"),
"client" : "127.0.0.1",
"allUsers" : [ ],
"user" : ""
}
and the explain information is as follows：
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "sns.message",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
{
"toid" : {
"$eq" : 123
}
}
]
},
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 10,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
{
"toid" : {
"$eq" : 123
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"sortid" : 1,
"toid" : 1
},
"indexName" : "toid_1_sortid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"sortid" : [ ],
"toid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "backward",
"indexBounds" : {
"sortid" : [
"[MaxKey, MinKey]"
],
"toid" : [
"[MaxKey, MinKey]"
]
}
}
}
},
"rejectedPlans" : [
{
"stage" : "SORT",
"sortPattern" : {
"sortid" : -1
},
"memLimit" : 104857600,
"limitAmount" : 10,
"type" : "simple",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"toid" : 1
},
"indexName" : "toid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"toid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"toid" : [
"[123.0, 123.0]"
]
}
}
}
},
{
"stage" : "SORT",
"sortPattern" : {
"sortid" : -1
},
"memLimit" : 104857600,
"limitAmount" : 10,
"type" : "simple",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"toid" : 1,
"replyid" : 1
},
"indexName" : "toid_1_replyid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"toid" : [ ],
"replyid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "forward",
"indexBounds" : {
"toid" : [
"[123.0, 123.0]"
],
"replyid" : [
"[MinKey, MaxKey]"
]
}
}
}
},
{
"stage" : "SORT",
"sortPattern" : {
"sortid" : -1
},
"memLimit" : 104857600,
"limitAmount" : 10,
"type" : "simple",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"toid" : 1,
"validtime" : 1,
"time" : 1
},
"indexName" : "toid_1_validtime_1_time_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"toid" : [ ],
"validtime" : [ ],
"time" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "forward",
"indexBounds" : {
"toid" : [
"[123.0, 123.0]"
],
"validtime" : [
"[MinKey, MaxKey]"
],
"time" : [
"[MinKey, MaxKey]"
]
}
}
}
},
// omit...
]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 10,
"executionTimeMillis" : 13477,
"totalKeysExamined" : 1295456,
"totalDocsExamined" : 1295456,
"executionStages" : {
"stage" : "LIMIT",
"nReturned" : 10,
"executionTimeMillisEstimate" : 700,
"works" : 1295457,
"advanced" : 10,
"needTime" : 1295446,
"needYield" : 0,
"saveState" : 6477,
"restoreState" : 6477,
"isEOF" : 1,
"limitAmount" : 10,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"$or" : [
{
"fromid" : {
"$eq" : 2
}
},
{
"rid" : {
"$eq" : 2
}
},
{
"validtime" : {
"$eq" : null
}
},
{
"validtime" : {
"$lt" : 1649565335
}
}
]
},
{
"toid" : {
"$eq" : 123
}
}
]
},
"nReturned" : 10,
"executionTimeMillisEstimate" : 690,
"works" : 1295456,
"advanced" : 10,
"needTime" : 1295446,
"needYield" : 0,
"saveState" : 6477,
"restoreState" : 6477,
"isEOF" : 0,
"docsExamined" : 1295456,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 1295456,
"executionTimeMillisEstimate" : 188,
"works" : 1295456,
"advanced" : 1295456,
"needTime" : 0,
"needYield" : 0,
"saveState" : 6477,
"restoreState" : 6477,
"isEOF" : 0,
"keyPattern" : {
"sortid" : 1,
"toid" : 1
},
"indexName" : "toid_1_sortid_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"sortid" : [ ],
"toid" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 1,
"direction" : "backward",
"indexBounds" : {
"sortid" : [
"[MaxKey, MinKey]"
],
"toid" : [
"[MaxKey, MinKey]"
]
},
"keysExamined" : 1295456,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0
}
}
}
},
"serverInfo" : {
"host" : "MongoDB",
"port" : 22005,
"version" : "4.4.13",
"gitVersion" : "df25c71b8674a78e17468f48bcda5285decb9246"
},
"ok" : 1,
"$gleStats" : {
"lastOpTime" : Timestamp(0, 0),
"electionId" : ObjectId("7fffffff0000000000000001")
},
"lastCommittedOpTime" : Timestamp(1649655993, 20),
"$configServerState" : {
"opTime" : {
"ts" : Timestamp(1649655992, 11),
"t" : NumberLong(1)
}
},
"$clusterTime" : {
"clusterTime" : Timestamp(1649655993, 26),
"signature" : {
"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
"keyId" : NumberLong(0)
}
},
"operationTime" : Timestamp(1649655993, 26)
}
in the "executionStats" block, both the "LIMIT" stage and its substage take less than or equal to 700ms, but the total time is 13477ms. what happened during this time? How can I locate the reason for the time consuming? And Looking forward to optimization suggestions.
Thanks
如果你对这篇内容有疑问，欢迎到本站社区发帖提问 参与讨论，获取更多帮助，或者扫码二维码加入 Web 技术交流群。
绑定邮箱获取回复消息
由于您还没有绑定你的真实邮箱，如果其他用户或者作者回复了您的评论，将不能在第一时间通知您！
发布评论
评论（1）
总
executionTimeMillis是计划 + 执行所需的“总”时间，这意味着现在在每个阶段的细分中计算了某些因素。例如：
锁定获取/总体数据库负载。
在计划时，仅检查 100 个文档样本，但正如您所看到的，实际查询会获取超过 100 万个文档。如果同一集合上有其他操作锁定它，或者数据库通常负载很重，这可能会影响性能，因为您的查询正在排队等待资源。
磁盘延迟
正如您所看到的，您的
docsExamined等于keysExamined，这意味着需要从磁盘中提取与查询匹配的每个文档进行检查。这是相当大的开销。我怀疑这是有关性能的主要“问题”。您可以通过创建适当的复合索引来满足此查询来降低此值。
您还可以添加具有更多 IOPS 的磁盘，增强硬件总是会提高性能，尤其是在瓶颈位置时。
The total
executionTimeMillisis the "total" amount of time required for both planning + execution, this means there are certain factors now calculated in the breakdown per stage.For example:
Lock acquisition / overall db load.
When planning only a 100 document sample is examined, however as you can see for the actual query over 1milion documents are being fetched. If the there are other operations on the same collection that lock it or if the db is in general under heavy load this can affect performance as your query is waiting in line for resources.
Disk latency
As you can see your
docsExaminedis equal tokeysExamined, this means that every single documents that matched the query needed to be fetched from disk to be examined.This is quite a lot of overhead. and I suspect this is the main "issue" regarding performance. You could probably lower this by creating a proper compound index to satisfy this query.
You can also add a disk with more IOPS, boosting hardware will always increase performance, especially if it's at the bottleneck places.