-
Type:
Bug
-
Resolution: Unresolved
-
Priority:
Minor - P4
-
None
-
Affects Version/s: 3.4.10
-
Component/s: Querying
-
Labels:
-
Environment:Server 3.4.10 on Ubuntu 16.04.3 LTS
-
Query Execution
-
ALL
Original Summary
Sorting used multi-key in one direction only, explain() provides wrong info
Original Description
I was looking at the slow query log tonight and decided to try to optimize some of them. One simple query was:
db.games.find({ ip: "1.2.3.4" }, { _id: 0, sgfhash: 1} ).sort({ _id: -1 }).limit(1);
to get the most recent itme with that IP address. Turns out this was taking 4-10 seconds. So I added a multi-index key for ip,_id so it could use that to optimize the search/sort. After much hair pulling, I finally realized the sort _id: 1 direction was instant, but the _id: -1 was the slow one. I tried changing my index to be ip:1,_id:-1 and ip:-1,_id:-1 with no help. Sort '1' was always fast, '-1' always slow.
I wrote about this all here as well when at my wit's end:
https://www.reddit.com/r/mongodb/comments/7nyx9b/using_indexes_to_reverse_sort_a_query/
What I found is that the optimizer was only using the proper key when sorting with '1' and never when sorting with '-1'. explain() mislead me however. Explain would say this:
"winningPlan" : { "stage" : "LIMIT", "limitAmount" : 1, "inputStage" : { "stage" : "PROJECTION", "transformBy" : { "_id" : 0, "sgfhash" : 1 }, "inputStage" : { "stage" : "FETCH", "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "ip" : -1, "_id" : -1 }, "indexName" : "ip_-1__id_-1", "isMultiKey" : false, "multiKeyPaths" : { "ip" : [ ], "_id" : [ ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "ip" : [ "[\"1.2.3.4\", \"1.2.3.4\"]" ], "_id" : [ "[MaxKey, MinKey]" ] } } } } }
Only changing "direction" to "backwards" if I tried the query in the opposite sort direction.
However, I turned on profiling and ran the slow sort direction, and I get this:
{
"op" : "query",
"ns" : "test.games",
"query" : {
"find" : "games",
"filter" : {
"ip" : "1.2.3.4"
},
"limit" : 1,
"singleBatch" : false,
"sort" : {
"_id" : -1
},
"projection" : {
"_id" : 0,
"sgfhash" : 1
}
},
"keysExamined" : 534,
"docsExamined" : 534,
"hasSortStage" : true,
"cursorExhausted" : true,
"numYield" : 215,
"locks" : {
"Global" : {
"acquireCount" : {
"r" : NumberLong(432)
}
},
"Database" : {
"acquireCount" : {
"r" : NumberLong(216)
}
},
"Collection" : {
"acquireCount" : {
"r" : NumberLong(216)
}
}
},
"nreturned" : 1,
"responseLength" : 169,
"protocol" : "op_command",
"millis" : 4772,
"planSummary" : "IXSCAN { ip: 1 }",
"execStats" : {
"stage" : "CACHED_PLAN",
"nReturned" : 1,
"executionTimeMillisEstimate" : 4777,
"works" : 2,
"advanced" : 1,
"needTime" : 0,
"needYield" : 0,
"saveState" : 215,
"restoreState" : 215,
"isEOF" : 1,
"invalidates" : 0,
"inputStage" : {
"stage" : "PROJECTION",
"nReturned" : 1,
"executionTimeMillisEstimate" : 4777,
"works" : 537,
"advanced" : 1,
"needTime" : 536,
"needYield" : 0,
"saveState" : 215,
"restoreState" : 215,
"isEOF" : 1,
"invalidates" : 0,
"transformBy" : {
"_id" : 0,
"sgfhash" : 1
},
"inputStage" : {
"stage" : "SORT",
"nReturned" : 1,
"executionTimeMillisEstimate" : 4777,
"works" : 537,
"advanced" : 1,
"needTime" : 536,
"needYield" : 0,
"saveState" : 215,
"restoreState" : 215,
"isEOF" : 1,
"invalidates" : 0,
"sortPattern" : {
"_id" : -1
},
"memUsage" : 769426,
"memLimit" : 33554432,
"limitAmount" : 1,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"nReturned" : 534,
"executionTimeMillisEstimate" : 4667,
"works" : 536,
"advanced" : 534,
"needTime" : 1,
"needYield" : 0,
"saveState" : 215,
"restoreState" : 215,
"isEOF" : 1,
"invalidates" : 0,
"inputStage" : {
"stage" : "FETCH",
"nReturned" : 534,
"executionTimeMillisEstimate" : 4667,
"works" : 535,
"advanced" : 534,
"needTime" : 0,
"needYield" : 0,
"saveState" : 215,
"restoreState" : 215,
"isEOF" : 1,
"invalidates" : 0,
"docsExamined" : 534,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 534,
"executionTimeMillisEstimate" : 13,
"works" : 535,
"advanced" : 534,
"needTime" : 0,
"needYield" : 0,
"saveState" : 215,
"restoreState" : 215,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : {
"ip" : 1
},
"indexName" : "ip_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"ip" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"ip" : [
"[\"1.2.3.4\", \"1.2.3.4\"]"
]
},
"keysExamined" : 534,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
}
}
}
}
},
"ts" : ISODate("2018-01-04T01:09:03.361Z"),
"client" : "127.0.0.1",
"appName" : "MongoDB Shell",
"allUsers" : [ ],
"user" : ""
Which revealed it wasn't using the multi-key index at all. I vaguely remembered the hint command, and making my query more like this:
db.games.find({ ip: "1.2.3.4" }, { _id: 0, sgfhash: 1} ).hint( "ip_-1__id_-1" ).sort({ _id: -1 }).limit(1);
solved it. Results are now instant.
I realize the query optimizer can't make every query perfect and that is why hint() exists, but it seemed odd it'd work for one direction but not the other, and that explain() would lie to me about what was going to happen vs what the profiling actually showed.
- is related to
-
SERVER-32452 Replanning may not occur when a plan with an extremely high 'works' value is cached
-
- Closed
-