[SERVER-14334] Possible double-counting of timeLockedMicros Created: 23/Jun/14  Updated: 20/Jun/16  Resolved: 20/Jun/16

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

Type: Bug Priority: Minor - P4
Reporter: Greg Murphy Assignee: Unassigned
Resolution: Done Votes: 0
Labels: polish
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to SERVER-7994 system.profile reports higher timeLoc... Closed
Operating System: ALL
Participants:

 Description   

I've observed what appear to be strange lock time values in my mongod log file.

I've got entries for two separate collections, col1 (no indexes apart from on _id) and col2 (index on _id plus two further indexes, one on a single key and one a compound on two keys - both ascending). For example:

2014-06-16T16:15:55.690+0000 [conn441056] insert dbname.col1 ninserted:2 keyUpdates:0 numYields:0 locks(micros) w:106859 106ms
2014-06-16T16:28:55.608+0000 [conn441056] insert dbname.col2 ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:237838 119ms

The vast majority of my col1 log entries show the write lock time to be either almost identical to, or significantly less than, the query time. However, the vast majority of my col2 entries show the write lock time to be double the query execution time.

I've tried profiling these queries and can see that the time is taken up in timeLocked not timeAcquiring, for example:
{ "op" : "insert", "ns" : "dbname.col2", "ninserted" : 1, "keyUpdates" : 0, "numYield" : 0, "lockStats" : { "timeLockedMicros" :

{ "r" : NumberLong(0), "w" : NumberLong(1186366) }

, "timeAcquiringMicros" :

{ "r" : NumberLong(0), "w" : NumberLong(51) }

}, "millis" : 593, "execStats" : { }, "ts" : ISODate("2014-06-20T16:33:55.763Z"), "client" : "10.0.4.4", "allUsers" : [ ], "user" : "" }

I know from the documentation that timeLockedMicros can be larger than mills due to locks on the oplog, but it seems strange that timeLockedMicros is only double on one of the two collections.

This behaviour has been observed on MongoDB 2.6.0 (mongodb-org package) on Ubuntu 13.04 64-bit.



 Comments   
Comment by Ian Whalen (Inactive) [ 20/Jun/16 ]

The locking code was entirely rewritten for 3.0 and the statistics code has undergone a complete rewrite as well. Please re-open if you believe that the current version is still exhibiting problematic behavior.

Comment by Matt Kangas [ 28/Jun/14 ]

Hi gregmurphy,

Based on my reading of previous tickets, this appears to be working correctly but I agree it is confusing. db.currentOp() displays more detail about locks than profiling will reveal. The additional time goes to recursive locks taken for "extra system" work.

If there are specific queries that you would like an explanation for, please try to capture both the profile and currentOp values and I'll be happy to help.

We are reworking how locking works currently in 2.7. I will leave this ticket as a request for more clarity in profile entries about lock utilization.

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