[SERVER-34785] The Cache Plan cause poor performance Created: 02/May/18  Updated: 08/Jun/18  Resolved: 14/May/18

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 3.2.19, 3.6.4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: zbdba Assignee: Kelsey Schubert
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-32452 Replanning may not occur when a plan ... Closed
Operating System: ALL
Participants:

 Description   

Hi All

Our MongoDB had poor perfomance when this query appear,this query like this:

db.files.find({"operation.sha1Code":"acca33867df96b97a05bdbd81f2aee13axxxxxxx","operation.is_prefix":true,"operation.des_url":"sh/"})

this collection have some indexes:

  {
  "v" : 1,
  "key" : {
  "operation.is_prefix" : 1
  },
  "name" : "operation.is_prefix_1",
  "ns" : "fs.files",
  "background" : true
  },
  {
  "v" : 1,
  "key" : {
  "operation.des_url" : 1
  },
  "name" : "operation.des_url_1",
  "ns" : "fs.files",
  "background" : true
  },
  {
  "v" : 1,
  "key" : {
  "operation.sha1Code" : 1
  },
  "name" : "operation.sha1Code_1",
  "ns" : "fs.files",
  "background" : true
  }

and every columns filter result count:

db.files.find({"operation.sha1Code":"acca33867df96b97a05bdbd81f2aee13axxxxxxx"}).count()
539408
db.files.find({"operation.is_prefix":true}).count()
463885621
db.files.find({"operation.des_url":"sh/"}).count()
*{color:#d04437}180999{color}*

this collection has 553055549 records.

So MongoDB choose the operation.des_url_1 index and it's perfect.but we saw many slow query after this query,such as :

2018-02-26T14:39:11.049+0800 I COMMAND  [conn3959231] command fs.files command: find { find: "files", filter: { operation.sha1Code: "e635838088b717ccfba83586375711c0axxxxxxx", operation.is_prefix: true, operation.des_url: "astro/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.des_url: 1.0 } keysExamined:21366 docsExamined:21366 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1146 nreturned:1 reslen:768 locks:{ Global: { acquireCount: { r: 2294 }, acquireWaitCount: { r: 1135 }, timeAcquiringMicros: { r: 21004892 } }, Database: { acquireCount: { r: 1147 } }, Collection: { acquireCount: { r: 1147 } } } protocol:op_query 50414ms

2018-02-26T14:40:08.200+0800 I COMMAND  [conn3935510] command fs.files command: find { find: "files", filter: { operation.sha1Code: "46cdc6924ad8fc298f2cac0b3e8536985xxxxxxx", operation.is_prefix: true, operation.des_url: "hebei/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.des_url: 1.0 } keysExamined:80967 docsExamined:80967 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:2807 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 5616 }, acquireWaitCount: { r: 2712 }, timeAcquiringMicros: { r: 53894897 } }, Database: { acquireCount: { r: 2808 } }, Collection: { acquireCount: { r: 2808 } } } protocol:op_query 127659ms

I learned about the plan cache mechanism by reading the MongoDB source code,MongoDB continue uses operation.des_url_1 Index scan internalQueryCacheEvictionRatio *works times for every similar queries, execute the replan mechanism if it exceeds 101 times advanced status. Otherwise, use the plan in the cache.If operation.des_url filter result count is less than 180999*10 will return IS_EOF status, will directly use the plan in the cache.

So after this query, we need to scan 180999*10 times for every similar queries,But all queries operation.des_url filter result count is less than 180999*10.so all queries get IS_EOF status,and directly use the plan in the cache.

All similar queries are used operation.des_url_1 index,But it needs to scan hundreds of thousands of times,Actually using operation.sha1Code_1 The index only needs to scan several times.

The operation.sha1Code filter result count:

db.files.find({"operation.sha1Code": "e635838088b717ccfba83586375711c0axxxxxxx"}).count()
1
 
db.files.find({"operation.sha1Code": "46cdc6924ad8fc298f2cac0b3e8536985xxxxxxx"}).count()
4

I think this is the main reason for our large number of slow queries,The mechanism to determine whether to use the plan in the cache is too simple,In some scenarios it may cause poor performance.
 



 Comments   
Comment by Kelsey Schubert [ 14/May/18 ]

Hi zbdba,

Thank you for the report. I believe that SERVER-32452 will address this issue. This ticket is actively being worked on and I recommend reviewing it and watching it for updates.

Kind regards,
Kelsey

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