Closed Bug 1206346 Opened 11 years ago Closed 10 years ago

Intermittent performance-timeline.https.html | User Timing - assert_greater_than: expected a number greater than 99 but got 98.98500000000001

Categories

(Core :: DOM: Service Workers, defect)

Product:
Core
Component:
DOM: Service Workers
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla47
Tracking Flags:
Tracking Status
firefox43 --- wontfix
firefox44 --- wontfix
firefox45 --- wontfix
firefox46 --- fixed
firefox47 --- fixed
firefox-esr45 --- fixed

People

(Reporter: philor, Assigned: bkelly)

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 2 obsolete files)

Widen the fuzzy timer duration check in performance-timeline.https.html. r=jdm
2.95 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
P2 Back out Date.now() comparison to Performance.now() measurements. r=jdm
2.70 KB, patch
jdm
: review+
Details | Diff | Splinter Review
No description provided.
Attached patch bug1206346_fuzzytimer.patch (obsolete) — — Splinter Review
We already treat the duration as a fuzzy value since timers are not precise. Looks like we're just not flexible enough, though, since sometimes we miss the fuzzy match by 0.1 or so. Lets widen it and be a little more explicit about what we are doing. https://treeherder.mozilla.org/#/jobs?repo=try&revision=ff260a88b1bd
Assignee: nobody → bkelly
Status: NEW → ASSIGNED
Attachment #8719182 - Flags: review?(josh)
Josh has asked for some additional information: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ee753256b0f4
Here is a case that shows 99ms elapsed using Date.now(): https://treeherder.mozilla.org/logviewer.html#?job_id=16866225&repo=try#L163522 This comment suggests timers can run early on workers: https://dxr.mozilla.org/mozilla-central/source/dom/workers/WorkerPrivate.cpp#5943 How would you like me to proceed? I could narrow the window a bit from the 5ms to something more like 1.5ms.
Flags: needinfo?(josh)
And it seems our timers do indeed do some rounding such that they can fire early: https://dxr.mozilla.org/mozilla-central/source/xpcom/threads/TimerThread.cpp#548 https://dxr.mozilla.org/mozilla-central/source/xpcom/threads/TimerThread.cpp#551 The accuracy of the timer is dependent on the platform. https://dxr.mozilla.org/mozilla-central/source/xpcom/threads/TimerThread.cpp#424 The interval resolution on my win10 machine is 500us. With the rounding down in the timer and the fuzzing in the performance API it seems reasonable we could end up just over 1ms early.
Automation seems to have the same resolution.
Ok, in that case let's modify the fuzziness to be as large as we expect but no larger.
Flags: needinfo?(josh)
I narrowed the fuzzy range to 1.5ms. I don't have confidence in my ability to trace all the rounding going on to go below that. I also added an additional check against Date.now(). In general the two measurements should always round to the same integral number of milliseconds.
Attachment #8719182 - Attachment is obsolete: true
Attachment #8719182 - Flags: review?(josh)
Attachment #8720937 - Flags: review?(josh)
Attachment #8720937 - Flags: review?(josh) → review+
Hmm, my assertion that rounding the performance measurement should equal the date measurement is wrong. With the fuzzy performance measurement they can sometimes be off by 1. I'll use assert_approx_equals().
More tweaks to the Date.now() measurement assert: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d6b5e61aebf4
https://treeherder.mozilla.org/logviewer.html#?job_id=22058487&repo=mozilla-inbound "User Timing - assert_approx_equals: expected 150 +/- 1 but got 100"
Keywords: leave-open
50ms difference between performance.now() and Date.now() in comment 50. Did GC hit at just before setting endDate?
And then in this case it got 82 instead of 100: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=22062808 I think trying to compare Date.now() to performance.now() is a bad idea. According to MDN Date.now() reflects NTP changes while performance.now() does not. I don't think we can rely on the clocks being directly comparable. I file a follow-up to remove the Date.now() comparison logic.
Remove the comparison between Date.now() and performance.now() measurements. I don't think they are reliable in automation for these reasons: 1) A GC could happen between the performance.now() and the Date.now() skewing numbers. Particularly on debug builds any unexpected work is going to create large differences. 2) According to MDN, Date.now() reflects NTP changes while performance.now() does not. Virtualized hardware often requires clock tweaks to keep things in sync, so I think we might hit this semi-frequently in automation.
Attachment #8721660 - Flags: review?(josh)
Attachment #8721660 - Flags: review?(josh) → review+
https://hg.mozilla.org/mozilla-central/rev/406ee0a64991
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
status-firefox47: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla47
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: