Closed Bug 874425 Opened 11 years ago Closed 11 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 Graveyard :: OS.File, defect)

Product:
Toolkit Graveyard
Component:
OS.File
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox24 fixed, firefox25 fixed, firefox26 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla26
Tracking Flags:
Tracking Status
firefox24 --- fixed
firefox25 --- fixed
firefox26 --- fixed

People

(Reporter: RyanVM, Assigned: Yoric)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 4 obsolete files)

Wallpaper typo fix
1.41 KB, patch
Yoric
: review+
Details | Diff | Splinter Review 
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: 11 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+

    
  
Flags: needinfo?(ryanvm)

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/f6d60cfe074c
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → FIXED

    
  
Product: Toolkit → Toolkit Graveyard

          You need to log in
          before you can comment on or make changes to this bug.
        






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: