Closed Bug 700077 Opened 8 years ago Closed 5 years ago

Intermittent test_smilDynamicDelayedBeginElement.xhtml | insertion of first animation element should have triggered a synchronous sample and updated our current time - didn't expect 0, but got it and | after rewinding to 0, our beginElement()-generated...

Categories

(Core :: SVG, defect)

x86
Windows XP
defect
Not set

Tracking

()

RESOLVED WORKSFORME
mozilla11

People

(Reporter: philor, Assigned: dholbert)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Yay for long test filenames and verbose error messages!

https://tbpl.mozilla.org/php/getParsedLog.php?id=7234201&tree=Firefox
Rev3 WINNT 5.1 mozilla-central opt test mochitests-1/5 on 2011-11-05 14:16:11 PDT for push ae228e329b42

88110 INFO TEST-START | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml
88111 INFO Error: Unable to restore focus, expect failures and timeouts.
88112 INFO TEST-PASS | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | even though we've allowed time to pass, we shouldn't have bothered updating the current time, since there aren't any animation elements - 0 should equal 0
88113 ERROR TEST-UNEXPECTED-FAIL | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | insertion of first animation element should have triggered a synchronous sample and updated our current time - didn't expect 0, but got it
88114 INFO TEST-PASS | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | inserted animation shouldn't have affected its targeted attribute, since it doesn't have any intervals yet - 500px should equal 500px
88115 INFO TEST-PASS | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | beginElement() should activate our animation & set its 'from' val - 20px should equal 20px
88116 ERROR TEST-UNEXPECTED-FAIL | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | after rewinding to 0, our beginElement()-generated interval shouldn't be active yet - got 20px, expected 500px
88117 INFO TEST-END | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | finished in 3086ms
Previously, on Misstarred Inbound:

https://tbpl.mozilla.org/php/getParsedLog.php?id=7228241&tree=Mozilla-Inbound
Rev3 WINNT 5.1 mozilla-inbound opt test mochitests-1/5 on 2011-11-05 06:31:43 PDT for push fdcef240a8a7

88118 INFO TEST-START | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml
88119 INFO Error: Unable to restore focus, expect failures and timeouts.
88120 INFO TEST-PASS | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | even though we've allowed time to pass, we shouldn't have bothered updating the current time, since there aren't any animation elements - 0 should equal 0
88121 ERROR TEST-UNEXPECTED-FAIL | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | insertion of first animation element should have triggered a synchronous sample and updated our current time - didn't expect 0, but got it
88122 INFO TEST-PASS | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | inserted animation shouldn't have affected its targeted attribute, since it doesn't have any intervals yet - 500px should equal 500px
88123 INFO TEST-PASS | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | beginElement() should activate our animation & set its 'from' val - 20px should equal 20px
88124 ERROR TEST-UNEXPECTED-FAIL | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | after rewinding to 0, our beginElement()-generated interval shouldn't be active yet - got 20px, expected 500px
88125 INFO TEST-END | /tests/content/smil/test/test_smilDynamicDelayedBeginElement.xhtml | finished in 3097ms
Hmm. So these test-failures are basically saying "we expected some time to pass since the document-onload-time, but it looks like none has."

I wonder if perhaps the executeSoon() call isn't allowing enough time to pass?  Perhaps we need a setTimeout with an explicit time value (e.g. 100ms) instead...
Blocks: 699143
Observation: so far, the failures are exclusively on WINNT 5.1 (WinXP) opt/pgo.  No other platforms yet, and no debug runs.

At bz's suggestion, I'm think I'm going to create a "new Date()" after SVGLoad, and then wait for the date to advance past that, to be sure that at least 1ms has elapsed since document start time.
Attached patch possible fixSplinter Review
Here's a patch along the lines of prev. comment.

This should hopefully fix this randomorange. (or if it doesn't fix the randomorange, it'll indicate that bug 699143 isn't entirely fixed...)
Comment on attachment 574536 [details] [diff] [review]
possible fix

Looks terrific! Thanks Daniel!
Attachment #574536 - Flags: review?(birtles) → review+
FWIW -- it looks like all the failures since the m-c merge in comment 23 are on other branches, which likely just haven't gotten the fix merged to them yet.

(Comment 24 is a failure on m-c, but it's for a build that started before the fix landed)

So assuming the fix works, we'll stop hitting this on mozilla-central-based branches when they merge in the fix from m-c.

We will need the fix on Aurora, though.  I'll request aurora approval once I'm sure this is fixed on trunk.
OK -- given that we're still hitting this after the "allowTimeToPass()" addition (attachment 574536 [details] [diff] [review]), I think that means bug 699143 or something like it is still legitimately broken, albeit very hard to hit.

We do the following:
 (a) catch SVGLoad (which corresponds to document time 0)
 (b) force at least 10ms to pass (along with using executeSoon which means more time should probably be passing)
 (c) *then* we insert our first <animate> element into the document, which should force a synchronous sample & update the internal "current time"
 (d) then we check that getCurrentTime() is nonzero (which it should be, since we waited for time to pass in (b) and did something that should make us update our timeline in (c))

So either bug 699143 is still semi-broken, or possibly our TimeStamp::Now() is occasionally returning the same value even after time (~10ms) has passed...
(given the low rate of failure, we might need some record-and-replay work to investigate this further)
(In reply to Daniel Holbert [:dholbert] from comment #19)
> Created attachment 574536 [details] [diff] [review]
> possible fix

Whilst this didn't fix the issue entirely, looking at the failure history in OrangeFactor shows it reduced the frequency considerably. Therefore backported to ESR10:
https://hg.mozilla.org/releases/mozilla-esr10/rev/9039d9b0f4f0
Whiteboard: [orange]
Closing bugs where TBPLbot has previously commented, but have now not been modified for >3 months & do not contain the whiteboard strings for disabled/annotated tests or use the keyword leave-open. Filter on: mass-intermittent-bug-closure-2014-07
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.