Closed Bug 874425 Opened 6 years ago Closed 6 years ago

Intermittent test_osfile_async.xul | duration: Operation duration time was updated correctly with a numeric value., | duration: OS.File.writeAtomic: Operation duration time is non-negative

Categories

(Toolkit :: OS.File, defect)

x86
Windows XP
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla26
Tracking Status
firefox24 --- fixed
firefox25 --- fixed
firefox26 --- fixed

People

(Reporter: RyanVM, Assigned: Yoric)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 4 obsolete files)

Appears to be a new failure on the iX test slaves (significantly faster than the rev3 Mac Minis they're replacing).

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

Windows XP 32-bit mozilla-inbound pgo test mochitest-other on 2013-05-20 21:30:09 PDT for push c750d5d003dd
slave: t-xp32-ix-046

22:35:14     INFO -  15492 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/components/osfile/tests/mochi/test_osfile_async.xul | system_shutdown: Log message observation promise was rejected as expected.
22:35:14     INFO -  15493 INFO TEST-INFO | chrome://mochitests/content/chrome/toolkit/components/osfile/tests/mochi/test_osfile_async.xul | system_shutdown: Complete
22:35:14     INFO -  15494 INFO TEST-INFO | chrome://mochitests/content/chrome/toolkit/components/osfile/tests/mochi/test_osfile_async.xul | duration: Entering
22:35:14     INFO -  15495 INFO TEST-INFO | chrome://mochitests/content/chrome/toolkit/components/osfile/tests/mochi/test_osfile_async.xul | duration: This was a promise
22:35:14     INFO -  15496 INFO TEST-INFO | chrome://mochitests/content/chrome/toolkit/components/osfile/tests/mochi/test_osfile_async.xul | duration: Gathered method duration time: -16 MS
22:35:14     INFO -  15497 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/components/osfile/tests/mochi/test_osfile_async.xul | duration: Operation duration time was updated correctly with a numeric value.
So we have a negative duration. That's certainly unexpected. Investigating.
Trivial patch to add a little more logging.
Attachment #753695 - Flags: review+
Keywords: checkin-needed
Whiteboard: [leave open]
Summary: Intermittent test_osfile_async.xul | duration: Operation duration time was updated correctly with a numeric value. → Intermittent test_osfile_async.xul | duration: Operation duration time was updated correctly with a numeric value., | duration: OS.File.writeAtomic: Operation duration time is non-negative
No longer depends on: 903707
(In reply to David Rajchenbach Teller [:Yoric] <on PTO, I'll be back on Thursday, August 22nd> from comment #4)

Is the extra logging providing any useful info?
Flags: needinfo?(dteller)
Not really.

What we know:
- this problem is not limited to one specific operation (it affects OS.File.{copy, read, writeAtomic});
- this problem appears limited to Windows;
- when the problem appears, duration is always -15ms or -16ms;
- when the problem does not appear, duration is always +1ms or +2ms.

Given that this time is measured through two successive calls to Date.now() in the same thread, I'm a bit at a loss.
Flags: needinfo?(dteller)
Attached patch Yet more logging (obsolete) — Splinter Review
Adding yet more logging...
Attachment #794237 - Flags: review+
I think Date isn't guaranteed to be monotonic. performance.now() usually provides higher resolution results and should also be monotonic.

performance.now() is 0 sometime during the page load, and then only progresses.
Do we have performance.now() in workers?
Attachment #753695 - Attachment description: A little more logging to improve readability → A little more logging to improve readability (already checked in)
I confirm that performance.now() is not available in workers (just filed bug 908390). Also, it might be useful to add a sanity check and discard negative durations in the code.
Attachment #753695 - Attachment description: A little more logging to improve readability (already checked in) → A little more logging to improve readability
Attachment #753695 - Flags: checkin+
Attachment #794237 - Flags: checkin+
https://hg.mozilla.org/integration/fx-team/rev/816c1730c8ec
Keywords: checkin-needed
Whiteboard: [leave open] → [leave open][fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/816c1730c8ec
Whiteboard: [leave open][fixed-in-fx-team] → [leave open]
Attached patch Wallpaper fix (obsolete) — Splinter Review
Attachment #795425 - Flags: review?(nfroyd)
Comment on attachment 795425 [details] [diff] [review]
Wallpaper fix

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

r=me.  Do you want the changes in main_test_osfile_async.js, or were those just debugging changes that got qref'd into your patch?
Attachment #795425 - Flags: review?(nfroyd) → review+
These changes are intentional, because I believe that they make sense. However, I should not have added them in the patch as they have already been checked-in by the previous patch.
Attached patch Wallpaper fix, v2 (obsolete) — Splinter Review
Removing code that has already been checked in.
Assignee: nobody → dteller
Attachment #795425 - Attachment is obsolete: true
Attachment #795428 - Flags: review+
https://hg.mozilla.org/integration/fx-team/rev/487e7ea49182
Flags: in-testsuite+
Keywords: checkin-needed
Whiteboard: [leave open] → [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/487e7ea49182
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → mozilla26
This test failed in this try push: https://tbpl.mozilla.org/?tree=Try&rev=e122cba93bab
I'm not sure it's really a problem because this try push looks weird.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Ah, there's a typo in my fix.
Typo fix
Attachment #753695 - Attachment is obsolete: true
Attachment #794237 - Attachment is obsolete: true
Attachment #795428 - Attachment is obsolete: true
Attachment #797716 - Flags: review+
Duplicate of this bug: 911036
Flags: needinfo?(ryanvm)
https://hg.mozilla.org/mozilla-central/rev/f6d60cfe074c
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.