[SERVER-53892] planSummary field incorrect when backup plan is used Created: 19/Jan/21  Updated: 02/Mar/22  Resolved: 20/May/21

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Chris Harris Assignee: Yoon Soo Kim
Resolution: Won't Fix Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Sprint: Query Execution 2021-03-22, Query Execution 2021-04-05, Query Execution 2021-04-19, Query Execution 2021-05-03, Query Execution 2021-05-31
Participants:
Case:

 Description   

Consider the following result from planning a query (on 4.2.11):

2021-01-19T15:23:11.369-0600 D2 QUERY    [conn3] Winning plan: IXSCAN { field: 1 }
2021-01-19T15:23:11.370-0600 D5 QUERY    [conn3] Winner has blocking stage, looking for backup plan...
2021-01-19T15:23:11.371-0600 D5 QUERY    [conn3] Candidate 1 is backup child
 
2021-01-19T15:23:11.373-0600 D5 QUERY    [conn3] Best plan errored out switching to backup

The (standard verbosity) log entry recorded at the conclusion of the operation is:

2021-01-19T15:23:13.459-0600 I  COMMAND  [conn3] command test.foo appName: "MongoDB Shell" command: find { find: "foo", filter: { field: 123.0 }, skip: 40000.0, limit: 10.0, singleBatch: false, sort: { _id: 1.0 }, lsid: { id: UUID("7e16439f-e7b6-4c0f-a615-3185d1a06143") }, $db: "test" } planSummary: IXSCAN { field: 1 } keysExamined:1040009 docsExamined:1040009 fromMultiPlanner:1 cursorExhausted:1 numYields:8369 nreturned:10 queryHash:62C53BBA planCacheKey:72D6FFD0 reslen:10807 locks:{ ReplicationStateTransition: { acquireCount: { w: 8370 } }, Global: { acquireCount: { r: 8370 } }, Database: { acquireCount: { r: 8370 } }, Collection: { acquireCount: { r: 8370 } }, Mutex: { acquireCount: { r: 1 } } } storage:{} protocol:op_msg 3367ms

Note here that the winning plan from the selection process was the one that used the { field: 1 } index.  That plan ended up failing (as it exceeded the sort memory threshold) which resulted in the database switching to using the backup plan (a scan of the { _id: 1 } index to support the sort in a non-blocking manner).  The final log entry reports the winning plan from the selection process as the planSummary but the database actually ended up using a different index/plan for the successful execution of the operation.  

The log entry should reflect the plan that was ultimately used (similar to what is normally done for replanned entries currently).  Indication that it was a backup plan was used may also be helpful.  



 Comments   
Comment by Yoon Soo Kim [ 19/May/21 ]

It does not repro on 5.0.0-alpha0 because there's no switching to a backup plan.

Repro steps on 5.0.0-alpha0:

 

db.adminCommand({"setParameter": 1, "logComponentVerbosity": {query: {verbosity: 5}, command: {verbosity: 5}}});
db.coll.createIndex({"a": 1});
for (var i = 1; i < 40000; ++i) { db.coll.insert({"a": i}); }
db.coll.explain().find({"a": {"$gt": 1}}).sort({_id: 1});

 

Logs:

{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D5", "c":"QUERY", "id":20967, "ctx":"conn1","msg":"Beginning planning","attr":{"options":"INDEX_INTERSECTION SPLIT_LIMITED_SORT ","query":"ns=test.collTree: a $gt 1.0
Sort: { _id: 1.0 }
Proj: {}
"}}
{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D5", "c":"QUERY", "id":20968, "ctx":"conn1","msg":"Index number and details","attr":{"indexNumber":0,"index":"kp: { _id: 1 } unique name: '(_id_, )' io: { v: 2, key: { _id: 1 }, name: \"_id_\" }"}}
{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D5", "c":"QUERY", "id":20968, "ctx":"conn1","msg":"Index number and details","attr":{"indexNumber":1,"index":"kp: { a: 1.0 } name: '(a_1, )' io: { v: 2, key: { a: 1.0 }, name: \"a_1\" }"}}
{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D5", "c":"QUERY", "id":20970, "ctx":"conn1","msg":"Predicate over field","attr":{"field":"a"}}
{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D2", "c":"QUERY", "id":20971, "ctx":"conn1","msg":"Relevant index","attr":{"indexNumber":0,"index":"kp: { a: 1.0 } name: '(a_1, )' io: { v: 2, key: { a: 1.0 }, name: \"a_1\" }"}}
{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D5", "c":"QUERY", "id":20972, "ctx":"conn1","msg":"Rated tree","attr":{"tree":"a $gt 1.0 || First: 0 notFirst: full path: a
"}}
{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D5", "c":"QUERY", "id":20944, "ctx":"conn1","msg":"Tagging memoID","attr":{"id":1}}
{"t":{"$date":"2021-05-19T01:10:31.854+00:00"},"s":"D5", "c":"QUERY", "id":20943, "ctx":"conn1","msg":"Enumerator: memo just before moving","attr":{"memo":"[Node #1]: AND enumstate counter 0
\tchoice 0:
\t\tsubnodes: 
\t\tidx[0]
\t\t\tpos 0 pred a $gt 1.0
"}}
{"t":{"$date":"2021-05-19T01:10:31.855+00:00"},"s":"D5", "c":"QUERY", "id":20976, "ctx":"conn1","msg":"About to build solntree from tagged tree","attr":{"tree":"a $gt 1.0 || Selected Index #0 pos 0 combine 1
"}}
{"t":{"$date":"2021-05-19T01:10:31.855+00:00"},"s":"D5", "c":"QUERY", "id":20978, "ctx":"conn1","msg":"Planner: adding solution","attr":{"solution":"SORT
---type = SIMPLE
---pattern = { _id: 1.0 }
---limit = 0
---nodeId = 3
---fetched = 1
---sortedByDiskLoc = 0
---providedSorts = {baseSortPattern: {}, ignoredFields: []}
---Child:
------FETCH
---------nodeId = 2
---------fetched = 1
---------sortedByDiskLoc = 0
---------providedSorts = {baseSortPattern: { a: 1 }, ignoredFields: []}
---------Child:
------------IXSCAN
---------------indexName = a_1
---------------keyPattern = { a: 1.0 }
---------------direction = 1
---------------bounds = field #0['a']: (1.0, inf.0]
---------------nodeId = 1
---------------fetched = 0
---------------sortedByDiskLoc = 0
---------------providedSorts = {baseSortPattern: { a: 1 }, ignoredFields: []}
"}}
{"t":{"$date":"2021-05-19T01:10:31.855+00:00"},"s":"D5", "c":"QUERY", "id":20979, "ctx":"conn1","msg":"Planner: outputted indexed solutions","attr":{"numSolutions":1}}
{"t":{"$date":"2021-05-19T01:10:31.855+00:00"},"s":"D5", "c":"QUERY", "id":20981, "ctx":"conn1","msg":"Planner: outputting soln that uses index to provide sort"}
{"t":{"$date":"2021-05-19T01:10:31.861+00:00"},"s":"D5", "c":"QUERY", "id":20956, "ctx":"conn1","msg":"Scoring plan","attr":{"planIndex":0,"querySolution":"SORT
---type = SIMPLE
---pattern = { _id: 1.0 }
---limit = 0
---nodeId = 3
---fetched = 1
---sortedByDiskLoc = 0
---providedSorts = {baseSortPattern: {}, ignoredFields: []}
---Child:
------FETCH
---------nodeId = 2
---------fetched = 1
---------sortedByDiskLoc = 0
---------providedSorts = {baseSortPattern: { a: 1 }, ignoredFields: []}
---------Child:
------------IXSCAN
---------------indexName = a_1
---------------keyPattern = { a: 1.0 }
---------------direction = 1
---------------bounds = field #0['a']: (1.0, inf.0]
---------------nodeId = 1
---------------fetched = 0
---------------sortedByDiskLoc = 0
---------------providedSorts = {baseSortPattern: { a: 1 }, ignoredFields: []}
","stats":"{
 \"stage\": \"SORT\",
 \"nReturned\": 0,
 \"executionTimeMillisEstimate\": 0,
 \"works\": 102,
 \"advanced\": 0,
 \"needTime\": 102,
 \"needYield\": 0,
 \"saveState\": 0,
 \"restoreState\": 0,
 \"isEOF\": 0,
 \"sortPattern\": {
 \"_id\": 1
 },
 \"memLimit\": 104857600,
 \"type\": \"simple\",
 \"totalDataSizeSorted\": 0,
 \"usedDisk\": false,
 \"inputStage\": {
 \"stage\": \"FETCH\",
 \"nReturned\": 102,
 \"executionTimeMillisEstimate\": 0,
 \"works\": 102,
 \"advanced\": 102,
 \"needTime\": 0,
 \"needYield\": 0,
 \"saveState\": 0,
 \"restoreState\": 0,
 \"isEOF\": 0,
 \"docsExamined\": 102,
 \"alreadyHasObj\": 0,
 \"inputStage\": {
 \"stage\": \"IXSCAN\",
 \"nReturned\": 102,
 \"executionTimeMillisEstimate\": 0,
 \"works\": 102,
 \"advanced\": 102,
 \"needTime\": 0,
 \"needYield\": 0,
 \"saveState\": 0,
 \"restoreState\": 0,
 \"isEOF\": 0,
 \"keyPattern\": {
 \"a\": 1
 },
 \"indexName\": \"a_1\",
 \"isMultiKey\": false,
 \"multiKeyPaths\": {
 \"a\": []
 },
 \"isUnique\": false,
 \"isSparse\": false,
 \"isPartial\": false,
 \"indexVersion\": 2,
 \"direction\": \"forward\",
 \"indexBounds\": {
 \"a\": [
 \"(1.0, inf.0]\"
 ]
 },
 \"keysExamined\": 102,
 \"seeks\": 1,
 \"dupsTested\": 0,
 \"dupsDropped\": 0
 }
 }
}"}}
{"t":{"$date":"2021-05-19T01:10:31.862+00:00"},"s":"D2", "c":"QUERY", "id":20957, "ctx":"conn1","msg":"Scoring query plan","attr":{"planSummary":"IXSCAN { a: 1 }","planHitEOF":false}}
{"t":{"$date":"2021-05-19T01:10:31.862+00:00"},"s":"D2", "c":"QUERY", "id":20961, "ctx":"conn1","msg":"Score formula","attr":{"formula":"score(1.0001) = baseScore(1) + productivity((0 advanced)/(102 works) = 0) + tieBreakers(0 noFetchBonus + 0 noSortBonus + 0.0001 noIxisectBonus = 0.0001)"}}
{"t":{"$date":"2021-05-19T01:10:31.862+00:00"},"s":"D5", "c":"QUERY", "id":20958, "ctx":"conn1","msg":"Basic plan score","attr":{"score":1.0001}}
{"t":{"$date":"2021-05-19T01:10:31.862+00:00"},"s":"D5", "c":"QUERY", "id":20956, "ctx":"conn1","msg":"Scoring plan","attr":{"planIndex":1,"querySolution":"FETCH
---filter:
 a $gt 1.0
---nodeId = 2
---fetched = 1
---sortedByDiskLoc = 0
---providedSorts = {baseSortPattern: { _id: 1 }, ignoredFields: []}
---Child:
------IXSCAN
---------indexName = _id_
---------keyPattern = { _id: 1 }
---------direction = 1
---------bounds = field #0['_id']: [MinKey, MaxKey]
---------nodeId = 1
---------fetched = 0
---------sortedByDiskLoc = 0
---------providedSorts = {baseSortPattern: { _id: 1 }, ignoredFields: []}
","stats":"{
 \"stage\": \"FETCH\",
 \"filter\": {
 \"a\": {
 \"$gt\": 1
 }
 },
 \"nReturned\": 101,
 \"executionTimeMillisEstimate\": 0,
 \"works\": 102,
 \"advanced\": 101,
 \"needTime\": 1,
 \"needYield\": 0,
 \"saveState\": 0,
 \"restoreState\": 0,
 \"isEOF\": 0,
 \"docsExamined\": 102,
 \"alreadyHasObj\": 0,
 \"inputStage\": {
 \"stage\": \"IXSCAN\",
 \"nReturned\": 102,
 \"executionTimeMillisEstimate\": 0,
 \"works\": 102,
 \"advanced\": 102,
 \"needTime\": 0,
 \"needYield\": 0,
 \"saveState\": 0,
 \"restoreState\": 0,
 \"isEOF\": 0,
 \"keyPattern\": {
 \"_id\": 1
 },
 \"indexName\": \"_id_\",
 \"isMultiKey\": false,
 \"multiKeyPaths\": {
 \"_id\": []
 },
 \"isUnique\": true,
 \"isSparse\": false,
 \"isPartial\": false,
 \"indexVersion\": 2,
 \"direction\": \"forward\",
 \"indexBounds\": {
 \"_id\": [
 \"[MinKey, MaxKey]\"
 ]
 },
 \"keysExamined\": 102,
 \"seeks\": 1,
 \"dupsTested\": 0,
 \"dupsDropped\": 0
 }
}"}}
{"t":{"$date":"2021-05-19T01:10:31.862+00:00"},"s":"D2", "c":"QUERY", "id":20957, "ctx":"conn1","msg":"Scoring query plan","attr":{"planSummary":"IXSCAN { _id: 1 }","planHitEOF":false}}
{"t":{"$date":"2021-05-19T01:10:31.863+00:00"},"s":"D2", "c":"QUERY", "id":20961, "ctx":"conn1","msg":"Score formula","attr":{"formula":"score(1.9903960784313726) = baseScore(1) + productivity((101 advanced)/(102 works) = 0.99019607843137258) + tieBreakers(0 noFetchBonus + 0.0001 noSortBonus + 0.0001 noIxisectBonus = 0.00020000000000000001)"}}
{"t":{"$date":"2021-05-19T01:10:31.863+00:00"},"s":"D5", "c":"QUERY", "id":20958, "ctx":"conn1","msg":"Basic plan score","attr":{"score":1.9903960784313726}}
{"t":{"$date":"2021-05-19T01:10:31.863+00:00"},"s":"D5", "c":"QUERY", "id":20590, "ctx":"conn1","msg":"Winning solution","attr":{"bestSolution":"FETCH
---filter:
 a $gt 1.0
---nodeId = 2
---fetched = 1
---sortedByDiskLoc = 0
---providedSorts = {baseSortPattern: { _id: 1 }, ignoredFields: []}
---Child:
------IXSCAN
---------indexName = _id_
---------keyPattern = { _id: 1 }
---------direction = 1
---------bounds = field #0['_id']: [MinKey, MaxKey]
---------nodeId = 1
---------fetched = 0
---------sortedByDiskLoc = 0
---------providedSorts = {baseSortPattern: { _id: 1 }, ignoredFields: []}
"}}

 

 

Generated at Thu Feb 08 05:32:07 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.