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