[SERVER-18507] A query will take very long time in a sudden but it works well in most time. Created: 18/May/15  Updated: 29/May/15  Resolved: 29/May/15

Status: Closed
Project: Core Server
Component/s: Querying, WiredTiger
Affects Version/s: 3.0.3
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: carl dong Assignee: Ramon Fernandez Marina
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File Test.log    
Issue Links:
Duplicate
duplicates SERVER-15225 CachedPlanStage should execute for tr... Closed
is duplicated by SERVER-18602 A query will take very long time in a... Closed
Related
related to SERVER-17054 Index not being utilized, on occasion. Closed
Operating System: ALL
Participants:

 Description   

There is a very strange issue when new Mongodb 3.0.3 instance running ,
queries works well in most time , but suddenly it will cost more than 10 seconds.

Here is the output from the db log, first the short one and then the long one:

2015-05-18T15:24:42.879+0800 I COMMAND  [conn22550] command Radius.$cmd command: findAndModify { findandmodify: "RadiusAccount", query: { acctsessionid: "90-3C-92-C2-EA-38-9659892E" }, sort: { _id: -1 }, update: { $set: { acctsessionid: "90-3C-92-C2-EA-38-9659892E", username: "18918978008", nasipaddress: "183.192.114.254", nasportid: "0000000125", nasporttype: 19, nasport: 1, sessiontime: 2700, inputoctets: "5456078", outputoctets: "694505", ipaddress: "100.65.154.152", calledstationid: "00-19-70-FE-14-5B:i-Shanghai", callingstationid: "90:3C:92:C2:EA:38", userlocation: "mobile&0206050021000460", operator: 2, userlevel: "1", nasipv6address: "::", framedinterfaceid: "9d27:dc24:ee63:9de5", loginipv6host: "2409:88a4:8000:16:9d27:dc24:ee63:9de5", acctipv6inputoctets: "6004364279808", acctipv6outputoctets: "19546396164096", nasidentifier: "0206050021000460", lut: new Date(1431933882876) } }, new: true, upsert: true } update: { $set: { acctsessionid: "90-3C-92-C2-EA-38-9659892E", username: "18918978008", nasipaddress: "183.192.114.254", nasportid: "0000000125", nasporttype: 19, nasport: 1, sessiontime: 2700, inputoctets: "5456078", outputoctets: "694505", ipaddress: "100.65.154.152", calledstationid: "00-19-70-FE-14-5B:i-Shanghai", callingstationid: "90:3C:92:C2:EA:38", userlocation: "mobile&0206050021000460", operator: 2, userlevel: "1", nasipv6address: "::", framedinterfaceid: "9d27:dc24:ee63:9de5", loginipv6host: "2409:88a4:8000:16:9d27:dc24:ee63:9de5", acctipv6inputoctets: "6004364279808", acctipv6outputoctets: "19546396164096", nasidentifier: "0206050021000460", lut: new Date(1431933882876) } } nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:865 locks:{ Global: { acquireCount: { w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 1ms
2015-05-17T00:12:46.422+0800 I COMMAND  [conn12974] command Radius.$cmd command: findAndModify { findandmodify: "RadiusAccount", query: { acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64" }, sort: { _id: -1 }, update: { $set: { acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64", username: "18817339667", nasipaddress: "222.66.249.120", nasportid: "CPD11225", nasporttype: 19, nasport: 1, stoptime: new Date(1431792754077), sessiontime: 114, inputoctets: "57753", outputoctets: "320987", terminatecause: "Admin-Reset", stopdelay: 0, ipaddress: "101.92.170.191", calledstationid: "ishanghai", callingstationid: "D0:DF:9A:46:F2:78", userlocation: "telecom&CPD11225", operator: 1, userlevel: "1", servicetype: "Framed-User", nasidentifier: "2bb2f23ce9c21f721e9087ee9899ff76", lut: new Date(1431792754078) } }, new: true, upsert: true } keyUpdates:0 writeConflicts:0 numYields:35862 reslen:707 locks:{ Global: { acquireCount: { w: 35864 } }, Database: { acquireCount: { w: 35864 } }, Collection: { acquireCount: { w: 35863 } }, oplog: { acquireCount: { w: 1 } } } 12341ms

Actully , both the same query , it cost only 1ms when I run them manually.

Here is my config file :

processManagement :
 fork : true
 pidFilePath :  /home/Radius/Rad.pid
systemLog:
 destination : file
 path : /home/Radius/Log/Rad_Log
 logAppend : true
 
storage:
 dbPath : /home/Radius/Data_WiredTiger
 engine : wiredTiger
 wiredTiger :
  engineConfig :
   cacheSizeGB : 20
 directoryPerDB : true
 
net:
 port : 40001
 maxIncomingConnections : 2000
 
security:
 authorization  : enabled
 keyFile : /home/Radius/Keys/RadKey
 
replication:
 replSetName : rad
 
auditLog:
 destination : file
 format : JSON
 path : /home/Radius/Log/RadiusDBAduit.json
 filter : '{ atype : {$nin : ["authenticate"]} }'

Please give some advise on tracing the issue .

Thanks .

Carl Dong



 Comments   
Comment by Ramon Fernandez Marina [ 29/May/15 ]

carl.dong@windfindtech.com, while the information you uploaded doesn't quite allow us to pinpoint the root cause of this issue, the fact that forcing your queries to use the acctsessionid index solves the slowness makes me think you may be running into SERVER-15225.

We're closing this ticket now, glad to hear you were able to resolve this successfully.

Regards,
Ramón.

Comment by carl dong [ 29/May/15 ]

Hi Ramon,

4 days since index filter was setup, no issue happen with those queries , the solution works very well .

Thanks for your trouble shooting .

Carl Dong

Comment by carl dong [ 25/May/15 ]

I setup Index Filters to force the queries to hint acctsessionid index to make sure it executes on the correct index ,

db.runCommand({ planCacheListFilters:'RadiusAccount'})
{
        "filters" : [
                {
                        "query" : {
                                "acctsessionid" : "28-E1-4C-1C-C3-FA-D062D8D5",
                                "$and" : [
                                        {
                                                "starttime" : {
                                                        "$gte" : ISODate("2015-05-25T08:08:57.026Z")
                                                }
                                        },
                                        {
                                                "starttime" : {
                                                        "$lte" : ISODate("2015-05-25T08:10:57.026Z")
                                                }
                                        }
                                ]
                        },
                        "sort" : {
                                "_id" : -1
                        },
                        "projection" : {
 
 
 
 
                        },
                        "indexes" : [
                                {
                                        "acctsessionid" : 1
                                }
                        ]
                },
                {
                        "query" : {
                                "acctsessionid" : "1667b808571ec145f6cf6931ee7952e67ad7368f8b9e7afc20e83a0adaee35ee017d5979f1bdfd74f0ae0100fb973340"
                        },
                        "sort" : {
                                "_id" : -1
                        },
                        "projection" : {
 
 
 
 
                        },
                        "indexes" : [
                                {
                                        "acctsessionid" : 1
                                }
                        ]
                }
        ],
        "ok" : 1
}

Is this the correct way to stabilize the explain plan ?
Will keep you update the performance .

Thanks ,

Carl Dong.

Comment by carl dong [ 25/May/15 ]

Hi Ramon,

Here's the output .

var oldLogLevel = db.adminCommand({getParameter:1, logLevel:1}).logLevel
db.adminCommand( { setParameter: 1, logLevel: 2 } ) 
 
db.RadiusAccount.getPlanCache().listQueryShapes()
 
[
        {
                "query" : {
                        "acctsessionid" : "1667b808571ec14596566644c87647f07104c7791b2fb9ec164f4cef210dacb22ef0728cbd10529b8431bd07a73017ec"
                },
                "sort" : {
                        "_id" : -1
                },
                "projection" : {
 
                }
        },
        {
                "query" : {
                        "username" : "13611755230",
                        "stoptime" : {
                                "$exists" : false
                        }
                },
                "sort" : {
 
                },
                "projection" : {
 
                }
        },
        {
                "query" : {
                        "acctsessionid" : "7C-1D-D9-75-52-D9-DF627B4D",
                        "$and" : [
                                {
                                        "starttime" : {
                                                "$gte" : ISODate("2015-05-25T01:29:53.941Z")
                                        }
                                },
                                {
                                        "starttime" : {
                                                "$lte" : ISODate("2015-05-25T01:31:53.941Z")
                                        }
                                }
                        ]
                },
                "sort" : {
                        "_id" : -1
                },
                "projection" : {
 
                }
        }
]

 
db.RadiusAccount.find({ acctsessionid: "90-3C-92-C2-EA-38-9659892E" }).sort({ _id: -1 }).explain(true)
{
        "queryPlanner" : {
                "plannerVersion" : 1,
                "namespace" : "Radius.RadiusAccount",
                "indexFilterSet" : false,
                "parsedQuery" : {
                        "acctsessionid" : {
                                "$eq" : "90-3C-92-C2-EA-38-9659892E"
                        }
                },
                "winningPlan" : {
                        "stage" : "SORT",
                        "sortPattern" : {
                                "_id" : -1
                        },
                        "inputStage" : {
                                "stage" : "FETCH",
                                "inputStage" : {
                                        "stage" : "IXSCAN",
                                        "keyPattern" : {
                                                "acctsessionid" : 1
                                        },
                                        "indexName" : "acctsessionid_1",
                                        "isMultiKey" : false,
                                        "direction" : "forward",
                                        "indexBounds" : {
                                                "acctsessionid" : [
                                                        "[\"90-3C-92-C2-EA-38-9659892E\", \"90-3C-92-C2-EA-38-9659892E\"]"
                                                ]
                                        }
                                }
                        }
                },
                "rejectedPlans" : [
                        {
                                "stage" : "FETCH",
                                "filter" : {
                                        "acctsessionid" : {
                                                "$eq" : "90-3C-92-C2-EA-38-9659892E"
                                        }
                                },
                                "inputStage" : {
                                        "stage" : "IXSCAN",
                                        "keyPattern" : {
                                                "_id" : 1
                                        },
                                        "indexName" : "_id_",
                                        "isMultiKey" : false,
                                        "direction" : "backward",
                                        "indexBounds" : {
                                                "_id" : [
                                                        "[MaxKey, MinKey]"
                                                ]
                                        }
                                }
                        }
                ]
        },
        "executionStats" : {
                "executionSuccess" : true,
                "nReturned" : 1,
                "executionTimeMillis" : 0,
                "totalKeysExamined" : 1,
                "totalDocsExamined" : 1,
                "executionStages" : {
                        "stage" : "SORT",
                        "nReturned" : 1,
                        "executionTimeMillisEstimate" : 0,
                        "works" : 6,
                        "advanced" : 1,
                        "needTime" : 2,
                        "needFetch" : 0,
                        "saveState" : 0,
                        "restoreState" : 0,
                        "isEOF" : 1,
                        "invalidates" : 0,
                        "sortPattern" : {
                                "_id" : -1
                        },
                        "memUsage" : 848,
                        "memLimit" : 33554432,
                        "inputStage" : {
                                "stage" : "FETCH",
                                "nReturned" : 1,
                                "executionTimeMillisEstimate" : 0,
                                "works" : 2,
                                "advanced" : 1,
                                "needTime" : 0,
                                "needFetch" : 0,
                                "saveState" : 0,
                                "restoreState" : 0,
                                "isEOF" : 1,
                                "invalidates" : 0,
                                "docsExamined" : 1,
                                "alreadyHasObj" : 0,
                                "inputStage" : {
                                        "stage" : "IXSCAN",
                                        "nReturned" : 1,
                                        "executionTimeMillisEstimate" : 0,
                                        "works" : 2,
                                        "advanced" : 1,
                                        "needTime" : 0,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 1,
                                        "invalidates" : 0,
                                        "keyPattern" : {
                                                "acctsessionid" : 1
                                        },
                                        "indexName" : "acctsessionid_1",
                                        "isMultiKey" : false,
                                        "direction" : "forward",
                                        "indexBounds" : {
                                                "acctsessionid" : [
                                                        "[\"90-3C-92-C2-EA-38-9659892E\", \"90-3C-92-C2-EA-38-9659892E\"]"
                                                ]
                                        },
                                        "keysExamined" : 1,
                                        "dupsTested" : 0,
                                        "dupsDropped" : 0,
                                        "seenInvalidated" : 0,
                                        "matchTested" : 0
                                }
                        }
                },
                "allPlansExecution" : [
                        {
                                "nReturned" : 0,
                                "executionTimeMillisEstimate" : 0,
                                "totalKeysExamined" : 5,
                                "totalDocsExamined" : 5,
                                "executionStages" : {
                                        "stage" : "FETCH",
                                        "filter" : {
                                                "acctsessionid" : {
                                                        "$eq" : "90-3C-92-C2-EA-38-9659892E"
                                                }
                                        },
                                        "nReturned" : 0,
                                        "executionTimeMillisEstimate" : 0,
                                        "works" : 5,
                                        "advanced" : 0,
                                        "needTime" : 5,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 0,
                                        "invalidates" : 0,
                                        "docsExamined" : 5,
                                        "alreadyHasObj" : 0,
                                        "inputStage" : {
                                                "stage" : "IXSCAN",
                                                "nReturned" : 5,
                                                "executionTimeMillisEstimate" : 0,
                                                "works" : 5,
                                                "advanced" : 5,
                                                "needTime" : 0,
                                                "needFetch" : 0,
                                                "saveState" : 0,
                                                "restoreState" : 0,
                                                "isEOF" : 0,
                                                "invalidates" : 0,
                                                "keyPattern" : {
                                                        "_id" : 1
                                                },
                                                "indexName" : "_id_",
                                                "isMultiKey" : false,
                                                "direction" : "backward",
                                                "indexBounds" : {
                                                        "_id" : [
                                                                "[MaxKey, MinKey]"
                                                        ]
                                                },
                                                "keysExamined" : 5,
                                                "dupsTested" : 0,
                                                "dupsDropped" : 0,
                                                "seenInvalidated" : 0,
                                                "matchTested" : 0
                                        }
                                }
                        },
                        {
                                "nReturned" : 1,
                                "executionTimeMillisEstimate" : 0,
                                "totalKeysExamined" : 1,
                                "totalDocsExamined" : 1,
                                "executionStages" : {
                                        "stage" : "SORT",
                                        "nReturned" : 1,
                                        "executionTimeMillisEstimate" : 0,
                                        "works" : 5,
                                        "advanced" : 1,
                                        "needTime" : 2,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 1,
                                        "invalidates" : 0,
                                        "sortPattern" : {
                                                "_id" : -1
                                        },
                                        "memUsage" : 848,
                                        "memLimit" : 33554432,
                                        "inputStage" : {
                                                "stage" : "FETCH",
                                                "nReturned" : 1,
                                                "executionTimeMillisEstimate" : 0,
                                                "works" : 2,
                                                "advanced" : 1,
                                                "needTime" : 0,
                                                "needFetch" : 0,
                                                "saveState" : 0,
                                                "restoreState" : 0,
                                                "isEOF" : 1,
                                                "invalidates" : 0,
                                                "docsExamined" : 1,
                                                "alreadyHasObj" : 0,
                                                "inputStage" : {
                                                        "stage" : "IXSCAN",
                                                        "nReturned" : 1,
                                                        "executionTimeMillisEstimate" : 0,
                                                        "works" : 2,
                                                        "advanced" : 1,
                                                        "needTime" : 0,
                                                        "needFetch" : 0,
                                                        "saveState" : 0,
                                                        "restoreState" : 0,
                                                        "isEOF" : 1,
                                                        "invalidates" : 0,
                                                        "keyPattern" : {
                                                                "acctsessionid" : 1
                                                        },
                                                        "indexName" : "acctsessionid_1",
                                                        "isMultiKey" : false,
                                                        "direction" : "forward",
                                                        "indexBounds" : {
                                                                "acctsessionid" : [
                                                                        "[\"90-3C-92-C2-EA-38-9659892E\", \"90-3C-92-C2-EA-38-9659892E\"]"
                                                                ]
                                                        },
                                                        "keysExamined" : 1,
                                                        "dupsTested" : 0,
                                                        "dupsDropped" : 0,
                                                        "seenInvalidated" : 0,
                                                        "matchTested" : 0
                                                }
                                        }
                                }
                        }
                ]
        },
        "serverInfo" : {
                "host" : "iSHGQSvrDB002",
                "port" : 40001,
                "version" : "3.0.3",
                "gitVersion" : "b40106b36eecd1b4407eb1ad1af6bc60593c6105 modules: enterprise"
        },
        "ok" : 1
}

db.RadiusAccount.getPlanCache().getPlansByQuery({ acctsessionid: "90-3C-92-C2-EA-38-9659892E" }, {}, { _id : -1})
 
 [
        {
                "details" : {
                        "solution" : "(index-tagged expression tree: tree=Leaf { acctsessionid: 1.0 }, pos: 0\n)"
                },
                "reason" : {
                        "score" : 1.2502,
                        "stats" : {
                                "stage" : "SORT",
                                "nReturned" : 1,
                                "executionTimeMillisEstimate" : 0,
                                "works" : 4,
                                "advanced" : 1,
                                "needTime" : 2,
                                "needFetch" : 0,
                                "saveState" : 0,
                                "restoreState" : 0,
                                "isEOF" : 1,
                                "invalidates" : 0,
                                "sortPattern" : {
                                        "_id" : -1
                                },
                                "memUsage" : 767,
                                "memLimit" : 33554432,
                                "limitAmount" : 1,
                                "inputStage" : {
                                        "stage" : "FETCH",
                                        "nReturned" : 1,
                                        "executionTimeMillisEstimate" : 0,
                                        "works" : 2,
                                        "advanced" : 1,
                                        "needTime" : 0,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 1,
                                        "invalidates" : 0,
                                        "docsExamined" : 1,
                                        "alreadyHasObj" : 0,
                                        "inputStage" : {
                                                "stage" : "IXSCAN",
                                                "nReturned" : 1,
                                                "executionTimeMillisEstimate" : 0,
                                                "works" : 2,
                                                "advanced" : 1,
                                                "needTime" : 0,
                                                "needFetch" : 0,
                                                "saveState" : 0,
                                                "restoreState" : 0,
                                                "isEOF" : 1,
                                                "invalidates" : 0,
                                                "keyPattern" : {
                                                        "acctsessionid" : 1
                                                },
                                                "indexName" : "acctsessionid_1",
                                                "isMultiKey" : false,
                                                "direction" : "forward",
                                                "indexBounds" : {
                                                        "acctsessionid" : [
                                                                "[\"00-61-71-0F-45-FB-BA627338\", \"00-61-71-0F-45-FB-BA627338\"]"
                                                        ]
                                                },
                                                "keysExamined" : 1,
                                                "dupsTested" : 0,
                                                "dupsDropped" : 0,
                                                "seenInvalidated" : 0,
                                                "matchTested" : 0
                                        }
                                }
                        }
                },
                "feedback" : {
                        "nfeedback" : 20,
                        "averageScore" : 1.1543666666666663,
                        "stdDevScore" : 0.11870093630928842,
                        "scores" : [
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.1668666666666667
                                },
                                {
                                        "score" : 1.1668666666666667
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                }
                        ]
                },
                "filterSet" : false
        },
        {
                "details" : {
                        "solution" : "(whole index scan solution: dir=-1; tree=Leaf { _id: 1 }, pos: 0\n)"
                },
                "reason" : {
                        "score" : 1.0003,
                        "stats" : {
                                "stage" : "LIMIT",
                                "nReturned" : 0,
                                "executionTimeMillisEstimate" : 0,
                                "works" : 4,
                                "advanced" : 0,
                                "needTime" : 4,
                                "needFetch" : 0,
                                "saveState" : 0,
                                "restoreState" : 0,
                                "isEOF" : 0,
                                "invalidates" : 0,
                                "limitAmount" : 1,
                                "inputStage" : {
                                        "stage" : "FETCH",
                                        "filter" : {
                                                "acctsessionid" : {
                                                        "$eq" : "00-61-71-0F-45-FB-BA627338"
                                                }
                                        },
                                        "nReturned" : 0,
                                        "executionTimeMillisEstimate" : 0,
                                        "works" : 4,
                                        "advanced" : 0,
                                        "needTime" : 4,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 0,
                                        "invalidates" : 0,
                                        "docsExamined" : 4,
                                        "alreadyHasObj" : 0,
                                        "inputStage" : {
                                                "stage" : "IXSCAN",
                                                "nReturned" : 4,
                                                "executionTimeMillisEstimate" : 0,
                                                "works" : 4,
                                                "advanced" : 4,
                                                "needTime" : 0,
                                                "needFetch" : 0,
                                                "saveState" : 0,
                                                "restoreState" : 0,
                                                "isEOF" : 0,
                                                "invalidates" : 0,
                                                "keyPattern" : {
                                                        "_id" : 1
                                                },
                                                "indexName" : "_id_",
                                                "isMultiKey" : false,
                                                "direction" : "backward",
                                                "indexBounds" : {
                                                        "_id" : [
                                                                "[MaxKey, MinKey]"
                                                        ]
                                                },
                                                "keysExamined" : 4,
                                                "dupsTested" : 0,
                                                "dupsDropped" : 0,
                                                "seenInvalidated" : 0,
                                                "matchTested" : 0
                                        }
                                }
                        }
                },
                "feedback" : {
 
                },
                "filterSet" : false
        }
]

db.RadiusAccount.find({ acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64" }).sort({ _id: -1 }).explain(true)
 
{
        "queryPlanner" : {
                "plannerVersion" : 1,
                "namespace" : "Radius.RadiusAccount",
                "indexFilterSet" : false,
                "parsedQuery" : {
                        "acctsessionid" : {
                                "$eq" : "090de21e9375571fece70d267c3e79a705e60cca2b751a64"
                        }
                },
                "winningPlan" : {
                        "stage" : "SORT",
                        "sortPattern" : {
                                "_id" : -1
                        },
                        "inputStage" : {
                                "stage" : "FETCH",
                                "inputStage" : {
                                        "stage" : "IXSCAN",
                                        "keyPattern" : {
                                                "acctsessionid" : 1
                                        },
                                        "indexName" : "acctsessionid_1",
                                        "isMultiKey" : false,
                                        "direction" : "forward",
                                        "indexBounds" : {
                                                "acctsessionid" : [
                                                        "[\"090de21e9375571fece70d267c3e79a705e60cca2b751a64\", \"090de21e9375571fece70d267c3e79a705e60cca2b751a64\"]"
                                                ]
                                        }
                                }
                        }
                },
                "rejectedPlans" : [ ]
        },
        "executionStats" : {
                "executionSuccess" : true,
                "nReturned" : 0,
                "executionTimeMillis" : 13,
                "totalKeysExamined" : 0,
                "totalDocsExamined" : 0,
                "executionStages" : {
                        "stage" : "SORT",
                        "nReturned" : 0,
                        "executionTimeMillisEstimate" : 10,
                        "works" : 4,
                        "advanced" : 0,
                        "needTime" : 1,
                        "needFetch" : 0,
                        "saveState" : 0,
                        "restoreState" : 0,
                        "isEOF" : 1,
                        "invalidates" : 0,
                        "sortPattern" : {
                                "_id" : -1
                        },
                        "memUsage" : 0,
                        "memLimit" : 33554432,
                        "inputStage" : {
                                "stage" : "FETCH",
                                "nReturned" : 0,
                                "executionTimeMillisEstimate" : 10,
                                "works" : 1,
                                "advanced" : 0,
                                "needTime" : 0,
                                "needFetch" : 0,
                                "saveState" : 0,
                                "restoreState" : 0,
                                "isEOF" : 1,
                                "invalidates" : 0,
                                "docsExamined" : 0,
                                "alreadyHasObj" : 0,
                                "inputStage" : {
                                        "stage" : "IXSCAN",
                                        "nReturned" : 0,
                                        "executionTimeMillisEstimate" : 10,
                                        "works" : 1,
                                        "advanced" : 0,
                                        "needTime" : 0,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 1,
                                        "invalidates" : 0,
                                        "keyPattern" : {
                                                "acctsessionid" : 1
                                        },
                                        "indexName" : "acctsessionid_1",
                                        "isMultiKey" : false,
                                        "direction" : "forward",
                                        "indexBounds" : {
                                                "acctsessionid" : [
                                                        "[\"090de21e9375571fece70d267c3e79a705e60cca2b751a64\", \"090de21e9375571fece70d267c3e79a705e60cca2b751a64\"]"
                                                ]
                                        },
                                        "keysExamined" : 0,
                                        "dupsTested" : 0,
                                        "dupsDropped" : 0,
                                        "seenInvalidated" : 0,
                                        "matchTested" : 0
                                }
                        }
                },
                "allPlansExecution" : [
                        {
                                "nReturned" : 0,
                                "executionTimeMillisEstimate" : 10,
                                "totalKeysExamined" : 0,
                                "totalDocsExamined" : 0,
                                "executionStages" : {
                                        "stage" : "SORT",
                                        "nReturned" : 0,
                                        "executionTimeMillisEstimate" : 10,
                                        "works" : 3,
                                        "advanced" : 0,
                                        "needTime" : 1,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 1,
                                        "invalidates" : 0,
                                        "sortPattern" : {
                                                "_id" : -1
                                        },
                                        "memUsage" : 0,
                                        "memLimit" : 33554432,
                                        "inputStage" : {
                                                "stage" : "FETCH",
                                                "nReturned" : 0,
                                                "executionTimeMillisEstimate" : 10,
                                                "works" : 1,
                                                "advanced" : 0,
                                                "needTime" : 0,
                                                "needFetch" : 0,
                                                "saveState" : 0,
                                                "restoreState" : 0,
                                                "isEOF" : 1,
                                                "invalidates" : 0,
                                                "docsExamined" : 0,
                                                "alreadyHasObj" : 0,
                                                "inputStage" : {
                                                        "stage" : "IXSCAN",
                                                        "nReturned" : 0,
                                                        "executionTimeMillisEstimate" : 10,
                                                        "works" : 1,
                                                        "advanced" : 0,
                                                        "needTime" : 0,
                                                        "needFetch" : 0,
                                                        "saveState" : 0,
                                                        "restoreState" : 0,
                                                        "isEOF" : 1,
                                                        "invalidates" : 0,
                                                        "keyPattern" : {
                                                                "acctsessionid" : 1
                                                        },
                                                        "indexName" : "acctsessionid_1",
                                                        "isMultiKey" : false,
                                                        "direction" : "forward",
                                                        "indexBounds" : {
                                                                "acctsessionid" : [
                                                                        "[\"090de21e9375571fece70d267c3e79a705e60cca2b751a64\", \"090de21e9375571fece70d267c3e79a705e60cca2b751a64\"]"
                                                                ]
                                                        },
                                                        "keysExamined" : 0,
                                                        "dupsTested" : 0,
                                                        "dupsDropped" : 0,
                                                        "seenInvalidated" : 0,
                                                        "matchTested" : 0
                                                }
                                        }
                                }
                        }
                ]
        },
        "serverInfo" : {
                "host" : "iSHGQSvrDB002",
                "port" : 40001,
                "version" : "3.0.3",
                "gitVersion" : "b40106b36eecd1b4407eb1ad1af6bc60593c6105 modules: enterprise"
        },
        "ok" : 1
}

db.RadiusAccount.getPlanCache().getPlansByQuery({acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64"}, {}, { _id : -1})
 
 [
        {
                "details" : {
                        "solution" : "(index-tagged expression tree: tree=Leaf { acctsessionid: 1.0 }, pos: 0\n)"
                },
                "reason" : {
                        "score" : 1.2502,
                        "stats" : {
                                "stage" : "SORT",
                                "nReturned" : 1,
                                "executionTimeMillisEstimate" : 0,
                                "works" : 4,
                                "advanced" : 1,
                                "needTime" : 2,
                                "needFetch" : 0,
                                "saveState" : 0,
                                "restoreState" : 0,
                                "isEOF" : 1,
                                "invalidates" : 0,
                                "sortPattern" : {
                                        "_id" : -1
                                },
                                "memUsage" : 622,
                                "memLimit" : 33554432,
                                "limitAmount" : 1,
                                "inputStage" : {
                                        "stage" : "FETCH",
                                        "nReturned" : 1,
                                        "executionTimeMillisEstimate" : 0,
                                        "works" : 2,
                                        "advanced" : 1,
                                        "needTime" : 0,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 1,
                                        "invalidates" : 0,
                                        "docsExamined" : 1,
                                        "alreadyHasObj" : 0,
                                        "inputStage" : {
                                                "stage" : "IXSCAN",
                                                "nReturned" : 1,
                                                "executionTimeMillisEstimate" : 0,
                                                "works" : 2,
                                                "advanced" : 1,
                                                "needTime" : 0,
                                                "needFetch" : 0,
                                                "saveState" : 0,
                                                "restoreState" : 0,
                                                "isEOF" : 1,
                                                "invalidates" : 0,
                                                "keyPattern" : {
                                                        "acctsessionid" : 1
                                                },
                                                "indexName" : "acctsessionid_1",
                                                "isMultiKey" : false,
                                                "direction" : "forward",
                                                "indexBounds" : {
                                                        "acctsessionid" : [
                                                                "[\"c1d350d83d11d79711f8101d9a54e2c069442c59ce1d29c5a1764b8c4fb198d38255c93d49d9a16e\", \"c1d350d83d11d79711f8101d9a54e2c069442c59ce1d29c5a1764b8c4fb198d38255c93d49d9a16e\"]"
                                                        ]
                                                },
                                                "keysExamined" : 1,
                                                "dupsTested" : 0,
                                                "dupsDropped" : 0,
                                                "seenInvalidated" : 0,
                                                "matchTested" : 0
                                        }
                                }
                        }
                },
                "feedback" : {
                        "nfeedback" : 20,
                        "averageScore" : 1.0876999999999997,
                        "stdDevScore" : 0.12234012123239821,
                        "scores" : [
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.0002
                                },
                                {
                                        "score" : 1.2502
                                },
                                {
                                        "score" : 1.0002
                                }
                        ]
                },
                "filterSet" : false
        },
        {
                "details" : {
                        "solution" : "(whole index scan solution: dir=-1; tree=Leaf { _id: 1 }, pos: 0\n)"
                },
                "reason" : {
                        "score" : 1.0003,
                        "stats" : {
                                "stage" : "LIMIT",
                                "nReturned" : 0,
                                "executionTimeMillisEstimate" : 0,
                                "works" : 4,
                                "advanced" : 0,
                                "needTime" : 4,
                                "needFetch" : 0,
                                "saveState" : 0,
                                "restoreState" : 0,
                                "isEOF" : 0,
                                "invalidates" : 0,
                                "limitAmount" : 1,
                                "inputStage" : {
                                        "stage" : "FETCH",
                                        "filter" : {
                                                "acctsessionid" : {
                                                        "$eq" : "c1d350d83d11d79711f8101d9a54e2c069442c59ce1d29c5a1764b8c4fb198d38255c93d49d9a16e"
                                                }
                                        },
                                        "nReturned" : 0,
                                        "executionTimeMillisEstimate" : 0,
                                        "works" : 4,
                                        "advanced" : 0,
                                        "needTime" : 4,
                                        "needFetch" : 0,
                                        "saveState" : 0,
                                        "restoreState" : 0,
                                        "isEOF" : 0,
                                        "invalidates" : 0,
                                        "docsExamined" : 4,
                                        "alreadyHasObj" : 0,
                                        "inputStage" : {
                                                "stage" : "IXSCAN",
                                                "nReturned" : 4,
                                                "executionTimeMillisEstimate" : 0,
                                                "works" : 4,
                                                "advanced" : 4,
                                                "needTime" : 0,
                                                "needFetch" : 0,
                                                "saveState" : 0,
                                                "restoreState" : 0,
                                                "isEOF" : 0,
                                                "invalidates" : 0,
                                                "keyPattern" : {
                                                        "_id" : 1
                                                },
                                                "indexName" : "_id_",
                                                "isMultiKey" : false,
                                                "direction" : "backward",
                                                "indexBounds" : {
                                                        "_id" : [
                                                                "[MaxKey, MinKey]"
                                                        ]
                                                },
                                                "keysExamined" : 4,
                                                "dupsTested" : 0,
                                                "dupsDropped" : 0,
                                                "seenInvalidated" : 0,
                                                "matchTested" : 0
                                        }
                                }
                        }
                },
                "feedback" : {
 
                },
                "filterSet" : false
        }
]

Comment by Ramon Fernandez Marina [ 22/May/15 ]

carl.dong@windfindtech.com, a colleague points out that removing the sort may not be a good idea, so I think the best workaround in this cases is for you to hint on the "acctsessionid_1" index.

Before you do that I'd like to ask you to run the test below though. My suspicion is that when querying for a given acctsessionid we consider the "acctsessionid_1" and the "_id" indexes, the query chooses to use "_id" (because it happens to be faster for this particular query), and this query plan gets cached. The next query on acctsessionid then uses the "_id" index, which may be less optimal than "acctsessionid_1" for this second query.

Can you please run the code below and send us the output? I hope this helps us narrow down the root cause of the behavior you're seeing.

// Save current logLevel, bump logLevel to 2
var oldLogLevel = db.adminCommand({getParameter:1, logLevel:1}).logLevel
db.adminCommand( { setParameter: 1, logLevel: 2 } ) 
 
db.RadiusAccount.getPlanCache().listQueryShapes()
 
db.RadiusAccount.find({ acctsessionid: "90-3C-92-C2-EA-38-9659892E" }).sort({ _id: -1 }).explain(true)
db.RadiusAccount.getPlanCache().getPlansByQuery({ acctsessionid: "90-3C-92-C2-EA-38-9659892E" }, {}, { _id : -1})
 
db.RadiusAccount.find({ acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64" }).sort({ _id: -1 }).explain)true)
db.RadiusAccount.getPlanCache().getPlansByQuery({acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64}, {}, { _id : -1})
 
// Reset logLevel
db.adminCommand( { setParameter: 1, logLevel: oldLogLevel } ) 

You'll notice that the code above also increases logging verbosity while the commands are run, so please also post the logs produced when running this test to help with the diagnosis.

Thanks,
Ramón.

Comment by carl dong [ 22/May/15 ]

Will try for that ,and keep you update.
Actually in most time , we got only 1 line with the acctsessionid , but as you see the log , the longer query creates a global lock the for a long time , wiredTiger is telling as a document level locking engine ,then in what situation will cause the global write lock ? Btw is there any way to trace on lock , open cursors and capture the long query execution plan at that moment?

keyUpdates:0 writeConflicts:0 numYields:35862 reslen:707 locks:{ Global: { acquireCount: { w: 35864 } }, 
Database: { acquireCount: { w: 35864 } }, Collection: { acquireCount: { w: 35863 } }, oplog: { acquireCount: { w: 1 } } } 12341ms

Comment by Ramon Fernandez Marina [ 21/May/15 ]

carl.dong@windfindtech.com, I believe the issue is related to cached plans for queries, but I'm still working on a reproducer. In the meantime I suggest you remove the sort in your query, as that may affect query plan selection. Could you do this and let us know if the issue goes away or persists?

Thanks,
Ramón.

Comment by carl dong [ 21/May/15 ]

I restarted the mongod service and queries works well in 2 days , but it happend today again , it only happens on this query , others are working good .
BTW, there are millions operations on RadiusAccount collection, and this issue causes lots of timeout operations, need to be solved.

Comment by carl dong [ 18/May/15 ]

Sure, I have some indexes build on the collection.

"indexSizes" : {
"id" : 48078848,
"username_1_stoptime_1" : 135180288,
"acctsessionid_1" : 397062144,
"starttime_1" : 37175296,
"stoptime_1" : 44113920,
"userlocation_1_stoptime_1" : 69537792

and Count in the collection:

PRIMARY> db.RadiusAccount.count()
4782765

Comment by Ramon Fernandez Marina [ 18/May/15 ]

Can you please post the list of indexes available in your RadiusAccount collection?

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