Closed Bug 580876 Opened 10 years ago Closed 9 years ago

Intermittent failure in test_play_events.html and test_play_events_2.html | Check expected event got canplaythrough at canplay

Categories

(Core :: Audio/Video, defect)

x86
Linux
defect
Not set

Tracking

()

RESOLVED FIXED

People

(Reporter: ehsan, Assigned: cpearce)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1279767863.1279770074.16205.gz
Rev3 Fedora 12x64 mozilla-central debug test mochitests-1/5 on 2010/07/21 20:04:23

47620 INFO TEST-START | /tests/content/media/test/test_play_events.html
WARNING: NS_ENSURE_TRUE(mSuspendCount > 0) failed: file /builds/slave/mozilla-central-linux64-debug/build/netwerk/protocol/http/nsHttpChannel.cpp, line 3030
++DOMWINDOW == 15 (0x8198628) [serial = 1488] [outer = 0x4080010]
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file /builds/slave/mozilla-central-linux64-debug/build/content/base/src/nsContentUtils.cpp, line 2812
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file /builds/slave/mozilla-central-linux64-debug/build/content/base/src/nsContentUtils.cpp, line 2812
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file /builds/slave/mozilla-central-linux64-debug/build/content/base/src/nsContentUtils.cpp, line 2812
WARNING: An error occurred while executing an async statement: 19 constraint failed: file /builds/slave/mozilla-central-linux64-debug/build/toolkit/components/places/src/Helpers.cpp, line 66
47621 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav
47622 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/320x240.ogv
47623 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
47624 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/seek.webm
47625 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav
47626 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at canplay for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav
47627 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/320x240.ogv
47628 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/320x240.ogv
47629 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/320x240.ogv
47630 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
47631 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
47632 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
47633 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at canplaythrough for http://mochi.test:8888/tests/content/media/test/320x240.ogv
47634 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/320x240.ogv
47635 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/320x240.ogv
47636 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/seek.webm
47637 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/seek.webm
47638 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/seek.webm
47639 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at canplaythrough for http://mochi.test:8888/tests/content/media/test/seek.webm
47640 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/seek.webm
47641 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/seek.webm
47642 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at canplaythrough for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
47643 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
47644 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
47645 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/320x240.ogv - "canplaythrough" should equal "canplaythrough"
47646 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/small-shot.ogg - "canplaythrough" should equal "canplaythrough"
47647 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav - "canplaythrough" should equal "canplaythrough"
47648 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/seek.webm - "canplaythrough" should equal "canplaythrough"
47649 INFO SimpleTest finished /tests/content/media/test/test_play_events.html in 5127ms
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1281941651.1281943122.26813.gz
Rev3 MacOSX Snow Leopard 10.6.2 mozilla-central debug test mochitests-1/5 on 2010/08/15 23:54:11
s: talos-r3-snow-038

49843 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events_2.html | Check expected event got canplaythrough at canplay for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav
Summary: Intermittent failure in test_play_events.html | Check expected event got canplaythrough at canplay for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav → Intermittent failure in test_play_events.html and test_play_events_2.html | Check expected event got canplaythrough at canplay for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav
After bug 589467 got fixed, the particular failure in this bug started happening frequently (the majority of mochitest-1 runs) on the Jaegermonkey branch. On JM, it happens mostly on small-shot.ogg, though, instead of r11025_s16_c1.wav. JM has been merged to Tracemonkey and it looks like the same thing is happening there. 

I have not been able to reproduce the failure at all on my desktop Win7 box.

It seems unlikely that we changed anything that directly relates to this. But maybe the test behavior depends on timing, so it got altered by a change in JS perf?
(In reply to comment #20)
> It seems unlikely that we changed anything that directly relates to this. But
> maybe the test behavior depends on timing, so it got altered by a change in JS
> perf?

I'm pretty sure this failure is dependent on the timing of our download, and the interaction of that with the media cache. It's entirely plausible that a change in JS timing affects this, will JM changes affect the timing of xpcshell (which runs httpd.js in mochitest)?

I'll try and have a look at this after the feature freeze.
(In reply to comment #21)
> will JM changes affect the timing of xpcshell
> (which runs httpd.js in mochitest)?

We didn't change xpcshell.cpp, so it won't run the methodjit--it will run with whatever options it did before. (We should probably change that at some point, though.)
Summary: Intermittent failure in test_play_events.html and test_play_events_2.html | Check expected event got canplaythrough at canplay for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav → Intermittent failure in test_play_events.html and test_play_events_2.html | Check expected event got canplaythrough at canplay
So the test which is failing is this one:

ok(tokens[v._state].indexOf(event.type) >= 0,
   "Check expected event got " + event.type + " at " + v._state + " for " + v.src);

The test is failing in several ways:
1. got canplaythrough instead of canplay (e.g. comment 143). This means the last event we received was play, and we expected to receive canplay, but got canplaythrough. This could be an error in the media decoders.
2. got canplay at canplaythrough (e.g. comment 140) 
3. got playing at canplay (e.g. comment 137)
and a few others.

2. and 3. can only happen if the indexOf operation is failing. Take case 3 for example, the ok statement should be:
ok(tokens["canplaythrough"].indexOf("canplay") >= 0, ...)

but that condition is returning false, i.e. indexOf isn't finding "canplay" in the array ["canplay", "canplaythrough"].

It's possible that since indexOf uses the strict equality operator, whatever is stringifying to these strings is actually of an incompatible type, and indexOf could be failing because of a type mismatch. I'm going to check in some debug code to the test in TM to see if that's the case (since I can't reproduce it even remotely reliably locally).
(In reply to comment #144)
> I'm going to check in some debug
> code to the test in TM to see if that's the case (since I can't reproduce it
> even remotely reliably locally).

http://hg.mozilla.org/tracemonkey/rev/557c44a519a7
(In reply to comment #144)
> So the test which is failing is this one:
> 
> ok(tokens[v._state].indexOf(event.type) >= 0,
>    "Check expected event got " + event.type + " at " + v._state + " for " +
> v.src);
> 
> The test is failing in several ways:
> 1. got canplaythrough instead of canplay (e.g. comment 143). This means the
> last event we received was play, and we expected to receive canplay, but got
> canplaythrough. This could be an error in the media decoders.
> 2. got canplay at canplaythrough (e.g. comment 140) 
> 3. got playing at canplay (e.g. comment 137)
> and a few others.
> 
> 2. and 3. can only happen if the indexOf operation is failing. Take case 3 for
> example, the ok statement should be:
> ok(tokens["canplaythrough"].indexOf("canplay") >= 0, ...)
> 
> but that condition is returning false, i.e. indexOf isn't finding "canplay" in
> the array ["canplay", "canplaythrough"].

Interesting. It seems we are getting mostly 2 & 3 as our "extra" failures in JM. On the JM side of this, we optimize expressions of the form |x[y]|, and also x.y for that matter, using ICs, which are more complicated and tend to harbor more bugs. I think I will turn off the optimization for |x[y]| on the JM tinderbox to see if that helps.
Depends on: 594636
(Oh, belatedly realized that you didn't get any debug output for that because it was a events_2 and it's only events that we're looking for.)
(In reply to comment #153)
> philringnalda%gmail.com
> http://tinderbox.mozilla.org/showlog.cgi?log=TraceMonkey/1283997443.1283999407.29085.gz
> Rev3 Fedora 12 tracemonkey debug test mochitests-1/5 on 2010/09/08 18:57:23
> 
> s: talos-r3-fed-021
> 53596 ERROR TEST-UNEXPECTED-FAIL |
> /tests/content/media/test/test_play_events.html | Check expected event got
> canplay at canplaythrough for
> http://mochi.test:8888/tests/content/media/test/small-shot.ogg
> uneval(event.type)="canplay" typeof(event.type)=string
> uneval(v._state)="canplaythrough" typeof(v._state)=string
> tokens[canplaythrough]=playing tokens[canplaythrough].indexOf(event.type)=-1

Shouldn't tokens[canplaythrough] be [canplay,canplaythrough] instead of [playing]? It's that in other cases (you can see in the log, and from test_play_events itself) is there some problem with array literal construction? Does this indicate problems elsewhere in JS?
(In reply to comment #154)
> is there some problem with array literal construction?
> Does this indicate problems elsewhere in JS?

Probably not array literal construction, else other cases in that test would have been bad too.
(In reply to comment #149)
> (In reply to comment #144)
> > So the test which is failing is this one:
> > 
> > ok(tokens[v._state].indexOf(event.type) >= 0,
> >    "Check expected event got " + event.type + " at " + v._state + " for " +
> > v.src);
> > 
> > The test is failing in several ways:
> > 1. got canplaythrough instead of canplay (e.g. comment 143). This means the
> > last event we received was play, and we expected to receive canplay, but got
> > canplaythrough. This could be an error in the media decoders.
> > 2. got canplay at canplaythrough (e.g. comment 140) 
> > 3. got playing at canplay (e.g. comment 137)
> > and a few others.
> > 
> > 2. and 3. can only happen if the indexOf operation is failing. Take case 3 for
> > example, the ok statement should be:
> > ok(tokens["canplaythrough"].indexOf("canplay") >= 0, ...)
> > 
> > but that condition is returning false, i.e. indexOf isn't finding "canplay" in
> > the array ["canplay", "canplaythrough"].
> 
> Interesting. It seems we are getting mostly 2 & 3 as our "extra" failures in
> JM. On the JM side of this, we optimize expressions of the form |x[y]|, and
> also x.y for that matter, using ICs, which are more complicated and tend to
> harbor more bugs. I think I will turn off the optimization for |x[y]| on the JM
> tinderbox to see if that helps.

No mochitest 1/5 box on any platform on this push has failed in test_play_events, so it looks to me this is probably the cause.
Meanwhile, on tracemonkey, landing bug 561506 seems so far to have fixed instances of this, and of all the other JM+TM-specific orange, too.
(In reply to comment #181)
> Meanwhile, on tracemonkey, landing bug 561506

Bug 593918 rather? But that can't help m-c while JM has yet to land on m-c.

/be
There are two bugs, intertwingled: these two tests failed every now and then and continue to fail every now and then, averaging a bit under once a day, on mozilla-central, and then in what always seemed to me like a separate JM bug, starting after an m-c->TM->JM merge, they failed on most platforms on most pushes on JM (around 5 to 7 times per *push*), and then at the same rate on TM after the JM->TM merge.

Then last night, on TM, starting with http://hg.mozilla.org/tracemonkey/rev/9a8b156c7396 which says it was for bug 561506 whether or not it meant that, they have failed zero times in two pushes. Since I don't understand anything about the failure or JM, I can't speak to whether it makes sense, but I can sure tell the difference between 5-7 orange "1"s and zero :)
Hrm, that's worrisome. Dave's change on the JM tree seems to have removed this failure as well. There's probably still a GETELEM PIC bug somewhere, that the addprop IC perturbed enough to silence.
Actually, bhackett's patch could make sense. The GETELEM PIC guarded on atoms but only cleared on shape regen GC. The addprop IC moved PIC clearing to every GC.
Cool -- I should not doubt premier phenomenologist philor.

/be
It looks like bhackett's patch which landed at Thu Sep 9 00:16:56 2010 PDT has fixed this failure on tracemonkey!
http://hg.mozilla.org/tracemonkey/rev/9a8b156c7396
So, whatever fixed the JM explosion of instances of this has apparently been unfixed. It was putting along at one or so a day, then http://hg.mozilla.org/mozilla-central/pushloghtml?changeset=7b83033bb6f8 merged TM to m-c an hour before comment 236, and since then we're back to tons o' fail.