[SERVER-15237] Performance issue: Query Plan Cache is always empty Created: 12/Sep/14  Updated: 12/Sep/14  Resolved: 12/Sep/14

Status: Closed
Project: Core Server
Component/s: Performance, Querying
Affects Version/s: 2.6.4, 2.7.6
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: flavio alberti Assignee: Ramon Fernandez Marina
Resolution: Done Votes: 0
Labels: indexes, performance, query
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-13675 Plans with differing performance can ... Closed
related to SERVER-14525 Perf regression in 2.6.2 caused by no... Closed
Operating System: ALL
Steps To Reproduce:

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 });

Participants:

 Description   

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



 Comments   
Comment by Ramon Fernandez Marina [ 12/Sep/14 ]

flavio@alicubi.net, given the indexes in your test26 collection, it is expected that your query plan cache is empty after a change introduced in SERVER-13675. If you're experiencing performance problems, the workaround as you found out is to use hint(). The potential performance impact of SERVER-13675 is being worked on in SERVER-14525, so please feel free to watch that ticket for progress updates.

Regards,
Ramón.

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