[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: |
|
||||||||
| 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 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: , "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. |