Closed Bug 750258 Opened 12 years ago Closed 10 years ago

Intermittent test_streams_element_capture.html,test_streams_element_capture_createObjectURL.html | {seek.webm|small-shot.ogg|detodos.opus|r11025_s16_c1.wav|320x240.ogv} checking readyState - got 4, expected 2

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Version:
15 Branch
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
VERIFIED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- wontfix
b2g-v1.3 --- wontfix
b2g-v1.3T --- wontfix
b2g-v1.4 --- wontfix
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: emorley, Assigned: roc)

References

Details

(Keywords: intermittent-failure)

Attachments

(8 files, 2 obsolete files)

testcase
458 bytes, text/html
Details
fix v2
5.19 KB, patch
jesup
: review+
Details | Diff | Splinter Review
Small cleanup to make it more obvious why mCurrentTime is initialized to 1
1.17 KB, patch
jesup
: review+
Details | Diff | Splinter Review
additional fix
1.23 KB, patch
cpearce
: review+
Details | Diff | Splinter Review
fix? v2
4.29 KB, patch
jesup
: review+
cpearce
: review+
Details | Diff | Splinter Review
750258_fix_stream_NotifyBlockingChanged-v1.patch
3.29 KB, patch
roc
: review+
Details | Diff | Splinter Review
750258_fix_stream_NotifyBlockingChanged-aurora.patch
3.29 KB, patch
jwwang
: review+
Sylvestre
: approval-mozilla-aurora+
Details | Diff | Splinter Review
750258_fix_stream_NotifyBlockingChanged-beta.patch
3.29 KB, patch
jwwang
: review+
Sylvestre
: approval-mozilla-beta+
Details | Diff | Splinter Review 
Rev3 WINNT 5.1 mozilla-inbound debug test mochitests-1/5 on 2012-04-29 22:31:12 PDT for push 57cc1577f951

slave: talos-r3-xp-030

https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=57cc1577f951
https://tbpl.mozilla.org/php/getParsedLog.php?id=11316672&tree=Mozilla-Inbound#error0

{
93789 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | r11025_s16_c1.wav set output element .src correctly - [object MediaStream @ 0x11138188 (native @ 0x118f5ea8)] should equal [object MediaStream @ 0x11138188 (native @ 0x118f5ea8)]
--DOCSHELL 11FD4DA0 == 9 [id = 564]
--DOCSHELL 11901588 == 8 [id = 565]
93790 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg stream final currentTime - 0.48459625244140625 should equal 0.48459625244140625
93791 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276
93792 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg checking readyState - got 4, expected 2
93793 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg checking playback has ended
93794 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | [finished small-shot.ogg-0] Length of array should match number of running tests - 1 should equal 1
93795 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | [started 320x240.ogv-2] Length of array should match number of running tests - 2 should equal 2
}
Attached file testcase — 
This lets me reproduce it on trunk.
Assignee: nobody → roc
Attached patch fix (obsolete) — — Splinter Review 
This fixes my testcase for me. Hopefully it'll fix tinderbox tests too.
Attachment #620602 - Flags: review?(rjesup)
Comment on attachment 620602 [details] [diff] [review]
fix

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

I agree this will resolve the orange.

I'm slightly concerned there might be an interaction with something external which doesn't know about the underrun - the delta time in the graph may not match the delta time in the rest of the system.  But this is just a "hmmm, I wonder if anyone could be bitten by this", and I really can't know without a better understanding of the interactions possible due to this.   If this is solely internal, and not exposed even indirectly, the issue is moot.  Even if it is in some manner visible (including indirectly by something assuming that if X time has passed that the Graph has advanced by X), then some additional analysis may be useful.  (I'm particularly sensitive to realtime playback and transmission issues, since pausing has much more impact there - on an underrun, instead of effectively adding delay, you probably should throw away the data that didn't meet the timeline.)

The patch comment is on the long side, though I'm actually usually a fan of detailed commit notices - but with our fairly strong bugzilla usage, most of that can be in bugzilla instead. :-)

r+ to this as an orange fix, but please noodle the issues above and if warranted file a bug for future work on it, or note here that it's not needed.
Attachment #620602 - Flags: review?(rjesup) → review+
Actually I think you've convinced me that instead of doing this, we should add extra blocked time to all the streams. Currently that amounts to the same thing, but it will let future stream observers observe what's happened more accurately.
Attached patch fix v2 — — Splinter Review 

        Attachment #620602 -
        Attachment is obsolete: true

        Attachment #621004 -
        Flags: review?(rjesup)

    
    

    
  
Running that test file locally with the patch, things are much better, but I still see occasional cases where the data played through the MediaStream is shorter than the actual media resource. This seems to be a completely different bug. In nsBuiltinDecoderStateMachine::DecodeLoop, between mReader->DecodeAudioData() and SendOutputStreamData() the audioloop thread can run, play audio and empty mAudioQueue, causing audio data to be removed before SendOutputStreamData can get to it. This is a little strange since media elements captured to a MediaStream aren't supposed to be running the audioloop thread...

    
    

    
      
  

    
    

    
      
  

        Attachment #621004 -
        Flags: review?(rjesup) → review+

    
    

    
      
  

    
    

    
  
With this additional fix, the testcase in comment #8 can run indefinitely and always returns the correct duration and readyState.

        Attachment #621493 -
        Flags: review?(cpearce) → review+

        Attachment #621491 -
        Flags: review?(rjesup) → review+

    
    

    
      
  

    
  
Status: RESOLVED → REOPENED
Resolution: FIXED → ---

    
    

    
      
  

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/718e334e4d99

(Was the same push on which the comment 26 failure occurred)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
Curiously, all the Linux failures are on 320x240.ogv. The only Mac failure is on small-shot.ogg, and curiously that's on the Oak branch.

    
    

    
  
Pounding on the testcase of comment #8 with 320x240.ogv doesn't ever fail on my Windows laptop.

    
    

    
  
Note, the failures after my checkins here are different from before. Now the durations are always correct, it's only the readyState that's wrong.

    
    

    
  
I have a theory about this now. A media element playing a source stream starts in HAVE_ENOUGH_DATA state (because ResourceLoaded is called immediately by SetupMediaStreamPlayback). However, the stream could be initially blocked. We could then go through an iteration of the MediaStreamGraph control loop which plays the entire content of the stream, finishes the stream, and returns it to the blocked state. Because the initial and final state of the stream was blocked, we wouldn't fire a NotifyBlockingChanged, so DoNotifyBlocked would never get called to call UpdateReadyStateForData to set the readyState to HAVE_CURRENT_DATA.

    
    

    
  

      
      
      
      

        Attached patch
          
          
        fix? (obsolete)
        — 
          — Splinter Review
      

    


  
This might fix it.

        Attachment #626396 -
        Flags: review?(rjesup)

    
    

    
  
Comment on attachment 626396 [details] [diff] [review]
fix?

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

::: content/html/content/src/nsHTMLMediaElement.cpp
@@ +2529,5 @@
> +  // Ensure that ResourceLoaded below won't take us to HAVE_ENOUGH_DATA.
> +  // Having attached our listener, we expect a DoNotifyBlocked or
> +  // DoNotifyUnblocked event to change our readyState to HAVE_CURRENT_DATA or
> +  // HAVE_ENOUGH_DATA.
> +  ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_NOTHING);

Doesn't this mean that the "loadedmetadata" event can arrive before readyState is greater than or equal to HAVE_METADATA? That seems wrong...

    
    

    
  

      
      
      
      

        Attached patch
          
          
        fix? v2
        — 
          — Splinter Review
      

    


  

        Attachment #626396 -
        Attachment is obsolete: true

        Attachment #626396 -
        Flags: review?(rjesup)

        Attachment #626396 -
        Flags: review?(cpearce)

        Attachment #626671 -
        Flags: review?(rjesup)

    
    

    
  
Comment on attachment 626671 [details] [diff] [review]
fix? v2

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

::: content/html/content/src/nsHTMLMediaElement.cpp
@@ +2644,5 @@
>    mBegun = false;
>    mNetworkState = nsIDOMHTMLMediaElement::NETWORK_IDLE;
>    AddRemoveSelfReference();
>    if (mReadyState >= nsIDOMHTMLMediaElement::HAVE_METADATA) {
> +    // MediaStream sources  are put into HAVE_CURRENT_DATA state here on setup. If the

s/sources  are/sources are/

        Attachment #626671 -
        Flags: review?(cpearce) → review+

        Attachment #626671 -
        Flags: review?(rjesup) → review-

        Attachment #626671 -
        Flags: review- → review+

    
    

    
      
  

    
    

    
  
So apparently this patch didn't fix the bug :-(.
Whiteboard: [orange] → [orange][leave open]

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Summary: Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | small-shot.ogg checking readyState - got 4, expected 2 → Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | small-shot.ogg checking readyState - got 4, expected 2, detodos.opus checking readyState - got 4, expected 2

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Summary: Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | small-shot.ogg checking readyState - got 4, expected 2, detodos.opus checking readyState - got 4, expected 2 → Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | {small-shot.ogg|detodos.opus|r11025_s16_c1.wav} checking readyState - got 4, expected 2

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
  
Whiteboard: [orange][leave open] → [orange]
Target Milestone: mozilla15 → ---

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Whiteboard: [orange]

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
  
Summary: Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | {small-shot.ogg|detodos.opus|r11025_s16_c1.wav} checking readyState - got 4, expected 2 → Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | {seek.webm|small-shot.ogg|detodos.opus|r11025_s16_c1.wav} checking readyState - got 4, expected 2

    
    

    
      
  

    
    

    
      
  

    
    

    
  
roc, any chance you could take another look at this long-running orange?
Flags: needinfo?(roc)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
The fixing of bug 938022 may help.
Flags: needinfo?(roc)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
Fixing bug 999267 made the more recent readyState failures almost perma-orange.
Bug 1010000 fixes that issue (which might be involved here).
Depends on: 1010000

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
https://tbpl.mozilla.org/php/getParsedLog.php?id=41248569&tree=Try
Summary: Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | {seek.webm|small-shot.ogg|detodos.opus|r11025_s16_c1.wav} checking readyState - got 4, expected 2 → Intermittent test_streams_element_capture.html,test_streams_element_capture_createObjectURL.html | {seek.webm|small-shot.ogg|detodos.opus|r11025_s16_c1.wav|320x240.ogv} checking readyState - got 4, expected 2

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
  
See Also:  → 1024535

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
This is currently the #3 orange on trunk, so any prioritization on this would be helpful :)
Flags: needinfo?(jwwang)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
I will investigate this bug.
Flags: needinfo?(jwwang)

    
    

    
  
http://hg.mozilla.org/mozilla-central/file/c4cf1181993e/content/media/test/test_streams_element_capture.html#l43

Hi roc,
What is checking readyState == HAVE_CURRENT_DATA for?
Flags: needinfo?(roc)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
(In reply to JW Wang [:jwwang] from comment #470)
> What is checking readyState == HAVE_CURRENT_DATA for?

When our stream ends, we still have the last frame but we don't have any future frames, so readyState should be HAVE_CURRENT_DATA.
Flags: needinfo?(roc)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/html/content/src/HTMLMediaElement.cpp#l2684
The ready state of the media element will become HAVE_CURRENT_DATA when the stream is blocked.

http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/html/content/src/HTMLMediaElement.cpp#l2677
DoNotifyFinished() will call HTMLMediaElement::PlaybackEnded which will then queue an 'ended' event.

http://hg.mozilla.org/mozilla-central/file/c4cf1181993e/content/media/test/test_streams_element_capture.html#l43
If the stream is not blocked when 'ended' event is fired, we will fail the test.

http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/MediaStreamGraph.cpp#l763
However, the stream blocking time is slightly greater than the stream end time.

http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/MediaStreamGraph.cpp#l452
It is possible for mCurrentTime to get in-between the stream end time and stream blocking time and NotifyFinished() will be called without NotifyBlockingChanged() being called first.

That's why we see the stream is not blocked and ready state is HAVE_ENOUGH_DATA when 'ended' is received.


http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/MediaStreamGraph.cpp#l798
It looks like we should pass the stream end time instead of |aTime| so that the blocking time is more precisely updated. Does that make sense?
Flags: needinfo?(roc)

    
    

    
  
(In reply to JW Wang [:jwwang] from comment #491)
> http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/
> MediaStreamGraph.cpp#l763
> However, the stream blocking time is slightly greater than the stream end
> time.

Can we fix that?

> http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/
> MediaStreamGraph.cpp#l798
> It looks like we should pass the stream end time instead of |aTime| so that
> the blocking time is more precisely updated. Does that make sense?

This doesn't seem like the right place to fix it.
Flags: needinfo?(roc)

    
    

    
  
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #492)
> (In reply to JW Wang [:jwwang] from comment #491)
> > http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/
> > MediaStreamGraph.cpp#l763
> > However, the stream blocking time is slightly greater than the stream end
> > time.
> 
> Can we fix that?

|aTime| is passed from |t| in RecomputeBlocking(). |t| is basically |mStateComputedTime| which is independent from any of the stream end time. How about aligning |endBlockingDecisions| with the stream end time?

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
(In reply to JW Wang [:jwwang] from comment #493)
> (In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment
> #492)
> > (In reply to JW Wang [:jwwang] from comment #491)
> > > http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/
> > > MediaStreamGraph.cpp#l763
> > > However, the stream blocking time is slightly greater than the stream end
> > > time.
> > 
> > Can we fix that?
> 
> |aTime| is passed from |t| in RecomputeBlocking(). |t| is basically
> |mStateComputedTime| which is independent from any of the stream end time.
> How about aligning |endBlockingDecisions| with the stream end time?

Doesn't seem so...

http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/MediaStreamGraph.cpp#l773
This line should ensure that |aTime| will never jump from |aTime| < endTime to |aTime| > endTime.

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
(In reply to Karl Tomlinson (needinfo?:karlt) from comment #508)
> If the stream becomes blocked at nextCurrentTime, then NotifyBlockingChanged
> will not be sent
> http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/
> MediaStreamGraph.cpp#l399
> 
> but NotifyFinished will be sent
> http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/
> MediaStreamGraph.cpp#l452

Yeah, I noticed that too. But I still need to add some logs to confirm this is what causes the test case to fail. https://hg.mozilla.org/try/rev/1f4b2fa6ed5b

Btw, it looks like if underrun happens, currentTime could advance to a position where blocking decision is not made yet. This could also result in NotifyBlockingChanged not sent...

    
    

    
      
  

    
    

    
  
(In reply to JW Wang [:jwwang] from comment #510)
> Btw, it looks like if underrun happens, currentTime could advance to a
> position where blocking decision is not made yet.

nextCurrentTime shouldn't be advancing beyond mStateComputedTime, and blocking decisions should have been made up to mStateComputedTime.

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
https://tbpl.mozilla.org/php/getParsedLog.php?id=42124266&tree=Try&full=1#error0

00:26:02     INFO -  2014-06-20 07:26:02.551000 UTC - 2824[1413ac0]: stream 13483c60 prevCurrentTime=507513 nextCurrentTime=507986 endTime=507904
00:26:02     INFO -  2014-06-20 07:26:02.551000 UTC - 2824[1413ac0]: stream 13483c60 blocked=0 507513 => 508416
00:26:02     INFO -  2014-06-20 07:26:02.551000 UTC - 2824[1413ac0]: stream 13483c60 blocked=0 507986 => 508416
00:26:02     INFO -  2014-06-20 07:26:02.551000 UTC - 2824[1413ac0]: stream 13483c60 blocked=0 507904 => 508416

The stream end time is 507904 [1]. However the stream is not blocked until 508416 which is beyond the end time. Is it normal for a stream created by AudioContext.createMediaStreamDestination()?

[1] https://hg.mozilla.org/try/file/1f4b2fa6ed5b/content/media/MediaStreamGraph.cpp#l466
Flags: needinfo?(karlt)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
(In reply to JW Wang [:jwwang] from comment #519)
> The stream end time is 507904 [1]. However the stream is not blocked until
> 508416 which is beyond the end time. Is it normal for a stream created by
> AudioContext.createMediaStreamDestination()?

Yes.  I think it is normal for streams in general.

1. RecomputeBlocking() determines the blocking time.

2. ProcessInput() ends tracks and sets mFinished on the stream.

3. UpdateCurrentTime() notices that mFinished has been set and tracks have ended,
   but mBlocked has not been updated since they finished.

Perhaps DoNotifyFinished() could call DoNotifyBlocked() if the order of events is important?
Flags: needinfo?(karlt) → needinfo?(roc)

    
    

    
  
A stream that has finished should be blocked as soon as it has finished.
Flags: needinfo?(roc)

    
    

    
  
The stream *is* blocked as soon as it has finished (as far as we know) in the graph timeline sense, and on the graph thread.

4. RecomputeBlocking() notices that the stream is finished, and sets the blocking time to the end time.

However, the order of notifications is not specified and BlockingChanged notifications are always sent strictly *after* the blocking status has changed.  Similarly for NotifyOutput, which may be sent after NotifyBlockingChanged(BLOCKED).

I guess NotifyFinished could be delayed until after the stream is known blocked, or the stream could be marked blocked when the stream is known finished.

However, HTMLMediaElement::StreamListener is dispatching these notifications to the main thread as separate events so blocking and finished will not change atomically.

    
    

    
  


  
Include |nextCurrentTime| to ensure NotifyBlockingChanged() is called before NotifyFinished() when |nextCurrentTime| happens to be the stream end time (all tracks ended).

    
    

    
  
Comment on attachment 8444207 [details] [diff] [review]
750258_fix_stream_NotifyBlockingChanged-v1.patch

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

::: content/media/MediaStreamGraph.cpp
@@ +397,5 @@
>      GraphTime blockedTime = 0;
>      GraphTime t = prevCurrentTime;
> +    // include |nextCurrentTime| to ensure NotifyBlockingChanged() is called
> +    // before NotifyFinished() when |nextCurrentTime == stream end time|
> +    while (t <= nextCurrentTime) {

It looks sub-optimal to include |nextCurrentTime| for it overlaps |prevCurrentTime| in next iteration. However, it is even more weird for |t| to start with |prevCurrentTime+1|. Since we have |mNotifiedBlocked| to ensure NotifyBlockingChanged() is only called when once for each change in blocking, we are somewhat fine with the overlap.

@@ +450,5 @@
>    for (uint32_t i = 0; i < streamsReadyToFinish.Length(); ++i) {
>      MediaStream* stream = streamsReadyToFinish[i];
>      // The stream is fully finished when all of its track data has been played
>      // out.
>      if (mCurrentTime >=

I changed '>=' to '>' for NotifyBlockingChanged is checked in the interval of [prevCurrentTime, nextCurrentTime). However, since |blockingDecisionsWillChange| [1] is checked in the interval of [mCurrentTime = nextCurrentTime, infinity), there will be no next iteration when |nextCurrentTime| happens to be the stream end time and NotifyFinished() is not called until MSG is waken up again.

[1] http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/MediaStreamGraph.cpp#l684

        Attachment #8444207 -
        Flags: review?(roc)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

        Attachment #8444207 -
        Flags: review?(roc) → review+

    
    

    
  
Please check in 750258_fix_stream_NotifyBlockingChanged-v1.patch only, thanks.
Keywords: checkin-needed

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/0deece85bc42
Status: REOPENED → RESOLVED
Closed: 12 years ago → 10 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
Target Milestone: --- → mozilla33

    
    

    
      
  

    
    

    
  
jwwang++ :D

Please request Aurora, Beta, and b2g30 approval on this when you get a chance :)

          status-b2g-v1.4:
          --- → affected

          status-b2g-v2.0:
          --- → affected

          status-b2g-v2.1:
          --- → fixed

          status-firefox31:
          --- → affected

          status-firefox32:
          --- → affected

          status-firefox33:
          --- → fixed

          status-firefox-esr24:
          --- → wontfix

    
    

    
  
(In reply to Karl Tomlinson (needinfo?:karlt) from comment #512)
> nextCurrentTime shouldn't be advancing beyond mStateComputedTime, and
> blocking decisions should have been made up to mStateComputedTime.

Blocking decisions are made in the interval of [xxx, mStateComputedTime) which doesn't include |mStateComputedTime|. When underrun happens, |nextCurrentTime| is adjusted to |mStateComputedTime|. If a stream happens to end at |mStateComputedTime|, we will run into the case in comment 519 for blocking decisions are not made yet at |mStateComputedTime|.

Trickily adjusting |nextCurrentTime| to |mStateComputedTime - 1| for underrun cases might work. I can give it a try though.
Flags: needinfo?(karlt)

    
    

    
  
(In reply to JW Wang [:jwwang] from comment #594)
> Blocking decisions are made in the interval of [xxx, mStateComputedTime)
> which doesn't include |mStateComputedTime|. When underrun happens,
> |nextCurrentTime| is adjusted to |mStateComputedTime|. If a stream happens
> to end at |mStateComputedTime|, we will run into the case in comment 519 for
> blocking decisions are not made yet at |mStateComputedTime|.

I think you are right and that is a likely situation if a stream finishes itself during processing (comment 551).

> Trickily adjusting |nextCurrentTime| to |mStateComputedTime - 1| for
> underrun cases might work. I can give it a try though.

That might work.
However, I think the solution I'd prefer, would be to delay sending NotifyFinished until NotifyBlockingChanged has been sent.  (That might fix bug 962719 too.)

I'd prefer that because I think having nextCurrentTime lag behind mStateComputedTime is a bug (https://bugzilla.mozilla.org/show_bug.cgi?id=962719#c10 and https://bugzilla.mozilla.org/show_bug.cgi?id=956574#c24).
I don't want to try to change that while Paul is working on bug 848954.
I suspect the notifications in UpdateCurrentTime() should happen at the end of the RunThread() loop, before the timeout or indefinite wait.
Flags: needinfo?(karlt)

    
    

    
      
  

    
    

    
  


  
[Approval Request Comment]
Bug caused by (feature/regressing bug #): unknown
User impact if declined: lower test coverage might decrease the code quality
Testing completed (on m-c, etc.): try: https://tbpl.mozilla.org/?tree=Try&rev=d06f6ad9fcb2
Risk to taking this patch (and alternatives if risky): low
String or IDL/UUID changes made by this patch: none

        Attachment #8446289 -
        Flags: review+

        Attachment #8446289 -
        Flags: approval-mozilla-aurora?

    
    

    
  


  
[Approval Request Comment]
Bug caused by (feature/regressing bug #): unknown
User impact if declined: lower test coverage might decrease the code quality
Testing completed (on m-c, etc.): try: https://tbpl.mozilla.org/?tree=Try&rev=714caea85861
Risk to taking this patch (and alternatives if risky): low
String or IDL/UUID changes made by this patch: none

        Attachment #8446292 -
        Flags: review+

        Attachment #8446292 -
        Flags: approval-mozilla-beta?

    
    

    
      
  

    
    

    
  
Comment on attachment 8446292 [details] [diff] [review]
750258_fix_stream_NotifyBlockingChanged-beta.patch

Taking because 31 is an ESR.

        Attachment #8446292 -
        Flags: approval-mozilla-beta? → approval-mozilla-beta+

        Attachment #8446289 -
        Flags: approval-mozilla-aurora? → approval-mozilla-aurora+

    
  
See Also: 1024535 → 

    
    

    
  
Is there a way we can manually verify this? Using the testcase from comment 8 the following errors appear in the console:

HTTP load failed with status 404. Load of media resource https://bug750258.bugzilla.mozilla.org/%5Bobject%20MediaStream%5D failed. attachment.cgi
HTTP load failed with status 404. Load of media resource https://bug750258.bugzilla.mozilla.org/small-shot.ogg failed. attachment.cgi
Flags: needinfo?(roc)

    
    

    
  
The lack of failures on TBPL since this landed is all the verification we need that the patch worked.
Status: RESOLVED → VERIFIED
Flags: needinfo?(roc)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

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






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: