[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:
Related
related to SERVER-2212 Server automatically abort queries/co... Closed
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().
2) all queries should not include time to acquire first lock: make CurOp::startTime() take an optional bool "reset", add logic to MaxTimeTracker to handle case where the currently-tracked operation "has not started yet".

Reproduce with:

$ mongo --eval 'db.adminCommand({sleep:1,secs:2}).ok' & sleep 1 && mongo --eval 'db.runCommand({dbStats:1,maxTimeMS:0})'
$ mongo --eval 'db.adminCommand({sleep:1,secs:2}).ok' & sleep 1 && mongo --eval 'db.runCommand({dbStats:1,maxTimeMS:60*1000})'

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
2013-11-13T02:27:10.191-0500 [conn14] command test.$cmd command: { dbStats: 1.0, maxTimeMS: 60000.0 } ntoreturn:1 keyUpdates:0 locks(micros) r:354 reslen:247 1000ms



 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: SERVER-10995 Leave CurOp::_start untouched when setting maxTimeMS
Branch: master
https://github.com/mongodb/mongo/commit/a87e0ed4ec30725e3ffd7de75c0f204ca0f42b45

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