[SERVER-10995] Elapsed time for $maxTimeMS queries includes time to acquire db lock Created: 01/Oct/13 Updated: 11/Jul/16 Resolved: 14/Nov/13 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Diagnostics |
| Affects Version/s: | 2.5.2 |
| Fix Version/s: | 2.5.4 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | J Rassi | Assignee: | J Rassi |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||
| Operating System: | ALL | ||||||||
| Participants: | |||||||||
| Description |
|
If a query needs to wait to acquire a database read lock, its reported elapsed time will be higher if it uses $maxTimeMS than if it does not. This is due to the fact that the $maxTimeMS implementation queries the operation for its start time at the beginning of runQuery(), but the act of doing so has the side effect of actually setting the start time for the operation. Since operations generally don't set their start time until right after they acquire a database lock for the first time, operations that specify $maxTimeMS will appear in logs to take longer to execute, even though they haven't. A fix would fall under either of: 1) all queries should include time to acquire first lock: call CurOp::ensureStarted() in assembleResponse() or receivedQuery(). — Reproduce with: $ mongo --eval 'db.adminCommand({sleep:1,secs:2}).ok' & sleep 1 && mongo --eval 'db.runCommand({dbStats:1,maxTimeMS:0})' The above generates two dbStats commands, each of which wait 1 second for a lock and then run in 0ms, but have completely different reported elapsed times: 2013-11-13T02:27:06.577-0500 [conn12] command test.$cmd command: { dbStats: 1.0, maxTimeMS: 0.0 } ntoreturn:1 keyUpdates:0 locks(micros) r:345 reslen:247 0ms |
| Comments |
| Comment by Githook User [ 14/Nov/13 ] |
|
Author: {u'username': u'jrassi', u'name': u'Jason Rassi', u'email': u'rassi@10gen.com'}Message: |