[
https://issues.apache.org/jira/browse/OAK-8351?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stefan Egli updated OAK-8351:
-----------------------------
Description:
On a mongodb setup a long running revision garbage collection operation has
been witnessed. The query was running for hours. Doing a
{{planCacheSetFilter}}, which hinted mongodb to use a specific index, together
with killing the running command resolved the situation.
The problem was that mongodb generated a query plan which scored high (2.0003)
but included an index scan through the {{\_id_}} index (and the collection
contained millions of documents). It also generated other, better, plans, but
they all "only" had the same high score, so it seemed legitimate that mongodb
would choose this one.
The reason why this, problematic, query plan resulted in a high score seems to
be that it does indeed find 101 documents after entering the first "or" - but
during query execution it would also enter the other "or" parts where it has
chosen to do a {{\_id_}} index scan.
The query involved was:
{noformat}
{
"_sdType" : {
"$in" : [
50,
60,
70
]
},
"$or" : [
{
"_sdType" : 50
},
{
"_sdType" : 60
},
{
"_sdType" : 70,
"$or" : [
{
"_id" : /.*-1\/0/
},
{
"_id" : /[^-]*/,
"_path" : /.*-1\/0/
}
],
"_sdMaxRevTime" : {
"$lt" : NumberLong(1551843365)
}
},
{
"_sdType" : 70,
"$or" : [
{
"_id" : /.*-2\/0/
},
{
"_id" : /[^-]*/,
"_path" : /.*-2\/0/
}
],
"_sdMaxRevTime" : {
"$lt" : NumberLong(1550757370)
}
}
],
"_sdMaxRevTime" : {
"$lt" :
NumberLong(1551756965)
}
}
{noformat}
The problematic plan was:
{noformat}
{
"details" : {
"solution" : "(index-tagged expression tree:
tree=Node\n---Node\n------Node\n---------Node\n------------Node\n---------------Leaf
_id_, pos: 0, can combine? 1\n---------------Leaf \n------------Leaf _id_,
pos: 0, can combine? 1\n---------Leaf \n---------Leaf
\n------Node\n---------Node\n------------Node\n---------------Leaf _id_, pos:
0, can combine? 1\n---------------Leaf \n------------Leaf _id_, pos: 0, can
combine? 1\n---------Leaf \n---------Leaf \n------Leaf
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1\n------Leaf
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1\n---Leaf Move to 2:
_sdType_1__sdMaxRevTime_1, pos: 1, can combine? 1. Move to 3:
_sdType_1__sdMaxRevTime_1, pos: 1, can combine? 1. \n---Leaf Move to 2:
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1. Move to 3:
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1. \n)"
},
"reason" : {
"score" : 2.0003,
"stats" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"_sdMaxRevTime"
: {
"$lt" :
NumberLong(1551410180)
}
},
{
"_sdType" : {
"$in" :
[
50,
60,
70
]
}
}
]
},
"nReturned" : 101,
"executionTimeMillisEstimate" : 0,
"works" : 101,
"advanced" : 101,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"docsExamined" : 101,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "OR",
"nReturned" : 101,
"executionTimeMillisEstimate" :
0,
"works" : 101,
"advanced" : 101,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"dupsTested" : 101,
"dupsDropped" : 0,
"recordIdsForgotten" : 0,
"inputStages" : [
{
"stage" :
"IXSCAN",
"nReturned" :
101,
"executionTimeMillisEstimate" : 0,
"works" : 101,
"advanced" :
101,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"keyPattern" : {
"_sdType" : 1,
"_sdMaxRevTime" : 1
},
"indexName" :
"_sdType_1__sdMaxRevTime_1",
"isMultiKey" :
false,
"multiKeyPaths"
: {
"_sdType" : [ ],
"_sdMaxRevTime" : [ ]
},
"isUnique" :
false,
"isSparse" :
true,
"isPartial" :
false,
"indexVersion"
: 2,
"direction" :
"forward",
"indexBounds" :
{
"_sdType" : [
"[50, 50]"
],
"_sdMaxRevTime" : [
"[-inf.0, 1551410180)"
]
},
"keysExamined"
: 101,
"seeks" : 1,
"dupsTested" :
0,
"dupsDropped" :
0,
"seenInvalidated" : 0
},
{
"stage" :
"IXSCAN",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"keyPattern" : {
"_sdType" : 1,
"_sdMaxRevTime" : 1
},
"indexName" :
"_sdType_1__sdMaxRevTime_1",
"isMultiKey" :
false,
"multiKeyPaths"
: {
"_sdType" : [ ],
"_sdMaxRevTime" : [ ]
},
"isUnique" :
false,
"isSparse" :
true,
"isPartial" :
false,
"indexVersion"
: 2,
"direction" :
"forward",
"indexBounds" :
{
"_sdType" : [
"[60, 60]"
],
"_sdMaxRevTime" : [
"[-inf.0, 1551410180)"
]
},
"keysExamined"
: 0,
"seeks" : 0,
"dupsTested" :
0,
"dupsDropped" :
0,
"seenInvalidated" : 0
},
{
"stage" :
"FETCH",
"filter" : {
"$and"
: [
{
"_sdType" : {
"$eq" : 70
}
},
{
"_sdMaxRevTime" : {
"$lt" : NumberLong(1551496575)
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"docsExamined"
: 0,
"alreadyHasObj"
: 0,
"inputStage" : {
"stage"
: "OR",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works"
: 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF"
: 0,
"invalidates" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"recordIdsForgotten" : 0,
"inputStages" : [
{
"stage" : "FETCH",
"filter" : {
"_path" : {
"$regex" : ".*-1/0"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"docsExamined" : 0,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"filter" : {
"_id" : {
"$regex" : "[^-]*"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/[^-]*/, /[^-]*/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
},
{
"stage" : "IXSCAN",
"filter" : {
"$or" : [
{
"_id" : {
"$regex" : ".*-1/0"
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/.*-1/0/, /.*-1/0/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
]
}
},
{
"stage" :
"FETCH",
"filter" : {
"$and"
: [
{
"_sdType" : {
"$eq" : 70
}
},
{
"_sdMaxRevTime" : {
"$lt" : NumberLong(1550757370)
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"docsExamined"
: 0,
"alreadyHasObj"
: 0,
"inputStage" : {
"stage"
: "OR",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works"
: 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF"
: 0,
"invalidates" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"recordIdsForgotten" : 0,
"inputStages" : [
{
"stage" : "FETCH",
"filter" : {
"_path" : {
"$regex" : ".*-2/0"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"docsExamined" : 0,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"filter" : {
"_id" : {
"$regex" : "[^-]*"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/[^-]*/, /[^-]*/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
},
{
"stage" : "IXSCAN",
"filter" : {
"$or" : [
{
"_id" : {
"$regex" : ".*-2/0"
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/.*-2/0/, /.*-2/0/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
]
}
}
]
}
}
},
"feedback" : {
"nfeedback" : 18,
"scores" : [
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
}
]
},
"filterSet" : false
}
{noformat}
Note that this was primarily caused by
[SERVER-20616|https://jira.mongodb.org/browse/SERVER-20616] and that
[SERVER-42090|https://jira.mongodb.org/browse/SERVER-42090] and
[SERVER-24396|https://jira.mongodb.org/browse/SERVER-24396] would also have
been helpful preventing this.
was:
On a mongodb setup a long running revision garbage collection operation has
been witnessed. The query was running for hours. Doing a
{{planCacheSetFilter}}, which hinted mongodb to use a specific index, together
with killing the running command resolved the situation.
The problem was that mongodb generated a query plan which scored high (2.0003)
but included an index scan through the {{\_id_}} index (and the collection
contained millions of documents). It also generated other, better, plans, but
they all "only" had the same high score, so it seemed legitimate that mongodb
would choose this one.
The reason why this, problematic, query plan resulted in a high score seems to
be that it does indeed find 101 documents after entering the first "or" - but
during query execution it would also enter the other "or" parts where it has
chosen to do a {{\_id_}} index scan.
The query involved was:
{noformat}
{
"_sdType" : {
"$in" : [
50,
60,
70
]
},
"$or" : [
{
"_sdType" : 50
},
{
"_sdType" : 60
},
{
"_sdType" : 70,
"$or" : [
{
"_id" : /.*-1\/0/
},
{
"_id" : /[^-]*/,
"_path" : /.*-1\/0/
}
],
"_sdMaxRevTime" : {
"$lt" : NumberLong(1551843365)
}
},
{
"_sdType" : 70,
"$or" : [
{
"_id" : /.*-2\/0/
},
{
"_id" : /[^-]*/,
"_path" : /.*-2\/0/
}
],
"_sdMaxRevTime" : {
"$lt" : NumberLong(1550757370)
}
}
],
"_sdMaxRevTime" : {
"$lt" :
NumberLong(1551756965)
}
}
{noformat}
The problematic plan was:
{noformat}
{
"details" : {
"solution" : "(index-tagged expression tree:
tree=Node\n---Node\n------Node\n---------Node\n------------Node\n---------------Leaf
_id_, pos: 0, can combine? 1\n---------------Leaf \n------------Leaf _id_,
pos: 0, can combine? 1\n---------Leaf \n---------Leaf
\n------Node\n---------Node\n------------Node\n---------------Leaf _id_, pos:
0, can combine? 1\n---------------Leaf \n------------Leaf _id_, pos: 0, can
combine? 1\n---------Leaf \n---------Leaf \n------Leaf
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1\n------Leaf
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1\n---Leaf Move to 2:
_sdType_1__sdMaxRevTime_1, pos: 1, can combine? 1. Move to 3:
_sdType_1__sdMaxRevTime_1, pos: 1, can combine? 1. \n---Leaf Move to 2:
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1. Move to 3:
_sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1. \n)"
},
"reason" : {
"score" : 2.0003,
"stats" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"_sdMaxRevTime"
: {
"$lt" :
NumberLong(1551410180)
}
},
{
"_sdType" : {
"$in" :
[
50,
60,
70
]
}
}
]
},
"nReturned" : 101,
"executionTimeMillisEstimate" : 0,
"works" : 101,
"advanced" : 101,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"docsExamined" : 101,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "OR",
"nReturned" : 101,
"executionTimeMillisEstimate" :
0,
"works" : 101,
"advanced" : 101,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"dupsTested" : 101,
"dupsDropped" : 0,
"recordIdsForgotten" : 0,
"inputStages" : [
{
"stage" :
"IXSCAN",
"nReturned" :
101,
"executionTimeMillisEstimate" : 0,
"works" : 101,
"advanced" :
101,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"keyPattern" : {
"_sdType" : 1,
"_sdMaxRevTime" : 1
},
"indexName" :
"_sdType_1__sdMaxRevTime_1",
"isMultiKey" :
false,
"multiKeyPaths"
: {
"_sdType" : [ ],
"_sdMaxRevTime" : [ ]
},
"isUnique" :
false,
"isSparse" :
true,
"isPartial" :
false,
"indexVersion"
: 2,
"direction" :
"forward",
"indexBounds" :
{
"_sdType" : [
"[50, 50]"
],
"_sdMaxRevTime" : [
"[-inf.0, 1551410180)"
]
},
"keysExamined"
: 101,
"seeks" : 1,
"dupsTested" :
0,
"dupsDropped" :
0,
"seenInvalidated" : 0
},
{
"stage" :
"IXSCAN",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"keyPattern" : {
"_sdType" : 1,
"_sdMaxRevTime" : 1
},
"indexName" :
"_sdType_1__sdMaxRevTime_1",
"isMultiKey" :
false,
"multiKeyPaths"
: {
"_sdType" : [ ],
"_sdMaxRevTime" : [ ]
},
"isUnique" :
false,
"isSparse" :
true,
"isPartial" :
false,
"indexVersion"
: 2,
"direction" :
"forward",
"indexBounds" :
{
"_sdType" : [
"[60, 60]"
],
"_sdMaxRevTime" : [
"[-inf.0, 1551410180)"
]
},
"keysExamined"
: 0,
"seeks" : 0,
"dupsTested" :
0,
"dupsDropped" :
0,
"seenInvalidated" : 0
},
{
"stage" :
"FETCH",
"filter" : {
"$and"
: [
{
"_sdType" : {
"$eq" : 70
}
},
{
"_sdMaxRevTime" : {
"$lt" : NumberLong(1551496575)
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"docsExamined"
: 0,
"alreadyHasObj"
: 0,
"inputStage" : {
"stage"
: "OR",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works"
: 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF"
: 0,
"invalidates" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"recordIdsForgotten" : 0,
"inputStages" : [
{
"stage" : "FETCH",
"filter" : {
"_path" : {
"$regex" : ".*-1/0"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"docsExamined" : 0,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"filter" : {
"_id" : {
"$regex" : "[^-]*"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/[^-]*/, /[^-]*/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
},
{
"stage" : "IXSCAN",
"filter" : {
"$or" : [
{
"_id" : {
"$regex" : ".*-1/0"
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/.*-1/0/, /.*-1/0/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
]
}
},
{
"stage" :
"FETCH",
"filter" : {
"$and"
: [
{
"_sdType" : {
"$eq" : 70
}
},
{
"_sdMaxRevTime" : {
"$lt" : NumberLong(1550757370)
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState"
: 3,
"isEOF" : 0,
"invalidates" :
0,
"docsExamined"
: 0,
"alreadyHasObj"
: 0,
"inputStage" : {
"stage"
: "OR",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works"
: 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF"
: 0,
"invalidates" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"recordIdsForgotten" : 0,
"inputStages" : [
{
"stage" : "FETCH",
"filter" : {
"_path" : {
"$regex" : ".*-2/0"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"docsExamined" : 0,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"filter" : {
"_id" : {
"$regex" : "[^-]*"
}
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/[^-]*/, /[^-]*/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
},
{
"stage" : "IXSCAN",
"filter" : {
"$or" : [
{
"_id" : {
"$regex" : ".*-2/0"
}
}
]
},
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 0,
"advanced" : 0,
"needTime" : 0,
"needYield" : 0,
"saveState" : 3,
"restoreState" : 3,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"[\"\", {})",
"[/.*-2/0/, /.*-2/0/]"
]
},
"keysExamined" : 0,
"seeks" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
]
}
}
]
}
}
},
"feedback" : {
"nfeedback" : 18,
"scores" : [
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
},
{
"score" : 2.0003
}
]
},
"filterSet" : false
}
{noformat}
> Long running RGC remove and getmore operations
> ----------------------------------------------
>
> Key: OAK-8351
> URL: https://issues.apache.org/jira/browse/OAK-8351
> Project: Jackrabbit Oak
> Issue Type: Bug
> Components: mongomk
> Affects Versions: 1.12.0
> Reporter: Stefan Egli
> Assignee: Stefan Egli
> Priority: Major
> Fix For: 1.10.3, 1.16.0, 1.8.15
>
> Attachments: OAK-8351-1.10.patch, OAK-8351-1.8.patch,
> OAK-8351-merged-1.8.patch, OAK-8351.patch
>
>
> On a mongodb setup a long running revision garbage collection operation has
> been witnessed. The query was running for hours. Doing a
> {{planCacheSetFilter}}, which hinted mongodb to use a specific index,
> together with killing the running command resolved the situation.
> The problem was that mongodb generated a query plan which scored high
> (2.0003) but included an index scan through the {{\_id_}} index (and the
> collection contained millions of documents). It also generated other, better,
> plans, but they all "only" had the same high score, so it seemed legitimate
> that mongodb would choose this one.
> The reason why this, problematic, query plan resulted in a high score seems
> to be that it does indeed find 101 documents after entering the first "or" -
> but during query execution it would also enter the other "or" parts where it
> has chosen to do a {{\_id_}} index scan.
> The query involved was:
> {noformat}
> {
> "_sdType" : {
> "$in" : [
>
> 50,
>
> 60,
>
> 70
> ]
> },
> "$or" : [
> {
>
> "_sdType" : 50
> },
> {
>
> "_sdType" : 60
> },
> {
>
> "_sdType" : 70,
>
> "$or" : [
>
> {
>
> "_id" : /.*-1\/0/
>
> },
>
> {
>
> "_id" : /[^-]*/,
>
> "_path" : /.*-1\/0/
>
> }
>
> ],
>
> "_sdMaxRevTime" : {
>
> "$lt" : NumberLong(1551843365)
>
> }
> },
> {
>
> "_sdType" : 70,
>
> "$or" : [
>
> {
>
> "_id" : /.*-2\/0/
>
> },
>
> {
>
> "_id" : /[^-]*/,
>
> "_path" : /.*-2\/0/
>
> }
>
> ],
>
> "_sdMaxRevTime" : {
>
> "$lt" : NumberLong(1550757370)
>
> }
> }
> ],
> "_sdMaxRevTime" : {
> "$lt" :
> NumberLong(1551756965)
> }
> }
> {noformat}
> The problematic plan was:
> {noformat}
> {
> "details" : {
> "solution" : "(index-tagged expression tree:
> tree=Node\n---Node\n------Node\n---------Node\n------------Node\n---------------Leaf
> _id_, pos: 0, can combine? 1\n---------------Leaf \n------------Leaf _id_,
> pos: 0, can combine? 1\n---------Leaf \n---------Leaf
> \n------Node\n---------Node\n------------Node\n---------------Leaf _id_, pos:
> 0, can combine? 1\n---------------Leaf \n------------Leaf _id_, pos: 0, can
> combine? 1\n---------Leaf \n---------Leaf \n------Leaf
> _sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1\n------Leaf
> _sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1\n---Leaf Move to 2:
> _sdType_1__sdMaxRevTime_1, pos: 1, can combine? 1. Move to 3:
> _sdType_1__sdMaxRevTime_1, pos: 1, can combine? 1. \n---Leaf Move to 2:
> _sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1. Move to 3:
> _sdType_1__sdMaxRevTime_1, pos: 0, can combine? 1. \n)"
> },
> "reason" : {
> "score" : 2.0003,
> "stats" : {
> "stage" : "FETCH",
> "filter" : {
> "$and" : [
> {
> "_sdMaxRevTime"
> : {
> "$lt" :
> NumberLong(1551410180)
> }
> },
> {
> "_sdType" : {
> "$in" :
> [
>
> 50,
>
> 60,
>
> 70
> ]
> }
> }
> ]
> },
> "nReturned" : 101,
> "executionTimeMillisEstimate" : 0,
> "works" : 101,
> "advanced" : 101,
> "needTime" : 0,
> "needYield" : 0,
> "saveState" : 3,
> "restoreState" : 3,
> "isEOF" : 0,
> "invalidates" : 0,
> "docsExamined" : 101,
> "alreadyHasObj" : 0,
> "inputStage" : {
> "stage" : "OR",
> "nReturned" : 101,
> "executionTimeMillisEstimate" :
> 0,
> "works" : 101,
> "advanced" : 101,
> "needTime" : 0,
> "needYield" : 0,
> "saveState" : 3,
> "restoreState" : 3,
> "isEOF" : 0,
> "invalidates" : 0,
> "dupsTested" : 101,
> "dupsDropped" : 0,
> "recordIdsForgotten" : 0,
> "inputStages" : [
> {
> "stage" :
> "IXSCAN",
> "nReturned" :
> 101,
>
> "executionTimeMillisEstimate" : 0,
> "works" : 101,
> "advanced" :
> 101,
> "needTime" : 0,
> "needYield" : 0,
> "saveState" : 3,
> "restoreState"
> : 3,
> "isEOF" : 0,
> "invalidates" :
> 0,
> "keyPattern" : {
>
> "_sdType" : 1,
>
> "_sdMaxRevTime" : 1
> },
> "indexName" :
> "_sdType_1__sdMaxRevTime_1",
> "isMultiKey" :
> false,
> "multiKeyPaths"
> : {
>
> "_sdType" : [ ],
>
> "_sdMaxRevTime" : [ ]
> },
> "isUnique" :
> false,
> "isSparse" :
> true,
> "isPartial" :
> false,
> "indexVersion"
> : 2,
> "direction" :
> "forward",
> "indexBounds" :
> {
>
> "_sdType" : [
>
> "[50, 50]"
> ],
>
> "_sdMaxRevTime" : [
>
> "[-inf.0, 1551410180)"
> ]
> },
> "keysExamined"
> : 101,
> "seeks" : 1,
> "dupsTested" :
> 0,
> "dupsDropped" :
> 0,
>
> "seenInvalidated" : 0
> },
> {
> "stage" :
> "IXSCAN",
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
> "works" : 0,
> "advanced" : 0,
> "needTime" : 0,
> "needYield" : 0,
> "saveState" : 3,
> "restoreState"
> : 3,
> "isEOF" : 0,
> "invalidates" :
> 0,
> "keyPattern" : {
>
> "_sdType" : 1,
>
> "_sdMaxRevTime" : 1
> },
> "indexName" :
> "_sdType_1__sdMaxRevTime_1",
> "isMultiKey" :
> false,
> "multiKeyPaths"
> : {
>
> "_sdType" : [ ],
>
> "_sdMaxRevTime" : [ ]
> },
> "isUnique" :
> false,
> "isSparse" :
> true,
> "isPartial" :
> false,
> "indexVersion"
> : 2,
> "direction" :
> "forward",
> "indexBounds" :
> {
>
> "_sdType" : [
>
> "[60, 60]"
> ],
>
> "_sdMaxRevTime" : [
>
> "[-inf.0, 1551410180)"
> ]
> },
> "keysExamined"
> : 0,
> "seeks" : 0,
> "dupsTested" :
> 0,
> "dupsDropped" :
> 0,
>
> "seenInvalidated" : 0
> },
> {
> "stage" :
> "FETCH",
> "filter" : {
> "$and"
> : [
>
> {
>
> "_sdType" : {
>
> "$eq" : 70
>
> }
>
> },
>
> {
>
> "_sdMaxRevTime" : {
>
> "$lt" : NumberLong(1551496575)
>
> }
>
> }
> ]
> },
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
> "works" : 0,
> "advanced" : 0,
> "needTime" : 0,
> "needYield" : 0,
> "saveState" : 3,
> "restoreState"
> : 3,
> "isEOF" : 0,
> "invalidates" :
> 0,
> "docsExamined"
> : 0,
> "alreadyHasObj"
> : 0,
> "inputStage" : {
> "stage"
> : "OR",
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
> "works"
> : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
> "isEOF"
> : 0,
>
> "invalidates" : 0,
>
> "dupsTested" : 0,
>
> "dupsDropped" : 0,
>
> "recordIdsForgotten" : 0,
>
> "inputStages" : [
>
> {
>
> "stage" : "FETCH",
>
> "filter" : {
>
> "_path" : {
>
> "$regex" : ".*-1/0"
>
> }
>
> },
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
>
> "works" : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
>
> "isEOF" : 0,
>
> "invalidates" : 0,
>
> "docsExamined" : 0,
>
> "alreadyHasObj" : 0,
>
> "inputStage" : {
>
> "stage" : "IXSCAN",
>
> "filter" : {
>
> "_id" : {
>
> "$regex" : "[^-]*"
>
> }
>
> },
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
>
> "works" : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
>
> "isEOF" : 0,
>
> "invalidates" : 0,
>
> "keyPattern" : {
>
> "_id" : 1
>
> },
>
> "indexName" : "_id_",
>
> "isMultiKey" : false,
>
> "multiKeyPaths" : {
>
> "_id" : [ ]
>
> },
>
> "isUnique" : true,
>
> "isSparse" : false,
>
> "isPartial" : false,
>
> "indexVersion" : 2,
>
> "direction" : "forward",
>
> "indexBounds" : {
>
> "_id" : [
>
> "[\"\", {})",
>
> "[/[^-]*/, /[^-]*/]"
>
> ]
>
> },
>
> "keysExamined" : 0,
>
> "seeks" : 0,
>
> "dupsTested" : 0,
>
> "dupsDropped" : 0,
>
> "seenInvalidated" : 0
>
> }
>
> },
>
> {
>
> "stage" : "IXSCAN",
>
> "filter" : {
>
> "$or" : [
>
> {
>
> "_id" : {
>
> "$regex" : ".*-1/0"
>
> }
>
> }
>
> ]
>
> },
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
>
> "works" : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
>
> "isEOF" : 0,
>
> "invalidates" : 0,
>
> "keyPattern" : {
>
> "_id" : 1
>
> },
>
> "indexName" : "_id_",
>
> "isMultiKey" : false,
>
> "multiKeyPaths" : {
>
> "_id" : [ ]
>
> },
>
> "isUnique" : true,
>
> "isSparse" : false,
>
> "isPartial" : false,
>
> "indexVersion" : 2,
>
> "direction" : "forward",
>
> "indexBounds" : {
>
> "_id" : [
>
> "[\"\", {})",
>
> "[/.*-1/0/, /.*-1/0/]"
>
> ]
>
> },
>
> "keysExamined" : 0,
>
> "seeks" : 0,
>
> "dupsTested" : 0,
>
> "dupsDropped" : 0,
>
> "seenInvalidated" : 0
>
> }
> ]
> }
> },
> {
> "stage" :
> "FETCH",
> "filter" : {
> "$and"
> : [
>
> {
>
> "_sdType" : {
>
> "$eq" : 70
>
> }
>
> },
>
> {
>
> "_sdMaxRevTime" : {
>
> "$lt" : NumberLong(1550757370)
>
> }
>
> }
> ]
> },
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
> "works" : 0,
> "advanced" : 0,
> "needTime" : 0,
> "needYield" : 0,
> "saveState" : 3,
> "restoreState"
> : 3,
> "isEOF" : 0,
> "invalidates" :
> 0,
> "docsExamined"
> : 0,
> "alreadyHasObj"
> : 0,
> "inputStage" : {
> "stage"
> : "OR",
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
> "works"
> : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
> "isEOF"
> : 0,
>
> "invalidates" : 0,
>
> "dupsTested" : 0,
>
> "dupsDropped" : 0,
>
> "recordIdsForgotten" : 0,
>
> "inputStages" : [
>
> {
>
> "stage" : "FETCH",
>
> "filter" : {
>
> "_path" : {
>
> "$regex" : ".*-2/0"
>
> }
>
> },
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
>
> "works" : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
>
> "isEOF" : 0,
>
> "invalidates" : 0,
>
> "docsExamined" : 0,
>
> "alreadyHasObj" : 0,
>
> "inputStage" : {
>
> "stage" : "IXSCAN",
>
> "filter" : {
>
> "_id" : {
>
> "$regex" : "[^-]*"
>
> }
>
> },
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
>
> "works" : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
>
> "isEOF" : 0,
>
> "invalidates" : 0,
>
> "keyPattern" : {
>
> "_id" : 1
>
> },
>
> "indexName" : "_id_",
>
> "isMultiKey" : false,
>
> "multiKeyPaths" : {
>
> "_id" : [ ]
>
> },
>
> "isUnique" : true,
>
> "isSparse" : false,
>
> "isPartial" : false,
>
> "indexVersion" : 2,
>
> "direction" : "forward",
>
> "indexBounds" : {
>
> "_id" : [
>
> "[\"\", {})",
>
> "[/[^-]*/, /[^-]*/]"
>
> ]
>
> },
>
> "keysExamined" : 0,
>
> "seeks" : 0,
>
> "dupsTested" : 0,
>
> "dupsDropped" : 0,
>
> "seenInvalidated" : 0
>
> }
>
> },
>
> {
>
> "stage" : "IXSCAN",
>
> "filter" : {
>
> "$or" : [
>
> {
>
> "_id" : {
>
> "$regex" : ".*-2/0"
>
> }
>
> }
>
> ]
>
> },
>
> "nReturned" : 0,
>
> "executionTimeMillisEstimate" : 0,
>
> "works" : 0,
>
> "advanced" : 0,
>
> "needTime" : 0,
>
> "needYield" : 0,
>
> "saveState" : 3,
>
> "restoreState" : 3,
>
> "isEOF" : 0,
>
> "invalidates" : 0,
>
> "keyPattern" : {
>
> "_id" : 1
>
> },
>
> "indexName" : "_id_",
>
> "isMultiKey" : false,
>
> "multiKeyPaths" : {
>
> "_id" : [ ]
>
> },
>
> "isUnique" : true,
>
> "isSparse" : false,
>
> "isPartial" : false,
>
> "indexVersion" : 2,
>
> "direction" : "forward",
>
> "indexBounds" : {
>
> "_id" : [
>
> "[\"\", {})",
>
> "[/.*-2/0/, /.*-2/0/]"
>
> ]
>
> },
>
> "keysExamined" : 0,
>
> "seeks" : 0,
>
> "dupsTested" : 0,
>
> "dupsDropped" : 0,
>
> "seenInvalidated" : 0
>
> }
> ]
> }
> }
> ]
> }
> }
> },
> "feedback" : {
> "nfeedback" : 18,
> "scores" : [
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> },
> {
> "score" : 2.0003
> }
> ]
> },
> "filterSet" : false
> }
> {noformat}
> Note that this was primarily caused by
> [SERVER-20616|https://jira.mongodb.org/browse/SERVER-20616] and that
> [SERVER-42090|https://jira.mongodb.org/browse/SERVER-42090] and
> [SERVER-24396|https://jira.mongodb.org/browse/SERVER-24396] would also have
> been helpful preventing this.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
