[SERVER-19312] Field 'executionTimeMillis' missing from explain execution stats output Created: 24/Apr/15  Updated: 05/Feb/16  Resolved: 08/Jul/15

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: None
Fix Version/s: 3.1.6

Type: Bug Priority: Minor - P4
Reporter: Spencer Brody (Inactive) Assignee: Qingyang Chen
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: HTML File explain2.js.html    
Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Quint Iteration 4, Quint Iteration 5, Quint Iteration 6
Participants:

 Description   

22596ecf7f OS X 10.8 jsCore
task failure
logs

	
assert: undefined is not greater than 4500 : undefined
Error: undefined is not greater than 4500 : undefined
    at Error (<anonymous>)
    at doassert (src/mongo/shell/assert.js:11:14)
    at Function.assert.gt (src/mongo/shell/assert.js:295:5)
    at /data/mci/shell/src/jstests/core/explain2.js:24:8
2015-04-24T09:42:37.311-0400 E QUERY    Error: undefined is not greater than 4500 : undefined
    at Error (<anonymous>)
    at doassert (src/mongo/shell/assert.js:11:14)
    at Function.assert.gt (src/mongo/shell/assert.js:295:5)
    at /data/mci/shell/src/jstests/core/explain2.js:24:8 at src/mongo/shell/assert.js:13
failed to load: /data/mci/shell/src/jstests/core/explain2.js



 Comments   
Comment by Githook User [ 08/Jul/15 ]

Author:

{u'username': u'coollog', u'name': u'Qingyang Chen', u'email': u'qingyang.chen@10gen.com'}

Message: SERVER-19312 execution stats output to handle negative executionTimeMillis correctly
Branch: master
https://github.com/mongodb/mongo/commit/659b6566c4251714ae95b7f249bf7ff3851f1aaf

Comment by J Rassi [ 06/Jul/15 ]

Q, I think you're confusing the following two facts:

  1. Explain::generateExecStats() has a parameter 'totalTimeMillis' with a default value of -1 (this is correct: the sentinel value -1 in this context denotes that the approximate elapsed time should be used instead of the actual elapsed time).
  2. Explain::explainStages() calls CurOp::elapsedMillis() without checking whether or not the returned value is negative (this is not correct: a negative value in this context means that the system time went backwards).

I believe that my analysis above is correct; let me know if you're still confused even after reading this clarification.

Comment by Qingyang Chen [ 06/Jul/15 ]

It seems that Explain::generateExecStats already handles negative values for totalTimeMillis, so would it be better to just change the core/explain2.js to use explain.executionStats.executionTimeMillisEstimate if explina.executionStats.executionTimeMillis is not defined?

Comment by Spencer Brody (Inactive) [ 29/Apr/15 ]

Changing priority to "minor" to get it out of the "needs triage" bucket in the buildbaron dashboard.

Comment by J Rassi [ 28/Apr/15 ]

The root cause of this failure is that Explain::explainStages() does not expect CurOp::elapsedMillis() to return a negative value. I conclude that, during execution of this test, this machine's system administrator (or a script) set the system clock to be earlier than the current time.

I would recommend the following as a fix:

  • Change Explain::explainStages() to specially handle a negative value from elapsedMillis().
  • Document the CurOp "elapsed time" methods as able to return negative values.
  • Document curTimeMicros64() and friends as being able to return decreasing values in consecutive calls from the same thread.

As an alternative, we could make the CurOp "elapsed time" methods return an elapsed time of zero if the second call to curTimeMicros64() returns a smaller value than the first call.

Comment by Spencer Brody (Inactive) [ 28/Apr/15 ]

Bumping to critical even though the test hasn't failed again in a while because they way it failed was that explain was missing an expected field, which seems bad and probably worth looking into.

Comment by Spencer Brody (Inactive) [ 24/Apr/15 ]

Looks like the explain output has executionTimeMillisEstimate but not executionTimeMillis for some reason?

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