[SERVER-41172] update slow down Created: 16/May/19  Updated: 20/May/19  Resolved: 20/May/19

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

Type: Question Priority: Major - P3
Reporter: shawn Assignee: Eric Sedor
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Participants:

 Description   

HI

I found many slow updates from  mongodb log ,as following:

2019-05-16T18:12:56.514+0800 I COMMAND [conn1931352] command db.$cmd command: update { update: "table", ordered: true, writeConcern:

{ j: true }

, updates: [ { q:

{ _id: ObjectId('5cd6e558d12f840077d79eb9') }

, u: { _id: ObjectId('5cd6e558d12f840077d79eb9'), im: "ebca3a98c70b8de169f2231195ca4f24", h: "www.aaaa.cc", nm: "nm-string", ch: "string", u: "html_addr", s: 1, ut: 1558001574941 }, upsert: true } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount:

{ r: 2, w: 2 }

}, Database: { acquireCount:

{ w: 2 }

}, Collection: { acquireCount:

{ w: 1 }

}, Metadata: { acquireCount:

{ w: 1 }

}, oplog: { acquireCount:

{ w: 1 }

} } protocol:op_query 1571ms

but  i saw the secton of  locks ,  cound't find anything valuable .

version of mongodb is  3.4.17 

how can i  found   this 1571ms      costed by which section of mongodb.



 Comments   
Comment by Eric Sedor [ 20/May/19 ]

As you've noted, log lines include the overall operation time and time spent waiting on locks. [Explain\https://docs.mongodb.com/manual/reference/method/cursor.explain/] is available for observing the work queries do and additional logging verbosity will also provide more detailed information.

We're going to go ahead and close this ticket. If you have any questions about these features we encourage you to ask our community by posting on the mongodb-user group or on Stack Overflow with the mongodb tag.

Comment by shawn [ 17/May/19 ]

HI

sadly to  hear that, this case  occurs  almostly every two minites in my production env.

and mongo doesn't  tell me the time  used by which section or functions , i've no idea  about  how to do more investigating.

I think  ,for the convenience of investiagating ,we shoud add  time used detail  to  mongo log.

Comment by Eric Sedor [ 17/May/19 ]

Hi shawn001;

The SERVER project is for bugs and feature suggestions for the MongoDB server. For initial assistance troubleshooting slow updates and interpreting diagnostic information, I encourage you to ask our community by posting on the mongodb-user group or on Stack Overflow with the mongodb tag.

If I've misunderstood and you have reason to suspect a bug, please let us know.

Thank you!

Comment by shawn [ 16/May/19 ]

explain msg as following:

 

"executionStats" : {
"executionSuccess" : true,
"nReturned" : 0,
"executionTimeMillis" : 0,
"totalKeysExamined" : 1,
"totalDocsExamined" : 1,
"executionStages" : {
"stage" : "UPDATE",
"nReturned" : 0,
"executionTimeMillisEstimate" : 0,
"works" : 2,
"advanced" : 0,
"needTime" : 1,
"needYield" : 0,
"saveState" : 0,
"restoreState" : 0,
"isEOF" : 1,
"invalidates" : 0,
"nMatched" : 1,
"nWouldModify" : 1,
"nInvalidateSkips" : 0,
"wouldInsert" : false,
"fastmodinsert" : false,
"inputStage" :

{ "stage" : "IDHACK", "nReturned" : 1, "executionTimeMillisEstimate" : 0, "works" : 1, "advanced" : 1, "needTime" : 0, "needYield" : 0, "saveState" : 1, "restoreState" : 1, "isEOF" : 1, "invalidates" : 0, "keysExamined" : 1, "docsExamined" : 1 }

}
}

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