Closed Bug 1224475 Opened 4 years ago Closed 4 years ago

Unlimited Buffering when seeking or re-playing video on b2g devices.

Categories

(Core :: Audio/Video: Playback, defect)

ARM
Gonk (Firefox OS)
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla45
blocking-b2g 2.5+
Tracking Status
firefox45 --- fixed
b2g-v2.5 --- fixed

People

(Reporter: JamesCheng, Assigned: alwu)

References

Details

Attachments

(2 files)

When trying to reproduce Bug 1222923,

I found that when I try to playback this link 

http://people.mozilla.org/~mfinkle/casting/Mobile-launch-greatday640.mp4

by browser app on b2g devices(Flame, Aries..etc), it is easy to encounter the unlimited buffering when 

(a) Random seeking.
(b) Play to the end and press "Play button".

The recovery approach is to turn off and on the screen or leave the browser to background and go to foreground again.(But this approach cannot recovery on TV build when try to reproducing Bug 1222923)

You can see the attachment for better understanding.

The similar symptom can be reproduced on TV build(bug 1222923)
Maybe the root cause is the same.
Hi Blake,

Have you ever met this issue or similar one before?

Or do you know anyone who is familiar with this domain?

Thanks.
Flags: needinfo?(bwu)
attach the symptom video
Please see this video link for this symptom..

https://youtu.be/lC-Rzf_fUJ0

I don't know why the attachment cannot display the video on browser...
(In reply to James Cheng[:JamesCheng] from comment #0)
> When trying to reproduce Bug 1222923,
> 
> I found that when I try to playback this link 
> 
> http://people.mozilla.org/~mfinkle/casting/Mobile-launch-greatday640.mp4
> 
> by browser app on b2g devices(Flame, Aries..etc), it is easy to encounter
> the unlimited buffering when 
> 
> (a) Random seeking.
> (b) Play to the end and press "Play button".
> 

What is your expected behavior and actual behavior?
I expect that I can seek with quick response(not unlimited buffering) and when the video played to the end, I can press the play button for replaying this video file.

But these two expectations usually bump into unlimited buffering issue...
Can it be reproduced by desktop browser ?  This would help to identify if it's platform-dependent.
No, I cannot reproduce this symptom on desktop browser.
John, 
Per comment 7, could you help have a check? It looks like the root cause could be in Gonk PDM.
Flags: needinfo?(bwu) → needinfo?(jolin)
Update some information.

I got similar logs on both TV build and device build when issue occurred.

I/Gecko   ( 1288): Decoder=0xad433200 Changed state to SEEKING (to 0)
I/Gecko   ( 1288): Decoder=0xad433200 Change machine state from COMPLETED to SEEKING
I/Gecko   ( 1288): Decoder=0xad433200 Changed mNextFrameStatus to NEXT_FRAME_UNAVAILABLE_SEEKING
I/Gecko   ( 1288): Decoder=0xad433200 StopPlayback()
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeAudio() isDec=0 decToTar=0 minPrl=0 seek=1 enufAud=0
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeVideo() isDec=0 decToTar=0 minPrl=0 seek=1 enufVid=0
I/Gecko   ( 1288): Decoder=0xad433200 DispatchDecodeTasksIfNeeded needAudio=0 audioStatus=idle needVideo=0 videoStatus=idle needIdle=0
I/Gecko   ( 1288): Decoder=0xad433200 UpdatePlaybackPositionInternal(0)
I/Gecko   ( 1288): Decoder=0xad433200 MediaDecoderStateMachine::Reset
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeVideo() isDec=1 decToTar=0 minPrl=0 seek=1 enufVid=0
I/Gecko   ( 1288): Decoder=0xad433200 EnsureVideoDecodeTaskQueued isDecoding=1 status=idle
I/Gecko   ( 1288): 0xaffaa000 Dispatching event play
I/Gecko   ( 1288): 0xaffaa000 Dispatching event timeupdate
I/Gecko   ( 1288): 0xaffaa000 Dispatching event waiting
I/Gecko   ( 1288): 0xaffaa000 Dispatching event mozinterruptbegin
I/Gecko   ( 1288): 0xaffaa000 Dispatching event canplay
I/Gecko   ( 1288): 0xaffaa000 Dispatching event playing
I/Gecko   ( 1288): 0xaffaa000 Dispatching event canplaythrough
I/Gecko   ( 1288): MediaElement 0xaffaa000 UpdateReadyStateInternal() NEXT_FRAME_UNAVAILABLE_SEEKING; Forcing HAVE_METADATA
I/Gecko   ( 1288): MediaElement 0xaffaa000 UpdateReadyStateInternal() NEXT_FRAME_UNAVAILABLE_SEEKING; Forcing HAVE_METADATA
I/Gecko   ( 1288): 0xaffaa000 Queuing event seeking
I/Gecko   ( 1288): 0xaffaa000 Dispatching event seeking

=========Above is the log |cannot replay when play to the end|===========

The normal log is like below,

I/Gecko   ( 1288): Decoder=0xad433200 Changed state to SEEKING (to 0)
I/Gecko   ( 1288): Decoder=0xad433200 Change machine state from COMPLETED to SEEKING
I/Gecko   ( 1288): Decoder=0xad433200 Changed mNextFrameStatus to NEXT_FRAME_UNAVAILABLE_SEEKING
I/Gecko   ( 1288): Decoder=0xad433200 StopPlayback()
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeAudio() isDec=0 decToTar=0 minPrl=0 seek=1 enufAud=0
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeVideo() isDec=0 decToTar=0 minPrl=0 seek=1 enufVid=0
I/Gecko   ( 1288): Decoder=0xad433200 DispatchDecodeTasksIfNeeded needAudio=0 audioStatus=idle needVideo=0 videoStatus=idle needIdle=0
I/Gecko   ( 1288): Decoder=0xad433200 UpdatePlaybackPositionInternal(0)
I/Gecko   ( 1288): Decoder=0xad433200 MediaDecoderStateMachine::Reset
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeVideo() isDec=1 decToTar=0 minPrl=0 seek=1 enufVid=0
I/Gecko   ( 1288): Decoder=0xad433200 EnsureVideoDecodeTaskQueued isDecoding=1 status=idle
I/Gecko   ( 1288): bool android::OmxDecoder::ReadVideo(android::OmxDecoder::VideoFrame*, int64_t, bool, bool)(581) 
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeAudio() isDec=1 decToTar=1 minPrl=0 seek=1 enufAud=0
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeVideo() isDec=1 decToTar=1 minPrl=0 seek=1 enufVid=0
I/Gecko   ( 1288): Decoder=0xad433200 DispatchDecodeTasksIfNeeded needAudio=1 audioStatus=idle needVideo=1 videoStatus=idle needIdle=0
I/Gecko   ( 1288): Decoder=0xad433200 EnsureAudioDecodeTaskQueued isDecoding=1 status=idle
I/Gecko   ( 1288): Decoder=0xad433200 Queueing audio task - queued=0, decoder-queued=0
I/Gecko   ( 1288): Decoder=0xad433200 EnsureVideoDecodeTaskQueued isDecoding=1 status=idle
I/Gecko   ( 1288): Decoder=0xad433200 Queueing video task - queued=0, decoder-queued=1, skip=0, time=0
I/Gecko   ( 1288): Decoder=0xad433200 OnAudioDecoded [64000,85333] disc=1
I/Gecko   ( 1288): [Child 1288] WARNING: Decoder=ad433200 Audio not synced after seek, maybe a poorly muxed file?: file /media/hdd/Projects/gmp-mozilla-central-gecko/dom/media/MediaDecoderStateMachine.cpp, line 2636
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeAudio() isDec=1 decToTar=1 minPrl=0 seek=1 enufAud=0
I/Gecko   ( 1288): Decoder=0xad433200 NeedToDecodeVideo() isDec=1 decToTar=1 minPrl=0 seek=1 enufVid=0
I/Gecko   ( 1288): Decoder=0xad433200 DispatchDecodeTasksIfNeeded needAudio=1 audioStatus=idle needVideo=1 videoStatus=pending needIdle=0
I/Gecko   ( 1288): Decoder=0xad433200 EnsureAudioDecodeTaskQueued isDecoding=1 status=idle
I/Gecko   ( 1288): Decoder=0xad433200 Queueing audio task - queued=1, decoder-queued=0
I/Gecko   ( 1288): Decoder=0xad433200 EnsureVideoDecodeTaskQueued isDecoding=1 status=pending
I/Gecko   ( 1288): Decoder=0xad433200 IsVideoSeekComplete() curTarVal=1 mVidDis=1 vqFin=0 vqSz=0
I/Gecko   ( 1288): Decoder=0xad433200 EnsureVideoDecodeTaskQueued isDecoding=1 status=pending
I/Gecko   ( 1288): Decoder=0xad433200 IsAudioSeekComplete() curTarVal=1 mAudDis=0 aqFin=0 aqSz=1
I/Gecko   ( 1288): Decoder=0xad433200 CheckIfSeekComplete() audioSeekComplete=1 videoSeekComplete=0
I/Gecko   ( 1288): Decoder=0xad433200 OnVideoDecoded [66733,66734] disc=1
I/Gecko   ( 1288): Decoder=0xad433200 DropVideoUpToSeekTarget() frame [66733, 66734]
I/Gecko   ( 1288): Decoder=0xad433200 DropVideoUpToSeekTarget() found video frame [66733, 66734] containing target=0
I/Gecko   ( 1288): Decoder=0xad433200 IsVideoSeekComplete() curTarVal=1 mVidDis=0 vqFin=0 vqSz=1
I/Gecko   ( 1288): Decoder=0xad433200 IsAudioSeekComplete() curTarVal=1 mAudDis=0 aqFin=0 aqSz=1
(In reply to Blake Wu [:bwu][:blakewu] from comment #8)
> John, 
> Per comment 7, could you help have a check? It looks like the root cause
> could be in Gonk PDM.

My investigation (on Aries) shows the problem is that MP4Demuxer blocked at [1]. Looks like MediaResource cannot read the needed bytes because ChannelMediaResource wasn't successfully resumed at [2]. I'm going to check why this happened.


[1] https://dxr.mozilla.org/mozilla-central/source/dom/media/fmp4/MP4Demuxer.cpp?from=MP4Demuxer.cpp#315
[2] https://dxr.mozilla.org/mozilla-central/source/dom/media/MediaResource.cpp?from=CacheClientSeek#944
Flags: needinfo?(jolin)
Update some info,
In successful case,

mozilla::ChannelSuspendAgent::NotifyChannelClosing will be invoked and mIsChannelSuspended will be set to false. 

In failed case,

ChannelMediaResource::CacheClientSeek will be invoked with aResume=false.

It kept in suspend mode as comment#11 mentioned.
Alastor, could you please help? It seems the extra ChannelMediaResource::Suspend() invocation is because media element believed it's muted by audio channel:

(gdb) bt
#0  mozilla::ChannelMediaResource::Suspend (this=0xaf9a9800, aCloseImmediately=true) at /Users/moz/Works/gecko-dev/dom/media/MediaResource.cpp:751
#1  0xb3eccbea in mozilla::MediaDecoder::Suspend (this=0xaf9e4800) at /Users/moz/Works/gecko-dev/dom/media/MediaDecoder.cpp:1314
#2  0xb3e6baac in SuspendOrResumeElement (aSuspendEvents=false, aPauseElement=<optimized out>, this=0xaf9c9400)
    at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:4210
#3  mozilla::dom::HTMLMediaElement::SuspendOrResumeElement (this=0xaf9c9400, aPauseElement=<optimized out>, aSuspendEvents=<optimized out>)
    at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:4178
#4  0xb3e6bbd8 in mozilla::dom::HTMLMediaElement::UpdateChannelMuteState (this=this@entry=0xaf9c9400, aVolume=aVolume@entry=1, aMuted=aMuted@entry=true)
    at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:4720
#5  0xb3e6bc26 in mozilla::dom::HTMLMediaElement::WindowVolumeChanged (this=0xaf9c9400, aVolume=1, aMuted=<optimized out>)
    at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:4824
#6  0xb3e69458 in mozilla::dom::HTMLMediaElement::NotifyAudioChannelAgent (this=0xaf9c9400, aPlaying=<optimized out>)
    at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:4813
#7  0xb3e696d4 in mozilla::dom::HTMLMediaElement::AddRemoveSelfReference (this=this@entry=0xaf9c9400)
    at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:4339
#8  0xb3e6e628 in PlayInternal (aCallerIsChrome=<optimized out>, this=0xaf9c9400) at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:2312
#9  mozilla::dom::HTMLMediaElement::PlayInternal (this=0xaf9c9400, aCallerIsChrome=<optimized out>) at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:2230
#10 0xb3e6e6d4 in mozilla::dom::HTMLMediaElement::Play (this=0xaf9c9400, aRv=...) at /Users/moz/Works/gecko-dev/dom/html/HTMLMediaElement.cpp:2223
Flags: needinfo?(alwu)
I'll check it later, keep NI.
Assignee: nobody → alwu
Flags: needinfo?(alwu)
[How bug happens]
1. Video ended
2. Replay the video
   2.1 Prepare to seek back to the start 
   2.2 Cache needs to download data again [1]
3. Start AudioChannelAgent
   3.1 As muted by default in b2g, suspend the MediaElement
4. Seek start, changing the ready state to "HAVE_METADATA" (the cache has not finished downloading)
5. Stop AudioChannelAgent, because the ready state < "HAVE_CURRENT_DATA" [2]

As we stop the AudioChannelAgent, the system app can't resume the MediaElement.
That is why the video can't be playback.

[1] In b2g, the cache is not large enough to store the whole video data.
[2] https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#4761
    In addition, |mPlayingThroughTheAudioChannelBeforeSeek| is false. 
    because when we call Seek(), we don't update the mPlayingThroughTheAudioChannel yet.

---

There are two possible solutions,

(1) Set |mPlayingThroughTheAudioChannelBeforeSeek| to true in [3].
We can check the IsPlayingThroughTheAudioChannel(), instead of mPlayingThroughTheAudioChannel.
It's a easy way to solve this issue. 

(2) Postpone the start time of the AudioChannelAgent
We should only start AudioChannelAgent when we have enough data, to make sure the audio has prepared to be playback.
I think that is better than the solution (1), but I have not figure out how to implement it without side-effect.

[3] https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#1585
For the solution (2), here are some more detailed analysis.

--

[Root cause]
Start AudioChannelAgent too early.

[Bug situation]
When we restart the video after video ended, we need to seek the video back to the start.

In b2g, the cache doesn't large enough to store the whole video data. Therefore, the cache needs to download data again. That means even we call the MediaElement::play(), we shouldn't start the AudioChannelAgent immediately. We should wait until the cache have enough data.

When the seeking started, the |mReadyState| would be changed to "HAVE_METADATA". After the seeking completed, the mReadyState| would be "HAVE_CURRENT_DATA".

In our expected, when the mReadyState becomes "HAVE_CURRENT_DATA" and the MediaElement doesn't be ended, we would start the AudioChannelAgent [1].

- Our expected
1. When we call Play() again - HAVE_NOTHING or HAVE_METADATA 
2. Seeking started         - HAVE_METADATA 
3. Seeking completed       - HAVE_CURRENT_DATA
4. Start AudioChannelAgent - Perfect!

- Actual case
1. When we call Play again - HAVE_CURRENT_DATA (There are the previous data in the cache, but we don't need them!!)
2. Start AudioChannelAgent - too early!

[1] https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#4761
Bug 1224475 - Start agent after seeking.
This patch continues the discussion from the comment 16.

[Solution]
Start AudioChannelAgent, only when we already have enough data to playback.

[Reason]
When we start to register the AudioChannelAgent, we would also request the muted status and volume from AudioChannelService. And then use these status to decide whether need to change its volume or suspend the MediaElement. [1]

In b2g, all the sound is muted by default. It means we always suspend MediaElement at the beginning. 
In the normal case, the system app would resume it later (via AudioChannelAgent) if this MediaElement is allowed to playback.

This behavior is little risky, because "suspend" means to stop everything of MediaElement, including loading.
If we suspend the MediaElement before finishing its loading process, we can't be resumed by system app, because AudioChannelAgent would be unregistered due to having no enough data.

Therefore, we need to make sure that to start AudioChannelAgent must happen after finishing the loading process and having the enough data.

[1] https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#4728
Attachment #8690669 - Flags: review?(amarchesini)
Comment on attachment 8690669 [details]
MozReview Request: Bug 1224475 - Start agent after seeking.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/25901/diff/1-2/
Hi, Baku,
Could you help me review this patch?
The explanation of this patch is in the comment19, you can also see some analysis in comment15 & comment16.
Very appreciate!
Attachment #8690669 - Flags: review?(amarchesini) → review?(roc)
Try-server result is in the comment21.
Keywords: checkin-needed
QA Whiteboard: [COM=TV Seamless Experience]
https://hg.mozilla.org/mozilla-central/rev/590126cc607b
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla45
This is a very important bug and we should do uplift to 2.5.
blocking-b2g: --- → 2.5+
Alastor, 
Could you help to do uplift?
Thanks!
Flags: needinfo?(alwu)
Comment on attachment 8690669 [details]
MozReview Request: Bug 1224475 - Start agent after seeking.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Don't resume the MediaResource after seeking
User impact if declined: Can't replay video
Testing completed: Yes
Risk to taking this patch (and alternatives if risky): None
String or UUID changes made by this patch: None
Flags: needinfo?(alwu)
Attachment #8690669 - Flags: approval‑mozilla‑b2g44?
Comment on attachment 8690669 [details]
MozReview Request: Bug 1224475 - Start agent after seeking.

Patch is required for TV, approved for 2.5 uplift. 

Thanks
Attachment #8690669 - Flags: approval‑mozilla‑b2g44? → approval‑mozilla‑b2g44+
You need to log in before you can comment on or make changes to this bug.