While looking at the QLOG output, I noticed that one of the solutions doesn't have the KEEP_MUTATIONS stage. It seems erroneous, as the code in planner_analysis.cpp doesn't imply any obvious exception for this index.
> db.contact.insert({_id:10,oId:100})
WriteResult({ "nInserted" : 1 })
> db.contact.insert({_id:11,oId:1234})
WriteResult({ "nInserted" : 1 })
> db.contact.insert({_id:12,oId:1234})
WriteResult({ "nInserted" : 1 })
> db.contact.insert({_id:13,oId:100})
WriteResult({ "nInserted" : 1 })
> db.contact.ensureIndex({ organizationId: 1.0, externalId: 1.0, _id: 1.0 })
{
"createdCollectionAutomatically" : false,
"numIndexesBefore" : 1,
"numIndexesAfter" : 2,
"ok" : 1
}
> db.adminCommand({setParameter: 1, verboseQueryLogging: true})
{ "was" : false, "ok" : 1 }
> db.contact.find({ _id: { $in: [ 11 ] }, organizationId: { $ne: 100 } } )
{ "_id" : 11, "oId" : 1234 }
QLOG output:
2014-11-04T20:35:25.843-0500 [conn3] build index on: test.contact properties: { v: 1, key: { organizationId: 1.0, externalId: 1.0, _id: 1.0 }, name: "organizationId_1_externalId_1__id_1", ns: "test.contact" }
2014-11-04T20:35:25.845-0500 [conn3] building index using bulk method
2014-11-04T20:35:25.846-0500 [conn3] build index done. scanned 4 total records. 0.003 secs
2014-11-04T20:36:37.769-0500 [clientcursormon] mem (MB) res:10 virt:2826
2014-11-04T20:36:37.769-0500 [clientcursormon] mapped (incl journal view):320
2014-11-04T20:36:37.769-0500 [clientcursormon] connections:1
2014-11-04T20:37:01.897-0500 [conn3] [QLOG] Running query:
ns=test.contact limit=0 skip=0
Tree: $and
$not
organizationId == 100.0
_id $in [ 11.0 ]
Sort: {}
Proj: {}
2014-11-04T20:37:01.897-0500 [conn3] [QLOG] Beginning planning...
=============================
Options = INDEX_INTERSECTION KEEP_MUTATIONS
Canonical query:
ns=test.contact limit=0 skip=0
Tree: $and
$not
organizationId == 100.0
_id $in [ 11.0 ]
Sort: {}
Proj: {}
=============================
2014-11-04T20:37:01.898-0500 [conn3] [QLOG] Index 0 is kp: { _id: 1 } io: { v: 1, key: { _id: 1 }, name: "_id_", ns: "test.contact" }
2014-11-04T20:37:01.898-0500 [conn3] [QLOG] Index 1 is kp: { organizationId: 1.0, externalId: 1.0, _id: 1.0 } io: { v: 1, key: { organizationId: 1.0, externalId: 1.0, _id: 1.0 }, name: "organizationId_1_externalId_1__id_1", ns: "test.contact" }
2014-11-04T20:37:01.898-0500 [conn3] [QLOG] Predicate over field 'organizationId'
2014-11-04T20:37:01.898-0500 [conn3] [QLOG] Predicate over field '_id'
2014-11-04T20:37:01.898-0500 [conn3] [QLOG] Relevant index 0 is kp: { _id: 1 } io: { v: 1, key: { _id: 1 }, name: "_id_", ns: "test.contact" }
2014-11-04T20:37:01.898-0500 [conn3] [QLOG] Relevant index 1 is kp: { organizationId: 1.0, externalId: 1.0, _id: 1.0 } io: { v: 1, key: { organizationId: 1.0, externalId: 1.0, _id: 1.0 }, name: "organizationId_1_externalId_1__id_1", ns: "test.contact" }
2014-11-04T20:37:01.899-0500 [conn3] [QLOG] Rated tree:
$and
$not
organizationId == 100.0 || First: 1 notFirst: full path: organizationId
_id $in [ 11.0 ] || First: 0 notFirst: 1 full path: _id
2014-11-04T20:37:01.899-0500 [conn3] [QLOG] Tagging memoID 1
2014-11-04T20:37:01.899-0500 [conn3] [QLOG] Enumerator: memo just before moving:
2014-11-04T20:37:01.899-0500 [conn3] [QLOG] About to build solntree from tagged tree:
$and
_id $in [ 11.0 ] || Selected Index #0 pos 0
$not
organizationId == 100.0
2014-11-04T20:37:01.899-0500 [conn3] [QLOG] Planner: adding solution:
KEEP_MUTATIONS
---filter:
$and
$not
organizationId == 100.0
_id $in [ 11.0 ]
---fetched = 1
---sortedByDiskLoc = 0
---getSort = []
---Child:
------FETCH
---------filter:
$not
organizationId == 100.0
---------fetched = 1
---------sortedByDiskLoc = 1
---------getSort = [{ _id: 1 }, ]
---------Child:
------------IXSCAN
---------------keyPattern = { _id: 1 }
---------------direction = 1
---------------bounds = field #0['_id']: [11.0, 11.0]
---------------fetched = 0
---------------sortedByDiskLoc = 1
---------------getSort = [{ _id: 1 }, ]
2014-11-04T20:37:01.900-0500 [conn3] [QLOG] Tagging memoID 1
2014-11-04T20:37:01.900-0500 [conn3] [QLOG] Enumerator: memo just before moving:
2014-11-04T20:37:01.900-0500 [conn3] [QLOG] About to build solntree from tagged tree:
$and
$not
organizationId == 100.0 || Selected Index #1 pos 0
_id $in [ 11.0 ] || Selected Index #1 pos 2
2014-11-04T20:37:01.900-0500 [conn3] [QLOG] Planner: adding solution:
FETCH
---fetched = 1
---sortedByDiskLoc = 0
---getSort = [{ organizationId: 1 }, { organizationId: 1, externalId: 1 }, { organizationId: 1, externalId: 1, _id: 1 }, ]
---Child:
------IXSCAN
---------keyPattern = { organizationId: 1.0, externalId: 1.0, _id: 1.0 }
---------direction = 1
---------bounds = field #0['organizationId']: [MinKey, 100.0), (100.0, MaxKey], field #1['externalId']: [MinKey, MaxKey], field #2['_id']: [11.0, 11.0]
---------fetched = 0
---------sortedByDiskLoc = 0
---------getSort = [{ organizationId: 1 }, { organizationId: 1, externalId: 1 }, { organizationId: 1, externalId: 1, _id: 1 }, ]
2014-11-04T20:37:01.900-0500 [conn3] [QLOG] Planner: outputted 2 indexed solutions.
2014-11-04T20:37:01.901-0500 [conn3] [QLOG] Scoring plan 0:
KEEP_MUTATIONS
---filter:
$and
$not
organizationId == 100.0
_id $in [ 11.0 ]
---fetched = 1
---sortedByDiskLoc = 0
---getSort = []
---Child:
------FETCH
---------filter:
$not
organizationId == 100.0
---------fetched = 1
---------sortedByDiskLoc = 1
---------getSort = [{ _id: 1 }, ]
---------Child:
------------IXSCAN
---------------keyPattern = { _id: 1 }
---------------direction = 1
---------------bounds = field #0['_id']: [11.0, 11.0]
---------------fetched = 0
---------------sortedByDiskLoc = 1
---------------getSort = [{ _id: 1 }, ]
Stats:
{ "type" : "KEEP_MUTATIONS",
"works" : 2,
"yields" : 0,
"unyields" : 0,
"invalidates" : 0,
"advanced" : 1,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 1,
"children" : [
{ "type" : "FETCH",
"works" : 2,
"yields" : 0,
"unyields" : 0,
"invalidates" : 0,
"advanced" : 1,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 1,
"alreadyHasObj" : 0,
"forcedFetches" : 0,
"matchTested" : 1,
"children" : [
{ "type" : "IXSCAN",
"works" : 2,
"yields" : 0,
"unyields" : 0,
"invalidates" : 0,
"advanced" : 1,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 1,
"keyPattern" : "{ _id: 1 }",
"isMultiKey" : 0,
"boundsVerbose" : "field #0['_id']: [11.0, 11.0]",
"yieldMovedCursor" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0,
"matchTested" : 0,
"keysExamined" : 1,
"children" : [] } ] } ] }
2014-11-04T20:37:01.901-0500 [conn3] [QLOG] score(1.5003) = baseScore(1) + productivity((1 advanced)/(2 works + 0 needFetch) = 0.5) + tieBreakers(0.0001 noFetchBonus + 0.0001 noSortBonus + 0.0001 noIxisectBonus = 0.0003)
2014-11-04T20:37:01.901-0500 [conn3] [QLOG] score = 1.5003
2014-11-04T20:37:01.901-0500 [conn3] [QLOG] Adding +1 EOF bonus to score.
2014-11-04T20:37:01.902-0500 [conn3] [QLOG] Scoring plan 1:
FETCH
---fetched = 1
---sortedByDiskLoc = 0
---getSort = [{ organizationId: 1 }, { organizationId: 1, externalId: 1 }, { organizationId: 1, externalId: 1, _id: 1 }, ]
---Child:
------IXSCAN
---------keyPattern = { organizationId: 1.0, externalId: 1.0, _id: 1.0 }
---------direction = 1
---------bounds = field #0['organizationId']: [MinKey, 100.0), (100.0, MaxKey], field #1['externalId']: [MinKey, MaxKey], field #2['_id']: [11.0, 11.0]
---------fetched = 0
---------sortedByDiskLoc = 0
---------getSort = [{ organizationId: 1 }, { organizationId: 1, externalId: 1 }, { organizationId: 1, externalId: 1, _id: 1 }, ]
Stats:
{ "type" : "FETCH",
"works" : 2,
"yields" : 0,
"unyields" : 0,
"invalidates" : 0,
"advanced" : 1,
"needTime" : 1,
"needFetch" : 0,
"isEOF" : 0,
"alreadyHasObj" : 0,
"forcedFetches" : 0,
"matchTested" : 0,
"children" : [
{ "type" : "IXSCAN",
"works" : 2,
"yields" : 0,
"unyields" : 0,
"invalidates" : 0,
"advanced" : 1,
"needTime" : 1,
"needFetch" : 0,
"isEOF" : 0,
"keyPattern" : "{ organizationId: 1.0, externalId: 1.0, _id: 1.0 }",
"isMultiKey" : 0,
"boundsVerbose" : "field #0['organizationId']: [MinKey, 100.0), (100.0, MaxKey], field #1['externalId']: [MinKey, MaxKey], field #2['_id']: [11.0, 11.0]",
"yieldMovedCursor" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0,
"matchTested" : 0,
"keysExamined" : 2,
"children" : [] } ] }
2014-11-04T20:37:01.902-0500 [conn3] [QLOG] score(1.5003) = baseScore(1) + productivity((1 advanced)/(2 works + 0 needFetch) = 0.5) + tieBreakers(0.0001 noFetchBonus + 0.0001 noSortBonus + 0.0001 noIxisectBonus = 0.0003)
2014-11-04T20:37:01.902-0500 [conn3] [QLOG] score = 1.5003
2014-11-04T20:37:01.902-0500 [conn3] [QLOG] Winning solution:
KEEP_MUTATIONS
---filter:
$and
$not
organizationId == 100.0
_id $in [ 11.0 ]
---fetched = 1
---sortedByDiskLoc = 0
---getSort = []
---Child:
------FETCH
---------filter:
$not
organizationId == 100.0
---------fetched = 1
---------sortedByDiskLoc = 1
---------getSort = [{ _id: 1 }, ]
---------Child:
------------IXSCAN
---------------keyPattern = { _id: 1 }
---------------direction = 1
---------------bounds = field #0['_id']: [11.0, 11.0]
---------------fetched = 0
---------------sortedByDiskLoc = 1
---------------getSort = [{ _id: 1 }, ]
2014-11-04T20:37:01.902-0500 [conn3] [QLOG] Not caching runner but returning 1 results.
- is related to
-
SERVER-20299 Delete KEEP_MUTATIONS stage
-
- Closed
-