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

Performance issue: Query Plan Cache is always empty

XMLWordPrintableJSON

    • 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 });
    • None
    • 0
    • None
    • None
    • None
    • None
    • None
    • None

      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: