Closed Bug 855058 Opened 7 years ago Closed 7 years ago

Intermittent browser/dom/tests/browser/browser_ConsoleAPITests.js | timer duration is positive

Categories

(DevTools :: Console, defect)

x86
Windows 8
defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
Firefox 23

People

(Reporter: RyanVM, Assigned: msucan)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

https://tbpl.mozilla.org/php/getParsedLog.php?id=21101858&tree=Mozilla-Inbound

WINNT 6.2 mozilla-inbound opt test mochitest-browser-chrome on 2013-03-26 04:16:43 PDT for push 58d7293faaff
slave: t-w864-ix-049

04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | timer.name matches
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | timer.started exists
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | correct arg 0
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | found #test-timeEnd button
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | found correct window by window ID
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | expected level received
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | we have arguments
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | filename matches
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | lineNumber matches
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | functionName matches
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | arguments.length matches
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | timer name matches
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | timer duration is a number
04:37:55  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | timer duration is positive
04:37:55     INFO -  Stack trace:
04:37:55     INFO -      JS frame :: chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js :: testConsoleTimeEnd :: line 329
04:37:55     INFO -      JS frame :: chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js :: CO_observe :: line 296
04:37:55     INFO -      JS frame :: resource://gre/components/ConsoleAPI.js :: CA_notifyObservers :: line 330
04:37:55     INFO -      JS frame :: resource://gre/components/ConsoleAPI.js :: CA__processQueuedItem :: line 306
04:37:55     INFO -      JS frame :: resource://gre/components/ConsoleAPI.js :: CA__timerCallback :: line 234
04:37:55     INFO -      native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | correct arg 0
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | found #test-namelessTimer button
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | found correct window by window ID
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | expected level received
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | we don't have arguments
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | we don't have a timer
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | functionName matches
04:37:55     INFO -  TEST-PASS | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | lineNumber matches
04:37:55     INFO -  INFO TEST-END | chrome://mochitests/content/browser/dom/tests/browser/browser_ConsoleAPITests.js | finished in 395ms
Going to attempt a fix in bug 808370 for this intermittent failure. Albeit, I'm surprised this started failing. Maybe there's a bug outside of the console code. We'll see.
Assignee: nobody → mihai.sucan
Status: NEW → ASSIGNED
Depends on: 808370
Bug 808370 landed. It includes a potential fix for this intermittent failure.
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 23
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Boris: this intermittent failure shows a -2 ms negative timer duration, which is odd. I remember we talked once about Date.now() not being a very reliable way to timestamp messages (for example, system dates can change). Do you know how we can get a negative duration on build servers?

It looks to me this test shouldn't really check for a strictly positive timer duration. As I understand things, here we have some options:

1. max(0, duration) so we avoid negative timers. Not a good idea, because it would be ideal to tell the user how much time has passed between the time() and timeEnd() calls, even if the user changes the system date.

2. allow negative duration.

3. use something different than Date.now(). Is there a way to get something like a system date-independent timestamp?

I see on MDN [1] that Windows systems have a 15ms resolution. That might be unrelated, but these test failures only occur on Win8.

Do you have any suggestions here? Thanks!


[1] https://developer.mozilla.org/en-US/docs/JavaScript/Reference/Global_Objects/Date/now
Flags: needinfo?(bzbarsky)
I don't know what exactly generates this .duration member, but if you just need monotonically nondecreasing time, can you use performance.now() on some window?
Flags: needinfo?(bzbarsky)
(In reply to Boris Zbarsky (:bz) from comment #10)
> I don't know what exactly generates this .duration member, but if you just
> need monotonically nondecreasing time, can you use performance.now() on some
> window?

Thank you! I didn't know we have something like that. Will submit a patch.
Attached patch proposed patchSplinter Review
This is a bit "heavy" for an intermittent test failure fix, however I think our timers are not accurate enough. I changed console.time() and timeEnd() to use performance.now(). We should always have positive durations. This also adds sub-millisecond timer accuracy.

I think timerRegistry is better implemented with a Map, rather than an Object. I've included changes to this effect.

Rob: please let me know if any other changes are needed.

Try push: https://tbpl.mozilla.org/?tree=Try&rev=d1798727301b
Attachment #743763 - Flags: review?(rcampbell)
Comment on attachment 743763 [details] [diff] [review]
proposed patch

Review of attachment 743763 [details] [diff] [review]:
-----------------------------------------------------------------

nice cleanup.
Attachment #743763 - Flags: review?(rcampbell) → review+
Thank you!

Landed:
https://hg.mozilla.org/integration/fx-team/rev/754c2079bde8
Whiteboard: [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/754c2079bde8
Status: REOPENED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.