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

Performance issue: Query Plan Cache is always empty

    • ALL
    • Hide

      mongodb standalone configuration

      systemLog:
         destination: file
         path: "test.log"
         quiet: true
         logAppend: true
      storage:
         journal:
            enabled: true
         dbPath: "d:\\dbpath\\test"
         directoryPerDB: false
      
      net:
         bindIp: 127.0.0.1
         port: 27017
         http:
            RESTInterfaceEnabled: true
      

      create some documents

      for (i = 0; i < 100000; i++) {
      db.test26.insert(
          {"_id" : new ObjectId, 
              "user" : "mario", "removed" : false, "objId" : i, "created" : new Date(),
              "p" : { "id" : ["content"+i,"content"+(i+1),"content"+(i+2)]   }, 
              "a" : "attributea"+i,"b" : "attributeb"+i,"c" : "attributec"+i}   );
          }
      

      create some index

      db.test26.ensureIndex({ "user" : 1,"removed":1,"a" : 1 });
      db.test26.ensureIndex({ "user" : 1,"removed":1,"b" : 1 });
      db.test26.ensureIndex({ "user" : 1,"removed":1,"c" : 1 });
      db.test26.ensureIndex({ "user" : 1,"removed":1,"p.id" : 1 });
      
      Show
      mongodb standalone configuration systemLog: destination: file path: "test.log" quiet: true logAppend: true storage: journal: enabled: true dbPath: "d:\\dbpath\\test" directoryPerDB: false net: bindIp: 127.0.0.1 port: 27017 http: RESTInterfaceEnabled: true create some documents for (i = 0; i < 100000; i++) { db.test26.insert( { "_id" : new ObjectId, "user" : "mario" , "removed" : false , "objId" : i, "created" : new Date(), "p" : { "id" : [ "content" +i, "content" +(i+1), "content" +(i+2)] }, "a" : "attributea" +i, "b" : "attributeb" +i, "c" : "attributec" +i} ); } create some index db.test26.ensureIndex({ "user" : 1, "removed" :1, "a" : 1 }); db.test26.ensureIndex({ "user" : 1, "removed" :1, "b" : 1 }); db.test26.ensureIndex({ "user" : 1, "removed" :1, "c" : 1 }); db.test26.ensureIndex({ "user" : 1, "removed" :1, "p.id" : 1 });

      I found really bad performance on mongodb 2.6.4 (... 2.6.latest, 2.7.latest)..
      It seams that Query Plan Cache is always empty, and for each single query (not working over a specific index), mongodb performs a Query Plan.
      Performance are good only if hint() operator is specified with the query. I tested the same scenario on mongodb 2.4.3 but everything works fine.

      the test query

      db.test26.find({"user":"mario","removed":false,"objId":3}).explain()
      
      Explain result:
      
      {
          "cursor" : "BtreeCursor user_1_removed_1_a_1",
          "isMultiKey" : false,
          "n" : 2,
          "nscannedObjects" : 210000,
          "nscanned" : 210000,
          "nscannedObjectsAllPlans" : 482615,
          "nscannedAllPlans" : 524601,
          "scanAndOrder" : false,
          "indexOnly" : false,
          "nYields" : 5158,
          "nChunkSkips" : 0,
          "millis" : 1072,
          "filterSet" : false
      }
      

      I tried to run these commands:

      db.test26.find({"user":"mario","removed":false,"objId":3}).explain()
      db.test26.find({"user":"mario","removed":false,"objId":3})
      db.test26.find({"user":"mario","removed":false,"objId":3}).hint("user_1_removed_1_a_1")
      

      getting the following log output:

      # log for query with explain true: [conn11] query test.test26 query: { query: { user: "mario", removed: false, objId: 3.0 }, $explain: true } planSummary: IXSCAN { user: 1.0, removed: 1.0, a: 1.0 } ntoreturn:0 ntoskip:0 nscanned:210000 nscannedObjects:210000 keyUpdates:0 numYields:1685 locks(micros) r:2127426 nreturned:1 reslen:3291 1072ms
      # log for query without explain: [conn11] query test.test26 query: { user: "mario", removed: false, objId: 3.0 } planSummary: IXSCAN { user: 1.0, removed: 1.0, a: 1.0 } ntoreturn:0 ntoskip:0 nscanned:210000 nscannedObjects:210000 keyUpdates:0 numYields:1 locks(micros) r:1298548 nreturned:2 reslen:424 981ms
      # log for query with hint: [conn11] query test.test26 query: { query: { user: "mario", removed: false, objId: 3.0 }, $hint: "user_1_removed_1_a_1" } planSummary: IXSCAN { user: 1.0, removed: 1.0, a: 1.0 } ntoreturn:0 ntoskip:0 nscanned:210000 nscannedObjects:210000 keyUpdates:0 numYields:1 locks(micros) r:777390 nreturned:2 reslen:424 390ms
      

      The query number 2 has the same performance of the query with the explain command, and I suppose that every time the query runs the mongodb server perform a full query plan!!! After the execution of the query, the Query Plan Cache seams to be empty

      db.collection.getPlanCache().listQueryShapes() = []
      

      Additional notes

      If I declare other indexes on the same collection the performance of query downgrade!

      mongodb 2.4.3 log for the same test:

      1st run of the query:  [conn2] query test.test26 query: { user: "mario", removed: false, objId: 3.0 } ntoreturn:0 ntoskip:0 nscanned:1470000 keyUpdates:0 numYields: 5 locks(micros) W:5252 r:8464649 nreturned:2 reslen:424 4381ms
      2nd run of the query:  [conn2] query test.test26 query: { user: "mario", removed: false, objId: 3.0 } ntoreturn:0 ntoskip:0 nscanned:210000 keyUpdates:0 locks(micros) r:652975 nreturned:2 reslen:424 652ms
      

            Assignee:
            ramon.fernandez@mongodb.com Ramon Fernandez Marina
            Reporter:
            flavio@alicubi.net flavio alberti
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: