Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-20913

DateTime index ignored / horrible performance

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor - P4
    • Resolution: Duplicate
    • Affects Version/s: 2.2.0, 3.0.6
    • Fix Version/s: None
    • Component/s: Querying
    • Labels:
      None
    • Operating System:
      ALL

      Description

      We have recently moved from a (single instance) MongoDB server 2.2.0 on Linux to a (single instance) MongoDB server 3.0.6 on Windows for a specific project. We have a collection that contains ~1.3 million documents.

      The following query to find messages for a specific 24h period performs perfectly fine on 2.2.0:

      db.MyCollection.find({ query: { 
          $and: [ 
              { "Messages.Message.Header.TimeStamp": { $gte: ISODate("2015-10-12T22:00:00Z") }},
              { "Messages.Message.Header.TimeStamp": { $lt: ISODate("2015-10-13T22:00:00Z") }}
          ] 
      }, $explain: 1});
      

      Explain:

      {
        "cursor": "BtreeCursor Messages.Message.Header.TimeStamp_1",
        "isMultiKey": true,
        "n": 7854,
        "nscannedObjects": 7854,
        "nscanned": 7854,
        "nscannedObjectsAllPlans": 7854,
        "nscannedAllPlans": 7854,
        "scanAndOrder": false,
        "indexOnly": false,
        "nYields": 0,
        "nChunkSkips": 0,
        "millis": 31,
        "indexBounds": {
          "Messages.Message.Header.TimeStamp": [
            [
              "2015-10-12T22:00:00Z",
              "292278995-01--2147483647T07:12:56.808Z"
            ]
          ]
        },
        "allPlans": [
          {
            "cursor": "BtreeCursor Messages.Message.Header.TimeStamp_1",
            "n": 7854,
            "nscannedObjects": 7854,
            "nscanned": 7854,
            "indexBounds": {
              "Messages.Message.Header.TimeStamp": [
                [
                  "2015-10-12T22:00:00Z",
                  "292278995-01--2147483647T07:12:56.808Z"
                ]
              ]
            }
          }
        ],
        "oldPlan": {
          "cursor": "BtreeCursor Messages.Message.Header.TimeStamp_1",
          "indexBounds": {
            "Messages.Message.Header.TimeStamp": [
              [
                "2015-10-12T22:00:00Z",
                "292278995-01--2147483647T07:12:56.808Z"
              ]
            ]
          }
        },
        "server": "myserver:27017"
      }
      

      (Though I don't know what's going on with the weird

      ""292278995-01--2147483647T07:12:56.808Z"

      value...?)

      We copied the collection to the new 3.0 (windows) server. And ran the same query; this took over 9 minutes to complete. I have re-created the index but that didn't help.

      The explain on this (win, 3.0.6) host looks like this:

      {
        "queryPlanner": {
          "plannerVersion": 1,
          "namespace": "MyDB.MyCollection",
          "indexFilterSet": false,
          "parsedQuery": {
            "$and": [
              {
                "Messages.Message.Header.TimeStamp": {
                  "$lt": "2015-10-13T22:00:00Z"
                }
              },
              {
                "Messages.Message.Header.TimeStamp": {
                  "$gte": "2015-10-12T22:00:00Z"
                }
              }
            ]
          },
          "winningPlan": {
            "stage": "KEEP_MUTATIONS",
            "inputStage": {
              "stage": "FETCH",
              "filter": {
                "Messages.Message.Header.TimeStamp": {
                  "$gte": "2015-10-12T22:00:00Z"
                }
              },
              "inputStage": {
                "stage": "IXSCAN",
                "keyPattern": {
                  "Messages.Message.Header.TimeStamp": 1
                },
                "indexName": "Messages.Message.Header.TimeStamp_1",
                "isMultiKey": true,
                "direction": "forward",
                "indexBounds": {
                  "Messages.Message.Header.TimeStamp": [
                    "(true, new Date(1444773600000))"
                  ]
                }
              }
            }
          },
          "rejectedPlans": []
        },
        "executionStats": {
          "executionSuccess": true,
          "nReturned": 8033,
          "executionTimeMillis": 118350,
          "totalKeysExamined": 1383287,
          "totalDocsExamined": 1383199,
          "executionStages": {
            "stage": "KEEP_MUTATIONS",
            "nReturned": 8033,
            "executionTimeMillisEstimate": 112792,
            "works": 1383353,
            "advanced": 8033,
            "needTime": 1375254,
            "needFetch": 65,
            "saveState": 11048,
            "restoreState": 11048,
            "isEOF": 1,
            "invalidates": 0,
            "inputStage": {
              "stage": "FETCH",
              "filter": {
                "Messages.Message.Header.TimeStamp": {
                  "$gte": "2015-10-12T22:00:00Z"
                }
              },
              "nReturned": 8033,
              "executionTimeMillisEstimate": 112652,
              "works": 1383353,
              "advanced": 8033,
              "needTime": 1375254,
              "needFetch": 65,
              "saveState": 11048,
              "restoreState": 11048,
              "isEOF": 1,
              "invalidates": 0,
              "docsExamined": 1383199,
              "alreadyHasObj": 0,
              "inputStage": {
                "stage": "IXSCAN",
                "nReturned": 1383199,
                "executionTimeMillisEstimate": 104092,
                "works": 1383287,
                "advanced": 1383199,
                "needTime": 88,
                "needFetch": 0,
                "saveState": 11048,
                "restoreState": 11048,
                "isEOF": 1,
                "invalidates": 0,
                "keyPattern": {
                  "Messages.Message.Header.TimeStamp": 1
                },
                "indexName": "Messages.Message.Header.TimeStamp_1",
                "isMultiKey": true,
                "direction": "forward",
                "indexBounds": {
                  "Messages.Message.Header.TimeStamp": [
                    "(true, new Date(1444773600000))"
                  ]
                },
                "keysExamined": 1383287,
                "dupsTested": 1383287,
                "dupsDropped": 88,
                "seenInvalidated": 0,
                "matchTested": 0
              }
            }
          },
          "allPlansExecution": []
        },
        "serverInfo": {
          "host": "myserver2",
          "port": 27017,
          "version": "3.0.6",
          "gitVersion": "1ef45a23a4c5e3480ac919b28afcba3c615488f2"
        }
      }
      

      If I change the query to 'greaterorequal than date X' instead of 'greaterorequal than date X and less than date Y' the query performs fine:

      db.Conversations.find({ query: { 
              "Messages.Message.Header.TimeStamp": { $gte: ISODate("2015-10-12T22:00:00Z") }
      }, $explain: 1});
      

      Explain:

      {
        "queryPlanner": {
          "plannerVersion": 1,
          "namespace": "MyDB.MyCollection",
          "indexFilterSet": false,
          "parsedQuery": {
            "Messages.Message.Header.TimeStamp": {
              "$gte": "2015-10-12T22:00:00Z"
            }
          },
          "winningPlan": {
            "stage": "FETCH",
            "inputStage": {
              "stage": "IXSCAN",
              "keyPattern": {
                "Messages.Message.Header.TimeStamp": 1
              },
              "indexName": "Messages.Message.Header.TimeStamp_1",
              "isMultiKey": true,
              "direction": "forward",
              "indexBounds": {
                "Messages.Message.Header.TimeStamp": [
                  "[new Date(1444687200000), new Date(9223372036854775807)]"
                ]
              }
            }
          },
          "rejectedPlans": []
        },
        "executionStats": {
          "executionSuccess": true,
          "nReturned": 11081,
          "executionTimeMillis": 359,
          "totalKeysExamined": 11081,
          "totalDocsExamined": 11081,
          "executionStages": {
            "stage": "FETCH",
            "nReturned": 11081,
            "executionTimeMillisEstimate": 330,
            "works": 11631,
            "advanced": 11081,
            "needTime": 0,
            "needFetch": 549,
            "saveState": 558,
            "restoreState": 558,
            "isEOF": 1,
            "invalidates": 0,
            "docsExamined": 11081,
            "alreadyHasObj": 0,
            "inputStage": {
              "stage": "IXSCAN",
              "nReturned": 11081,
              "executionTimeMillisEstimate": 270,
              "works": 11081,
              "advanced": 11081,
              "needTime": 0,
              "needFetch": 0,
              "saveState": 558,
              "restoreState": 558,
              "isEOF": 1,
              "invalidates": 0,
              "keyPattern": {
                "Messages.Message.Header.TimeStamp": 1
              },
              "indexName": "Messages.Message.Header.TimeStamp_1",
              "isMultiKey": true,
              "direction": "forward",
              "indexBounds": {
                "Messages.Message.Header.TimeStamp": [
                  "[new Date(1444687200000), new Date(9223372036854775807)]"
                ]
              },
              "keysExamined": 11081,
              "dupsTested": 11081,
              "dupsDropped": 0,
              "seenInvalidated": 0,
              "matchTested": 0
            }
          },
          "allPlansExecution": []
        },
        "serverInfo": {
          "host": "myserver2",
          "port": 27017,
          "version": "3.0.6",
          "gitVersion": "1ef45a23a4c5e3480ac919b28afcba3c615488f2"
        }
      }
      

      It seems that a range query "X => date1 X $and X < date2" somehow trips the queryplanner into not using the index whereas "X >= date1" is fine.

      If there's anything I can to to help or provide more information then please let me know.

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                8 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: