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

query does not use same execution plan w/wo explain(executionStats)

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Index Maintenance
    • None
    • Server Triage
    • ALL

      Hello,

      I open this ticket adviced by Renato.

      We have an slow query (find+sort) that takes 5 minutes. The collection has 1.2million documents:

      db.PassengerNameRecord.find({     "value.airSegments.serviceProviderCode" : "AC4",     "value.airSegments.identifier.code" : "123",     "value.airSegments.start.locationCode" : "CDG",     "value.airSegments.end.locationCode" : "YVR",     "value.airSegments.start.date" : "2018-09-25",     "value.airSegments.identifier.suffix" : "A" }).sort({fid:1})

       

      The same query with an explanation plan takes less than 1 second:

      db.PassengerNameRecord.find({     "value.airSegments.serviceProviderCode" : "AC4",     "value.airSegments.identifier.code" : "123",     "value.airSegments.start.locationCode" : "CDG",     "value.airSegments.end.locationCode" : "YVR",     "value.airSegments.start.date" : "2018-09-25",     "value.airSegments.identifier.suffix" : "A" }).sort({fid:1}).explain("executionStats")

       

      Seems the query does not execute in the same way when we use or not the explain.

       

      This is the output logged on the console from mongoD:

      2018-10-02T08:41:57.913+0000 I COMMAND [conn352677] command sampledb.PassengerNameRecord appName: "MongoDB Shell" command: find { find: "PassengerNameRecord", filter: { value.airSegments.serviceProviderCode: "AC4", value.airSegments.identifier.code: "123", value.airSegments.start.locationCode: "CDG", value.airSegments.end.locationCode: "YVR", value.airSegments.start.date: "2018-09-25", value.airSegments.identifier.suffix: "A" }, sort: { fid: 1.0 }, $db: "sampledb" } planSummary: IXSCAN { fid: 1 } keysExamined:1284240 docsExamined:1284240 cursorExhausted:1 numYields:13909 nreturned:0 reslen:101 locks:{ Global: { acquireCount: { r: 27820 } }, Database: { acquireCount: { r: 13910 } }, Collection: { acquireCount: { r: 13910 } } } protocol:op_msg 225041ms

       

       

      And here the output of the explain plan with the sort predicate:

      > db.PassengerNameRecord.find({ "value.airSegments.serviceProviderCode" : "AC4", "value.airSegments.identifier.code" : "123", "value.airSegments.start.locationCode" : "CDG", "value.airSegments.end.locationCode" : "YVR", "value.airSegments.start.date" : "2018-09-25", "value.airSegments.identifier.suffix" : "A" }).sort({fid:1}).explain("executionStats")
      {
      "queryPlanner" : {
      "plannerVersion" : 1,
      "namespace" : "sampledb.PassengerNameRecord",
      "indexFilterSet" : false,
      "parsedQuery" : {
      "$and" : [
      {
      "value.airSegments.end.locationCode" : { "$eq" : "YVR" }
      },
      {
      "value.airSegments.identifier.code" : { "$eq" : "123" }
      },
      {
      "value.airSegments.identifier.suffix" : { "$eq" : "A" }
      },
      {
      "value.airSegments.serviceProviderCode" : { "$eq" : "AC4" }
      },
      {
      "value.airSegments.start.date" : { "$eq" : "2018-09-25" }
      },
      {
      "value.airSegments.start.locationCode" : { "$eq" : "CDG" }
      }
      ]
      },
      "winningPlan" : {
      "stage" : "SORT",
      "sortPattern" : { "fid" : 1 },
      "inputStage" : {
      "stage" : "SORT_KEY_GENERATOR",
      "inputStage" : {
      "stage" : "FETCH",
      "filter" : {
      "$and" : [
      {
      "value.airSegments.end.locationCode" : { "$eq" : "YVR" }
      },
      {
      "value.airSegments.identifier.code" : { "$eq" : "123" }
      },
      {
      "value.airSegments.identifier.suffix" : { "$eq" : "A" }
      },
      {
      "value.airSegments.start.date" : { "$eq" : "2018-09-25" }
      },
      {
      "value.airSegments.start.locationCode" : { "$eq" : "CDG" }
      }
      ]
      },
      "inputStage" : {
      "stage" : "IXSCAN",
      "keyPattern" : { "value.airSegments.serviceProviderCode" : 1, "value.airSegments.identifier.code" : 1, "value.airSegments.start.locationCode" : 1, "value.airSegments.end.locationCode" : 1, "value.airSegments.start.date" : -1, "value.airSegments.identifier.suffix" : 1 },
      "indexName" : "pnrFlightDetailsIdx",
      "isMultiKey" : true,
      "multiKeyPaths" : { "value.airSegments.serviceProviderCode" : [ "value.airSegments" ], "value.airSegments.identifier.code" : [ "value.airSegments" ], "value.airSegments.start.locationCode" : [ "value.airSegments" ], "value.airSegments.end.locationCode" : [ "value.airSegments" ], "value.airSegments.start.date" : [ "value.airSegments" ], "value.airSegments.identifier.suffix" : [ "value.airSegments" ] },
      "isUnique" : false,
      "isSparse" : false,
      "isPartial" : false,
      "indexVersion" : 2,
      "direction" : "forward",
      "indexBounds" : { "value.airSegments.serviceProviderCode" : [ "[\"AC4\", \"AC4\"]" ], "value.airSegments.identifier.code" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.end.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.date" : [ "[MaxKey, MinKey]" ], "value.airSegments.identifier.suffix" : [ "[MinKey, MaxKey]" ] }
      }
      }
      }
      },
      "rejectedPlans" : [
      {
      "stage" : "FETCH",
      "filter" : {
      "$and" : [
      {
      "value.airSegments.end.locationCode" : { "$eq" : "YVR" }
      },
      {
      "value.airSegments.identifier.code" : { "$eq" : "123" }
      },
      {
      "value.airSegments.identifier.suffix" : { "$eq" : "A" }
      },
      {
      "value.airSegments.serviceProviderCode" : { "$eq" : "AC4" }
      },
      {
      "value.airSegments.start.date" : { "$eq" : "2018-09-25" }
      },
      {
      "value.airSegments.start.locationCode" : { "$eq" : "CDG" }
      }
      ]
      },
      "inputStage" : {
      "stage" : "IXSCAN",
      "keyPattern" : { "fid" : 1 },
      "indexName" : "fid_1",
      "isMultiKey" : false,
      "isUnique" : true,
      "isSparse" : false,
      "isPartial" : false,
      "indexVersion" : 1,
      "direction" : "forward",
      "indexBounds" : { "fid" : [ "[MinKey, MaxKey]" ] }
      }
      }
      ]
      },
      "executionStats" : {
      "executionSuccess" : true,
      "nReturned" : 0,
      "executionTimeMillis" : 0,
      "totalKeysExamined" : 0,
      "totalDocsExamined" : 0,
      "executionStages" : {
      "stage" : "SORT",
      "nReturned" : 0,
      "executionTimeMillisEstimate" : 0,
      "works" : 4,
      "advanced" : 0,
      "needTime" : 2,
      "needYield" : 0,
      "saveState" : 0,
      "restoreState" : 0,
      "isEOF" : 1,
      "invalidates" : 0,
      "sortPattern" : { "fid" : 1 },
      "memUsage" : 0,
      "memLimit" : 33554432,
      "inputStage" : {
      "stage" : "SORT_KEY_GENERATOR",
      "nReturned" : 0,
      "executionTimeMillisEstimate" : 0,
      "works" : 2,
      "advanced" : 0,
      "needTime" : 1,
      "needYield" : 0,
      "saveState" : 0,
      "restoreState" : 0,
      "isEOF" : 1,
      "invalidates" : 0,
      "inputStage" : {
      "stage" : "FETCH",
      "filter" : {
      "$and" : [
      {
      "value.airSegments.end.locationCode" : { "$eq" : "YVR" }
      },
      {
      "value.airSegments.identifier.code" : { "$eq" : "123" }
      },
      {
      "value.airSegments.identifier.suffix" : { "$eq" : "A" }
      },
      {
      "value.airSegments.start.date" : { "$eq" : "2018-09-25" }
      },
      {
      "value.airSegments.start.locationCode" : { "$eq" : "CDG" }
      }
      ]
      },
      "nReturned" : 0,
      "executionTimeMillisEstimate" : 0,
      "works" : 1,
      "advanced" : 0,
      "needTime" : 0,
      "needYield" : 0,
      "saveState" : 0,
      "restoreState" : 0,
      "isEOF" : 1,
      "invalidates" : 0,
      "docsExamined" : 0,
      "alreadyHasObj" : 0,
      "inputStage" : {
      "stage" : "IXSCAN",
      "nReturned" : 0,
      "executionTimeMillisEstimate" : 0,
      "works" : 1,
      "advanced" : 0,
      "needTime" : 0,
      "needYield" : 0,
      "saveState" : 0,
      "restoreState" : 0,
      "isEOF" : 1,
      "invalidates" : 0,
      "keyPattern" : { "value.airSegments.serviceProviderCode" : 1, "value.airSegments.identifier.code" : 1, "value.airSegments.start.locationCode" : 1, "value.airSegments.end.locationCode" : 1, "value.airSegments.start.date" : -1, "value.airSegments.identifier.suffix" : 1 },
      "indexName" : "pnrFlightDetailsIdx",
      "isMultiKey" : true,
      "multiKeyPaths" : { "value.airSegments.serviceProviderCode" : [ "value.airSegments" ], "value.airSegments.identifier.code" : [ "value.airSegments" ], "value.airSegments.start.locationCode" : [ "value.airSegments" ], "value.airSegments.end.locationCode" : [ "value.airSegments" ], "value.airSegments.start.date" : [ "value.airSegments" ], "value.airSegments.identifier.suffix" : [ "value.airSegments" ] },
      "isUnique" : false,
      "isSparse" : false,
      "isPartial" : false,
      "indexVersion" : 2,
      "direction" : "forward",
      "indexBounds" : { "value.airSegments.serviceProviderCode" : [ "[\"AC4\", \"AC4\"]" ], "value.airSegments.identifier.code" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.end.locationCode" : [ "[MinKey, MaxKey]" ], "value.airSegments.start.date" : [ "[MaxKey, MinKey]" ], "value.airSegments.identifier.suffix" : [ "[MinKey, MaxKey]" ] },
      "keysExamined" : 0,
      "seeks" : 1,
      "dupsTested" : 0,
      "dupsDropped" : 0,
      "seenInvalidated" : 0
      }
      }
      }
      }
      },
      "serverInfo" : { "host" : "mongodb-5-9c8hd", "port" : 27017, "version" : "3.6.3", "gitVersion" : "nogitversion" },
      "ok" : 1
      }
      >

       

      Mongo version:

      bash-4.2$ mongod --version
      db version v3.6.3
      git version: nogitversion
      OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
      allocator: tcmalloc
      modules: none
      build environment:
      distarch: x86_64
      target_arch: x86_64

       

       

      After cleaning the plan cache the problem dissappears:
      db.PassengerNameRecord.getPlanCache().clear()
      The collection has 1 index on the filter criteria (that was build on background), and one index on sort criteria.

      This record may be related to

      https://jira.mongodb.org/browse/SERVER-32943

      Thanks a lot.

      Jose MORALES ARAGON

            Assignee:
            backlog-server-triage [HELP ONLY] Backlog - Triage Team
            Reporter:
            jose.morales Jose MORALES ARAGON
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: