[SERVER-17260] Wrong index is often chosen for query: { "foo": "fooValue", "_id": { "$gte": "idValue" } }, sort: { "_id": 1 } Created: 11/Feb/15  Updated: 02/Mar/15  Resolved: 24/Feb/15

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

Type: Bug Priority: Major - P3
Reporter: Matt Hurne Assignee: David Storch
Resolution: Duplicate Votes: 3
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-15225 CachedPlanStage should execute for tr... Closed
Related
is related to SERVER-14071 For queries with .sort(), bad non-blo... Closed
Operating System: ALL
Participants:

 Comments   
Comment by Matt Hurne [ 02/Mar/15 ]

Thanks for the info, Dave!

Comment by David Storch [ 02/Mar/15 ]

Hi mhurne,

Sounds like this is unlikely to be fixed until 3.1?

Work for SERVER-15225 is ongoing. Once it is complete, we will evaluate whether or not it could be backported for a 3.0.x patch release. Unfortunately, I cannot promise that a fix will be available in 3.0.x, but please watch SERVER-15225 for future updates.

Any chance it was fixed in 2.6.8 under SERVER-15802, or is it definitely unrelated to that?

This was not fixed under SERVER-15802. That ticket only offers a fix for queries with equality predicates over a unique index. In this case there is a range predicate ($gte) over a unique index ({_id: 1}), so the fix does not apply.

Best,
Dave

Comment by Matt Hurne [ 02/Mar/15 ]

Thanks, Dave. Sounds like this is unlikely to be fixed until 3.1? Any chance it was fixed in 2.6.8 under SERVER-15802, or is it definitely unrelated to that?

Comment by David Storch [ 24/Feb/15 ]

Hi mhurne,

Thanks very much for the additional info, and apologies for the delay in my response.

After reviewing the plan cache output, I have determined that this is not in fact a duplicate of SERVER-14071. The output shows that for this query, the {_id: 1} and {groupKey: 1, _id: 1} indices are in fact equally good. Both scan a continuous range of about 25 index keys, fetching and returning the document associated with each key. In both cases, the nscannedObjects/nscanned ratio is a perfect 1.0.

In the case that two or more plans appear to be equally efficient (that is, in the case of a tie), the query system will not create a plan cache entry. In such cases, the optimizer does not have enough information to be confident that one plan is better than another in general. However, as you noticed, the plans did not tie: {_id: 1} got a slightly higher score of ~1.7 whereas {groupKey: 1, _id: 1} got a slightly lower score of ~1.6. The reason is that the {groupKey: 1, _id: 1} triggered an additional page fault compared to {_id: 1}. The system's guess at the number of page faults is tracked in the plan cache stats as the field needFetch. You can see that the needFetch number is 6 for {groupKey: 1, _id: 1} but only 5 for {_id: 1}. Plans are penalized during scoring if they trigger page faults as these plans require potentially expensive IO operations, which is why the plan with fewer faults wins in this case.

Under the current design of MongoDB's query engine, it is possible for a plan drawn from the plan cache to be far from optimal. The fact that this is possible is expected behavior of the system. You have encountered one among several underlying causes for the creation of a plan cache entry that will be suboptimal on subsequent executions of the query shape. We are working on much more aggressively limiting the impact of suboptimal plan cache entries under SERVER-15225. I am closing this ticket as a duplicate of SERVER-15225, as that ticket is where the relevant work items are being completed.

Best,
Dave

Comment by Matt Hurne [ 19/Feb/15 ]

So, looks like the index I'd expect to be used ({ groupKey: 1, _id: 1 }) gets a score of 1.6759756756756756, while another index ({ _id: 1 }) gets a higher score of 1.7225222222222223.

Comment by Matt Hurne [ 19/Feb/15 ]

Here you go:

db.ProductData.getPlanCache().listQueryShapes()
[
  {
    "query": {
      "groupKey": "518dde6bc519cc16e935b45a_51247477c519e3a71e639634",
      "_id": {
        "$gte": ObjectId("53224575e4b08cd8f178b154")
      }
    },
    "sort": {
      "_id": 1
    },
    "projection": {
 
    }
  },
  {
    "query": {
      "groupKey": "518dde6bc519cc16e935b45a_51247477c519e3a71e639634"
    },
    "sort": {
      "_id": 1
    },
    "projection": {
 
    }
  },
  {
    "query": {
      "jobIds": ObjectId("54e65357e4b03847b679c7f2")
    },
    "sort": {
      "_id": 1
    },
    "projection": {
 
    }
  },
  {
    "query": {
      "groupKey": "4eaff5bcc5191a6af89d7ab7_4f7dbb95c519b28ce23ffc54",
      "key": "410066"
    },
    "sort": {
 
    },
    "projection": {
 
    }
  },
  {
    "query": {
      "groupKey": "4eaff5bcc5191a6af89d7ab7_4f7dbb95c519b28ce23ffc54",
      "specId": ObjectId("54aeec43e4b0b6278ea04413"),
      "_id": {
        "$gte": ObjectId("54cfecfde4b02c33361d5002")
      }
    },
    "sort": {
      "_id": 1
    },
    "projection": {
 
    }
  },
  {
    "query": {
      "groupKey": "4eaff5bcc5191a6af89d7ab7_4f7dbb95c519b28ce23ffc54",
      "specId": ObjectId("54aeec43e4b0b6278ea04413"),
      "_id": {
        "$gte": ObjectId("54cfecfce4b02c33361d4fd0")
      }
    },
    "sort": {
 
    },
    "projection": {
 
    }
  },
  {
    "query": {
      "groupKey": "4eaff5bcc5191a6af89d7ab7_4f7dbb95c519b28ce23ffc54",
      "specId": ObjectId("54aeec43e4b0b6278ea04413")
    },
    "sort": {
      "_id": 1
    },
    "projection": {
 
    }
  }
]

db.ProductData.getPlanCache().getPlansByQuery({ groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", "_id": { $gte: ObjectId("53224505e4b055a5d8ac41fb") } }, {}, { "_id": 1 })
[
  {
    "details": {
      "solution": "(index-tagged expression tree: tree=Node\n---Leaf \n---Leaf { _id: 1 }, pos: 0\n)"
    },
    "reason": {
      "score": 1.7225222222222223,
      "stats": {
        "type": "FETCH",
        "works": 31,
        "yields": 17,
        "unyields": 17,
        "invalidates": 0,
        "advanced": 26,
        "needTime": 0,
        "needFetch": 5,
        "isEOF": 0,
        "alreadyHasObj": 0,
        "forcedFetches": 0,
        "matchTested": 26,
        "children": [
          {
            "type": "IXSCAN",
            "works": 26,
            "yields": 17,
            "unyields": 17,
            "invalidates": 0,
            "advanced": 26,
            "needTime": 0,
            "needFetch": 0,
            "isEOF": 0,
            "keyPattern": "{ _id: 1 }",
            "isMultiKey": 0,
            "boundsVerbose": "field #0['_id']: [ObjectId('53224575e4b08cd8f178b154'), ObjectId('ffffffffffffffffffffffff')]",
            "yieldMovedCursor": 0,
            "dupsTested": 0,
            "dupsDropped": 0,
            "seenInvalidated": 0,
            "matchTested": 0,
            "keysExamined": 26,
            "children": [ ]
          }
        ]
      }
    },
    "feedback": {
      "nfeedback": 0,
      "averageScore": 0,
      "stdDevScore": 0,
      "scores": [ ]
    },
    "filterSet": false
  },
  {
    "details": {
      "solution": "(index-tagged expression tree: tree=Node\n---Leaf { groupKey: 1, _id: 1 }, pos: 0\n---Leaf { groupKey: 1, _id: 1 }, pos: 1\n)"
    },
    "reason": {
      "score": 1.6759756756756756,
      "stats": {
        "type": "FETCH",
        "works": 31,
        "yields": 17,
        "unyields": 17,
        "invalidates": 0,
        "advanced": 25,
        "needTime": 0,
        "needFetch": 6,
        "isEOF": 0,
        "alreadyHasObj": 0,
        "forcedFetches": 0,
        "matchTested": 0,
        "children": [
          {
            "type": "IXSCAN",
            "works": 25,
            "yields": 17,
            "unyields": 17,
            "invalidates": 0,
            "advanced": 25,
            "needTime": 0,
            "needFetch": 0,
            "isEOF": 0,
            "keyPattern": "{ groupKey: 1, _id: 1 }",
            "isMultiKey": 0,
            "boundsVerbose": "field #0['groupKey']: [\"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\", \"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\"], field #1['_id']: [ObjectId('53224575e4b08cd8f178b154'), ObjectId('ffffffffffffffffffffffff')]",
            "yieldMovedCursor": 0,
            "dupsTested": 0,
            "dupsDropped": 0,
            "seenInvalidated": 0,
            "matchTested": 0,
            "keysExamined": 25,
            "children": [ ]
          }
        ]
      }
    },
    "feedback": {
 
    },
    "filterSet": false
  },
  {
    "details": {
      "solution": "(index-tagged expression tree: tree=Node\n---Leaf { groupKey: 1, uniquenessKeys: 1 }, pos: 0\n---Leaf \n)"
    },
    "reason": {
      "score": 1.0002,
      "stats": {
        "type": "KEEP_MUTATIONS",
        "works": 31,
        "yields": 17,
        "unyields": 17,
        "invalidates": 0,
        "advanced": 0,
        "needTime": 31,
        "needFetch": 0,
        "isEOF": 0,
        "children": [
          {
            "type": "OR",
            "works": 31,
            "yields": 17,
            "unyields": 17,
            "invalidates": 0,
            "advanced": 0,
            "needTime": 31,
            "needFetch": 0,
            "isEOF": 0,
            "dupsTested": 0,
            "dupsDropped": 0,
            "locsForgotten": 0,
            "matchTested_0": 0,
            "matchTested_1": 0,
            "children": [
              {
                "type": "SORT",
                "works": 31,
                "yields": 17,
                "unyields": 17,
                "invalidates": 0,
                "advanced": 0,
                "needTime": 30,
                "needFetch": 0,
                "isEOF": 0,
                "forcedFetches": 0,
                "memUsage": 8190,
                "memLimit": 33554432,
                "children": [
                  {
                    "type": "FETCH",
                    "works": 30,
                    "yields": 17,
                    "unyields": 17,
                    "invalidates": 0,
                    "advanced": 1,
                    "needTime": 29,
                    "needFetch": 0,
                    "isEOF": 0,
                    "alreadyHasObj": 0,
                    "forcedFetches": 0,
                    "matchTested": 1,
                    "children": [
                      {
                        "type": "IXSCAN",
                        "works": 30,
                        "yields": 17,
                        "unyields": 17,
                        "invalidates": 0,
                        "advanced": 30,
                        "needTime": 0,
                        "needFetch": 0,
                        "isEOF": 0,
                        "keyPattern": "{ groupKey: 1, uniquenessKeys: 1 }",
                        "isMultiKey": 0,
                        "boundsVerbose": "field #0['groupKey']: [\"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\", \"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\"], field #1['uniquenessKeys']: [MinKey, MaxKey]",
                        "yieldMovedCursor": 0,
                        "dupsTested": 0,
                        "dupsDropped": 0,
                        "seenInvalidated": 0,
                        "matchTested": 0,
                        "keysExamined": 30,
                        "children": [ ]
                      }
                    ]
                  }
                ]
              },
              {
                "type": "SORT",
                "works": 0,
                "yields": 17,
                "unyields": 17,
                "invalidates": 0,
                "advanced": 0,
                "needTime": 0,
                "needFetch": 0,
                "isEOF": 0,
                "forcedFetches": 0,
                "memUsage": 0,
                "memLimit": 33554432,
                "children": [
                  {
                    "type": "FETCH",
                    "works": 0,
                    "yields": 17,
                    "unyields": 17,
                    "invalidates": 0,
                    "advanced": 0,
                    "needTime": 0,
                    "needFetch": 0,
                    "isEOF": 0,
                    "alreadyHasObj": 0,
                    "forcedFetches": 0,
                    "matchTested": 0,
                    "children": [
                      {
                        "type": "IXSCAN",
                        "works": 0,
                        "yields": 17,
                        "unyields": 17,
                        "invalidates": 0,
                        "advanced": 0,
                        "needTime": 0,
                        "needFetch": 0,
                        "isEOF": 0,
                        "keyPattern": "{ groupKey: 1, uniquenessKeys: 1 }",
                        "isMultiKey": 0,
                        "boundsVerbose": "field #0['groupKey']: [\"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\", \"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\"], field #1['uniquenessKeys']: [MinKey, MaxKey]",
                        "yieldMovedCursor": 0,
                        "dupsTested": 0,
                        "dupsDropped": 0,
                        "seenInvalidated": 0,
                        "matchTested": 0,
                        "keysExamined": 0,
                        "children": [ ]
                      }
                    ]
                  }
                ]
              }
            ]
          }
        ]
      }
    },
    "feedback": {
 
    },
    "filterSet": false
  },
  {
    "details": {
      "solution": "(index-tagged expression tree: tree=Node\n---Leaf { groupKey: 1, key: 1 }, pos: 0\n---Leaf \n)"
    },
    "reason": {
      "score": 1.0002,
      "stats": {
        "type": "KEEP_MUTATIONS",
        "works": 31,
        "yields": 17,
        "unyields": 17,
        "invalidates": 0,
        "advanced": 0,
        "needTime": 28,
        "needFetch": 3,
        "isEOF": 0,
        "children": [
          {
            "type": "OR",
            "works": 31,
            "yields": 17,
            "unyields": 17,
            "invalidates": 0,
            "advanced": 0,
            "needTime": 28,
            "needFetch": 3,
            "isEOF": 0,
            "dupsTested": 0,
            "dupsDropped": 0,
            "locsForgotten": 0,
            "matchTested_0": 0,
            "matchTested_1": 0,
            "children": [
              {
                "type": "SORT",
                "works": 31,
                "yields": 17,
                "unyields": 17,
                "invalidates": 0,
                "advanced": 0,
                "needTime": 27,
                "needFetch": 3,
                "isEOF": 0,
                "forcedFetches": 0,
                "memUsage": 225830,
                "memLimit": 33554432,
                "children": [
                  {
                    "type": "FETCH",
                    "works": 30,
                    "yields": 17,
                    "unyields": 17,
                    "invalidates": 0,
                    "advanced": 26,
                    "needTime": 1,
                    "needFetch": 3,
                    "isEOF": 0,
                    "alreadyHasObj": 0,
                    "forcedFetches": 0,
                    "matchTested": 26,
                    "children": [
                      {
                        "type": "IXSCAN",
                        "works": 27,
                        "yields": 17,
                        "unyields": 17,
                        "invalidates": 0,
                        "advanced": 27,
                        "needTime": 0,
                        "needFetch": 0,
                        "isEOF": 0,
                        "keyPattern": "{ groupKey: 1, key: 1 }",
                        "isMultiKey": 0,
                        "boundsVerbose": "field #0['groupKey']: [\"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\", \"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\"], field #1['key']: [MinKey, MaxKey]",
                        "yieldMovedCursor": 0,
                        "dupsTested": 0,
                        "dupsDropped": 0,
                        "seenInvalidated": 0,
                        "matchTested": 0,
                        "keysExamined": 27,
                        "children": [ ]
                      }
                    ]
                  }
                ]
              },
              {
                "type": "SORT",
                "works": 0,
                "yields": 17,
                "unyields": 17,
                "invalidates": 0,
                "advanced": 0,
                "needTime": 0,
                "needFetch": 0,
                "isEOF": 0,
                "forcedFetches": 0,
                "memUsage": 0,
                "memLimit": 33554432,
                "children": [
                  {
                    "type": "FETCH",
                    "works": 0,
                    "yields": 17,
                    "unyields": 17,
                    "invalidates": 0,
                    "advanced": 0,
                    "needTime": 0,
                    "needFetch": 0,
                    "isEOF": 0,
                    "alreadyHasObj": 0,
                    "forcedFetches": 0,
                    "matchTested": 0,
                    "children": [
                      {
                        "type": "IXSCAN",
                        "works": 0,
                        "yields": 17,
                        "unyields": 17,
                        "invalidates": 0,
                        "advanced": 0,
                        "needTime": 0,
                        "needFetch": 0,
                        "isEOF": 0,
                        "keyPattern": "{ groupKey: 1, key: 1 }",
                        "isMultiKey": 0,
                        "boundsVerbose": "field #0['groupKey']: [\"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\", \"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\"], field #1['key']: [MinKey, MaxKey]",
                        "yieldMovedCursor": 0,
                        "dupsTested": 0,
                        "dupsDropped": 0,
                        "seenInvalidated": 0,
                        "matchTested": 0,
                        "keysExamined": 0,
                        "children": [ ]
                      }
                    ]
                  }
                ]
              }
            ]
          }
        ]
      }
    },
    "feedback": {
 
    },
    "filterSet": false
  },
  {
    "details": {
      "solution": "(index-tagged expression tree: tree=Node\n---Leaf { groupKey: 1.0, updated: 1.0 }, pos: 0\n---Leaf \n)"
    },
    "reason": {
      "score": 1.0002,
      "stats": {
        "type": "KEEP_MUTATIONS",
        "works": 31,
        "yields": 17,
        "unyields": 17,
        "invalidates": 0,
        "advanced": 0,
        "needTime": 28,
        "needFetch": 3,
        "isEOF": 0,
        "children": [
          {
            "type": "OR",
            "works": 31,
            "yields": 17,
            "unyields": 17,
            "invalidates": 0,
            "advanced": 0,
            "needTime": 28,
            "needFetch": 3,
            "isEOF": 0,
            "dupsTested": 0,
            "dupsDropped": 0,
            "locsForgotten": 0,
            "matchTested_0": 0,
            "matchTested_1": 0,
            "children": [
              {
                "type": "SORT",
                "works": 31,
                "yields": 17,
                "unyields": 17,
                "invalidates": 0,
                "advanced": 0,
                "needTime": 27,
                "needFetch": 3,
                "isEOF": 0,
                "forcedFetches": 0,
                "memUsage": 248340,
                "memLimit": 33554432,
                "children": [
                  {
                    "type": "FETCH",
                    "works": 30,
                    "yields": 17,
                    "unyields": 17,
                    "invalidates": 0,
                    "advanced": 27,
                    "needTime": 0,
                    "needFetch": 3,
                    "isEOF": 0,
                    "alreadyHasObj": 0,
                    "forcedFetches": 0,
                    "matchTested": 27,
                    "children": [
                      {
                        "type": "IXSCAN",
                        "works": 27,
                        "yields": 17,
                        "unyields": 17,
                        "invalidates": 0,
                        "advanced": 27,
                        "needTime": 0,
                        "needFetch": 0,
                        "isEOF": 0,
                        "keyPattern": "{ groupKey: 1.0, updated: 1.0 }",
                        "isMultiKey": 0,
                        "boundsVerbose": "field #0['groupKey']: [\"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\", \"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\"], field #1['updated']: [MinKey, MaxKey]",
                        "yieldMovedCursor": 0,
                        "dupsTested": 0,
                        "dupsDropped": 0,
                        "seenInvalidated": 0,
                        "matchTested": 0,
                        "keysExamined": 27,
                        "children": [ ]
                      }
                    ]
                  }
                ]
              },
              {
                "type": "SORT",
                "works": 0,
                "yields": 17,
                "unyields": 17,
                "invalidates": 0,
                "advanced": 0,
                "needTime": 0,
                "needFetch": 0,
                "isEOF": 0,
                "forcedFetches": 0,
                "memUsage": 0,
                "memLimit": 33554432,
                "children": [
                  {
                    "type": "FETCH",
                    "works": 0,
                    "yields": 17,
                    "unyields": 17,
                    "invalidates": 0,
                    "advanced": 0,
                    "needTime": 0,
                    "needFetch": 0,
                    "isEOF": 0,
                    "alreadyHasObj": 0,
                    "forcedFetches": 0,
                    "matchTested": 0,
                    "children": [
                      {
                        "type": "IXSCAN",
                        "works": 0,
                        "yields": 17,
                        "unyields": 17,
                        "invalidates": 0,
                        "advanced": 0,
                        "needTime": 0,
                        "needFetch": 0,
                        "isEOF": 0,
                        "keyPattern": "{ groupKey: 1.0, updated: 1.0 }",
                        "isMultiKey": 0,
                        "boundsVerbose": "field #0['groupKey']: [\"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\", \"518dde6bc519cc16e935b45a_51247477c519e3a71e639634\"], field #1['updated']: [MinKey, MaxKey]",
                        "yieldMovedCursor": 0,
                        "dupsTested": 0,
                        "dupsDropped": 0,
                        "seenInvalidated": 0,
                        "matchTested": 0,
                        "keysExamined": 0,
                        "children": [ ]
                      }
                    ]
                  }
                ]
              }
            ]
          }
        ]
      }
    },
    "feedback": {
 
    },
    "filterSet": false
  }
]

Comment by David Storch [ 17/Feb/15 ]

mhurne, got it, thanks. I'm going to move this ticket back into Waiting for User state. Feel free to add any additional info here whenever it is available.

Comment by Matt Hurne [ 17/Feb/15 ]

david.storch: Makes sense - I'll see what I can do! We have a workaround for this in production (a query hint), so I'll have to try to reproduce it in another environment.

Comment by David Storch [ 17/Feb/15 ]

mhurne, the best thing would be the output of getPlansByQuery at a time when the wrong index is being used for the query. If you experience this problem again, could you please provide the output from running the following on the offending node?

db.ProductData.getPlanCache().listQueryShapes()
db.ProductData.getPlanCache().getPlansByQuery({ groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", "_id": { $gte: ObjectId("53224505e4b055a5d8ac41fb") } }, {}, { "_id": 1 })

I see that you ran these commands before, but it looks like this was done at a time that there was no entry in the plan cache for this particular query shape. We need to capture the output at a time when the bad plan has been cached.

Thanks,
Dave

Comment by Matt Hurne [ 15/Feb/15 ]

david.storch: Is there anything I can do to help?

Comment by David Storch [ 13/Feb/15 ]

Possibly a duplicate of SERVER-14071. Waiting on capturing plan cache output in order to verify.

Comment by Matt Hurne [ 13/Feb/15 ]

Great, thanks ramon.fernandez!

Comment by Ramon Fernandez Marina [ 13/Feb/15 ]

Thanks for the report and the detailed information mhurne, we're currently investigating and will let you know if we need any additional data.

Comment by Larry Zarou [ 11/Feb/15 ]

+1

Comment by Matt Hurne [ 11/Feb/15 ]

Please feel free to let me know if there's any additional information I can provide.

Comment by Matt Hurne [ 11/Feb/15 ]

Mongo 2.6.7 seems to often choose the wrong index for a query of the form

{ "foo": "fooValue", "_id": { "$gte": "idValue" } }

with sort:

{ "_id": 1 }

We typically apply a limit of around 25 as well. Not sure that is relevant.

When Mongo chooses the wrong index, the query takes significantly longer to execute than when the correct index is chosen. Sometimes Mongo chooses the correct index on its own; in other cases while troubleshooting this issue, we have forced it to use the correct index with hint().

Here's what we see in mongodb.log when Mongo decides to use the wrong index:

2015-02-10T17:30:02.222-0500 [conn30278] query klerk.ProductData query: { $query: { groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", _id: { $gte: ObjectId('53224505e4b055a5d8ac41fb') } }, $orderby: { _id: 1 } } planSummary: IXSCAN { _id: 1 } ntoreturn:26 ntoskip:0 nscanned:1213701 nscannedObjects:1213701 keyUpdates:0 numYields:899175 locks(micros) r:68739007 nreturned:9 reslen:55587 901318ms

Per instructions in a comment on SERVER-15802:

1. Increased log level:

        set1:PRIMARY> db.adminCommand( { setParameter: 1, logLevel: 2 } )
        { "was" : 0, "ok" : 1 }

2. List of indexes in the collection:

        set1:PRIMARY> db.ProductData.getIndexes()
        [
            {
                "v" : 1,
                "name" : "_id_",
                "key" : {
                    "_id" : 1
                },
                "ns" : "klerk.ProductData"
            },
            {
                "v" : 1,
                "name" : "groupKey_1_uniquenessKeys_1",
                "key" : {
                    "groupKey" : 1,
                    "uniquenessKeys" : 1
                },
                "ns" : "klerk.ProductData",
                "background" : true
            },
            {
                "v" : 1,
                "name" : "groupKey_1_key_1",
                "key" : {
                    "groupKey" : 1,
                    "key" : 1
                },
                "ns" : "klerk.ProductData",
                "background" : true
            },
            {
                "v" : 1,
                "name" : "jobIds_1",
                "key" : {
                    "jobIds" : 1
                },
                "ns" : "klerk.ProductData",
                "background" : true
            },
            {
                "v" : 1,
                "name" : "groupKey_1__id_1",
                "key" : {
                    "groupKey" : 1,
                    "_id" : 1
                },
                "ns" : "klerk.ProductData",
                "background" : true
            },
            {
                "v" : 1,
                "name" : "groupKey_1_updated_1",
                "key" : {
                    "groupKey" : 1,
                    "updated" : 1
                },
                "ns" : "klerk.ProductData",
                "background" : true
            }
        ]

3. Query shapes from the plan cache:

        set1:PRIMARY> db.ProductData.getPlanCache().listQueryShapes()
        [
            {
                "query" : {
                    "groupKey" : "53196e7cc51930a52d3ef36b_51247477c519e3a71e639634",
                    "key" : "DB-MXL190301"
                },
                "sort" : {
        
                },
                "projection" : {
        
                }
            }
        ]

4. getPlansByQuery on the offending query:

        set1:PRIMARY> db.ProductData.getPlanCache().getPlansByQuery({ groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", "_id": { $gte: ObjectId("53224505e4b055a5d8ac41fb") } }, {}, { "_id": 1 })
        [ ]

5. Query with explain(true):

        set1:PRIMARY> db.ProductData.find({ groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", "_id": { $gte: ObjectId("53224505e4b055a5d8ac41fb") } }).sort({ "_id": 1 }).explain(true)
        {
            "cursor" : "BtreeCursor groupKey_1__id_1",
            "isMultiKey" : false,
            "n" : 9,
            "nscannedObjects" : 9,
            "nscanned" : 9,
            "nscannedObjectsAllPlans" : 46,
            "nscannedAllPlans" : 46,
            "scanAndOrder" : false,
            "indexOnly" : false,
            "nYields" : 33,
            "nChunkSkips" : 0,
            "millis" : 472,
            "indexBounds" : {
                "groupKey" : [
                    [
                        "4e20d04bec33075d8671fbec_51247477c519e3a71e639634",
                        "4e20d04bec33075d8671fbec_51247477c519e3a71e639634"
                    ]
                ],
                "_id" : [
                    [
                        ObjectId("53224505e4b055a5d8ac41fb"),
                        ObjectId("ffffffffffffffffffffffff")
                    ]
                ]
            },
            "allPlans" : [
                {
                    "cursor" : "BtreeCursor groupKey_1__id_1",
                    "isMultiKey" : false,
                    "n" : 9,
                    "nscannedObjects" : 9,
                    "nscanned" : 9,
                    "scanAndOrder" : false,
                    "indexOnly" : false,
                    "nChunkSkips" : 0,
                    "indexBounds" : {
                        "groupKey" : [
                            [
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634",
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634"
                            ]
                        ],
                        "_id" : [
                            [
                                ObjectId("53224505e4b055a5d8ac41fb"),
                                ObjectId("ffffffffffffffffffffffff")
                            ]
                        ]
                    }
                },
                {
                    "cursor" : "BtreeCursor _id_",
                    "isMultiKey" : false,
                    "n" : 1,
                    "nscannedObjects" : 11,
                    "nscanned" : 11,
                    "scanAndOrder" : false,
                    "indexOnly" : false,
                    "nChunkSkips" : 0,
                    "indexBounds" : {
                        "_id" : [
                            [
                                ObjectId("53224505e4b055a5d8ac41fb"),
                                ObjectId("ffffffffffffffffffffffff")
                            ]
                        ]
                    }
                },
                {
                    "cursor" : "BtreeCursor groupKey_1_uniquenessKeys_1",
                    "isMultiKey" : false,
                    "n" : 0,
                    "nscannedObjects" : 10,
                    "nscanned" : 10,
                    "scanAndOrder" : true,
                    "indexOnly" : false,
                    "nChunkSkips" : 0,
                    "indexBounds" : {
                        "groupKey" : [
                            [
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634",
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634"
                            ]
                        ],
                        "uniquenessKeys" : [
                            [
                                {
                                    "$minElement" : 1
                                },
                                {
                                    "$maxElement" : 1
                                }
                            ]
                        ]
                    }
                },
                {
                    "cursor" : "BtreeCursor groupKey_1_key_1",
                    "isMultiKey" : false,
                    "n" : 0,
                    "nscannedObjects" : 8,
                    "nscanned" : 8,
                    "scanAndOrder" : true,
                    "indexOnly" : false,
                    "nChunkSkips" : 0,
                    "indexBounds" : {
                        "groupKey" : [
                            [
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634",
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634"
                            ]
                        ],
                        "key" : [
                            [
                                {
                                    "$minElement" : 1
                                },
                                {
                                    "$maxElement" : 1
                                }
                            ]
                        ]
                    }
                },
                {
                    "cursor" : "BtreeCursor groupKey_1_updated_1",
                    "isMultiKey" : false,
                    "n" : 0,
                    "nscannedObjects" : 8,
                    "nscanned" : 8,
                    "scanAndOrder" : true,
                    "indexOnly" : false,
                    "nChunkSkips" : 0,
                    "indexBounds" : {
                        "groupKey" : [
                            [
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634",
                                "4e20d04bec33075d8671fbec_51247477c519e3a71e639634"
                            ]
                        ],
                        "updated" : [
                            [
                                {
                                    "$minElement" : 1
                                },
                                {
                                    "$maxElement" : 1
                                }
                            ]
                        ]
                    }
                }
            ],
            "server" : "mdb02:27017",
            "filterSet" : false,
            "stats" : {
                "type" : "FETCH",
                "works" : 17,
                "yields" : 33,
                "unyields" : 33,
                "invalidates" : 0,
                "advanced" : 9,
                "needTime" : 0,
                "needFetch" : 6,
                "isEOF" : 1,
                "alreadyHasObj" : 0,
                "forcedFetches" : 0,
                "matchTested" : 0,
                "children" : [
                    {
                        "type" : "IXSCAN",
                        "works" : 10,
                        "yields" : 33,
                        "unyields" : 33,
                        "invalidates" : 0,
                        "advanced" : 9,
                        "needTime" : 0,
                        "needFetch" : 0,
                        "isEOF" : 1,
                        "keyPattern" : "{ groupKey: 1, _id: 1 }",
                        "isMultiKey" : 0,
                        "boundsVerbose" : "field #0['groupKey']: [\"4e20d04bec33075d8671fbec_51247477c519e3a71e639634\", \"4e20d04bec33075d8671fbec_51247477c519e3a71e639634\"], field #1['_id']: [ObjectId('53224505e4b055a5d8ac41fb'),         ObjectId('ffffffffffffffffffffffff')]",
                        "yieldMovedCursor" : 0,
                        "dupsTested" : 0,
                        "dupsDropped" : 0,
                        "seenInvalidated" : 0,
                        "matchTested" : 0,
                        "keysExamined" : 9,
                        "children" : [ ]
                    }
                ]
            }
        }

6. Re-set the log level to the previous value:

        set1:PRIMARY> db.adminCommand( { setParameter: 1, logLevel: 0 } )
        { "was" : 2, "ok" : 1 }

Relevant output from mongodb.log:

        2015-02-11T12:29:31.089-0500 [conn54874] run command klerk.$cmd { planCacheListPlans: "ProductData", query: { groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634",         _id: { $gte: ObjectId('53224505e4b055a5d8ac41fb') } }, projection: {}, sort: { _id: 1.0 } }
        2015-02-11T12:29:31.089-0500 [conn54874] command klerk.$cmd command: planCacheListPlans { planCacheListPlans: "ProductData", query: { groupKey:         "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", _id: { $gte: ObjectId('53224505e4b055a5d8ac41fb') } }, projection: {}, sort: { _id: 1.0 } } keyUpdates:0 numYields:0 locks(        micros) r:36 reslen:49 0ms
        
        ...
        
        2015-02-11T12:29:37.781-0500 [conn54874] Running query: query: { groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", _id: { $gte:         ObjectId('53224505e4b055a5d8ac41fb') } } sort: { _id: 1.0 } projection: {} skip: 0 limit: 0
        2015-02-11T12:29:37.781-0500 [conn32535] Only one plan is available; it will be run but will not be cached. query: {} sort: {} projection: {} skip: 0 limit: 0, planSummary:         COLLSCAN
        2015-02-11T12:29:37.781-0500 [conn54874] Relevant index 0 is kp: { _id: 1 } io: { v: 1, name: "_id_", key: { _id: 1 }, ns: "klerk.ProductData" }
        2015-02-11T12:29:37.781-0500 [conn54874] Relevant index 1 is kp: { groupKey: 1, uniquenessKeys: 1 } io: { v: 1, name: "groupKey_1_uniquenessKeys_1", key: { groupKey: 1,         uniquenessKeys: 1 }, ns: "klerk.ProductData", background: true }
        2015-02-11T12:29:37.781-0500 [conn54874] Relevant index 2 is kp: { groupKey: 1, key: 1 } io: { v: 1, name: "groupKey_1_key_1", key: { groupKey: 1, key: 1 }, ns: "klerk.        ProductData", background: true }
        2015-02-11T12:29:37.781-0500 [conn54874] Relevant index 3 is kp: { groupKey: 1, _id: 1 } io: { v: 1, name: "groupKey_1__id_1", key: { groupKey: 1, _id: 1 }, ns: "klerk.        ProductData", background: true }
        2015-02-11T12:29:37.781-0500 [conn54874] Relevant index 4 is kp: { groupKey: 1.0, updated: 1.0 } io: { v: 1, name: "groupKey_1_updated_1", key: { groupKey: 1.0, updated: 1.0         }, ns: "klerk.ProductData", background: true }
        2015-02-11T12:29:37.797-0500 [conn54874] Relevant index 0 is kp: { _id: 1.0 } multikey
        2015-02-11T12:29:37.797-0500 [conn54874] Relevant index 0 is kp: { _id: 1.0 } multikey
        2015-02-11T12:29:37.797-0500 [slaveTracking] Relevant index 0 is kp: { _id: 1 } io: { v: 1, name: "_id_", key: { _id: 1 }, ns: "local.slaves" }
        
        ...
        
        2015-02-11T12:29:38.265-0500 [conn54874] query klerk.ProductData query: { query: { groupKey: "4e20d04bec33075d8671fbec_51247477c519e3a71e639634", _id: { $gte: ObjectId('53224505e4b055a5d8ac41fb') } }, orderby: { _id: 1.0 }, $explain: true } planSummary: IXSCAN { groupKey: 1, _id: 1 } ntoreturn:0 ntoskip:0 nscanned:9 nscannedObjects:9 keyUpdates:0 numYields:31 locks(micros) r:401901 nreturned:1 reslen:2955 472ms

Generated at Thu Feb 08 03:43:49 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.