Uploaded image for project: 'Jackrabbit Oak'
  1. Jackrabbit Oak
  2. OAK-8351

Long running RGC remove and getmore operations

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 1.12.0
    • Fix Version/s: 1.10.3, 1.16.0, 1.8.15
    • Component/s: mongomk
    • Labels:
      None

      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:

      					{
      						"_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)
      						}
      				}
      

      The problematic plan was:

      	{
      			"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
      		}
      

      Note that this was primarily caused by SERVER-20616 and that SERVER-42090 and SERVER-24396 would also have been helpful preventing this.

        Attachments

        1. OAK-8351-merged-1.8.patch
          9 kB
          Stefan Egli
        2. OAK-8351-1.8.patch
          23 kB
          Stefan Egli
        3. OAK-8351-1.10.patch
          25 kB
          Stefan Egli
        4. OAK-8351.patch
          25 kB
          Stefan Egli

          Activity

            People

            • Assignee:
              stefanegli Stefan Egli
              Reporter:
              stefanegli Stefan Egli
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: