Closed Bug 855058 Opened 12 years ago Closed 12 years ago

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

Categories

(DevTools :: Console, defect)

Product:
DevTools
Component:
Console
Platform:
x86
Windows 8
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED
Milestone:
Firefox 23

People

(Reporter: RyanVM, Assigned: msucan)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

proposed patch
7.42 KB, patch
rcampbell
: review+
Details | Diff | Splinter Review
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: 12 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 patch — — Splinter 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: 12 years ago → 12 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.

Attachment

General

Creator:
Created:
Updated:
Size: