1397708 - Video tag element is not firing progress event after some time at first play

Status: RESOLVED FIXED

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

Description

[dante_s]

Attachment: Firefox progress bug.png

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.113 Safari/537.36

Steps to reproduce:

1) Open custom html5 player, for example videojs (http://videojs.com/)
2) Start Playing
3) Do not seek, or stop video
4) From a short time buffering line will stop, but if you look at buffered object its timing will exceed actual currentTime

PS MacOS 10.12.6


Actual results:

Shortly after playing started, video element stopped firing 'progress' event.

As you can see at screenshot attached, I am listening 'progress' event by handler and through addEventListener.

Lat time progress event fired at 75.766712 of video is loaded. But TimeRange object already at timing 109.389207. And 'progress' event wont be fired again.


Expected results:

Video element should fire 'progress' event, each time after buffered object is changed.

Comment 1

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

IGN video on http://videojs.com/ plays fine for me. Can you please provide more precise detail on the steps to reproduce?

Comment 2

[dante_s]

1) http://jsbin.com/zozepewena/1/edit?console,output
2) click Run with js
3) buffered object will shoot in console every 4 seconds
4) start video
5) do not stop or seek video
6) look at the console

It will work only if video is not cached. So to reproduce this bug maybe you should disable disk cache for a while.

Sample console output, which I got

"progress"
0.510839
"progress"
13.580233
"progress"
13.580233
"buffered"
61.694966
"buffered"
61.694966
"buffered"

As you see, video buffered for 61 seconds, but last progress event was at 13 seconds.

Comment 3

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

(In reply to dante_s from comment #2)
> As you see, video buffered for 61 seconds, but last progress event was at 13
> seconds.

It stops firing progress events when it stops buffering the video at 60 seconds.

Comment 4

[dante_s]

It stoped firing progress event at all. Check video. As you can see, last buffering event was at 11 seconds of buffering progress, but buffered length changed twice, to 63 seconds, and to 91 seconds, and there was no progress event between them. But it should be. 

https://drive.google.com/file/d/0B476pc_6qEy7S3BqdndCczlfb2c/view?usp=sharing

Comment 5

[Jean-Yves Avenard [:jya]]

"progress" events indicates that data is being fetched.

https://html.spec.whatwg.org/multipage/media.html#event-media-progress

that is when networkState is equal to NETWORK_LOADING.

Per spec it also states:
https://html.spec.whatwg.org/multipage/media.html#concept-media-load-resource

if mode is remote
Step 2:
"While the load is not suspended (see below), every 350ms (±200ms) or for every byte received, whichever is least frequent, queue a task to fire an event named progress at the element."

Changing the timer so that buffered is updated every 300ms we see:
buffered 60.794066 61014
buffered 60.794066 61315
buffered 90.1901 61618
buffered 90.1901 61920
buffered 90.1901 62225
buffered 90.1901 62528
(the second number is the current time since page first loaded in milliseconds)

progress is certainly not fired every 350ms.
even though we can see that new data has been downloaded.

Comment 6

[JW Wang [:jwwang] [:jw_wang]]

I think the 350ms refers to the wall clock time.

buffered 61014
buffered 61315
buffered 61618
buffered 61920
buffered 62225
buffered 62528

The intervals of the events are exactly about 300ms.

Comment 7

[Jean-Yves Avenard [:jya]]

(In reply to JW Wang [:jwwang] [:jw_wang] from comment #6)
> I think the 350ms refers to the wall clock time.
> 
> buffered 61014
> buffered 61315
> buffered 61618
> buffered 61920
> buffered 62225
> buffered 62528
> 
> The intervals of the events are exactly about 300ms.

uh? I think you went a tad too quickly in answering this one!

Please refer to the original JS page: http://jsbin.com/zozepewena/1/edit?console,output

the time shown is the interval set to display the buffered message on the console (changed from the original 4000ms).

The time shows next to buffered as *nothing* to do with the delay between "progress" events (the text buffered is rather a given :P) but the time at which the buffered attribute is read.

The progress event isn't being fired as it should.

My previous message listed:
buffered 60.794066 61014
buffered 60.794066 61315
buffered 90.1901 61618
buffered 90.1901 61920
buffered 90.1901 62225
buffered 90.1901 62528

as proof that the progress event wasn't being fired.
We can see that at time 61014, the buffered's end attribute is 60.79s
604ms later, it moves to 90.19s

This shows that during those 604ms we had over 30s more data that have been downloaded, yet no progress event was fired.

Comment 8

[JW Wang [:jwwang] [:jw_wang]]

buffered 60.794066 61315
buffered 90.1901   61618

Our media stack updates buffered ranges asynchronously (with 500ms delay). So it is wrong to interpret the logs as we downloaded (90.1901-60.794066=~30)s data within (61618-61315=303)ms.

Comment 9

[Jean-Yves Avenard [:jya]]

And as per the user description, also reproduced by me, it shows that there are never any progress events fired once download has started.

If you ran the script it's rather obvious, I only copied the few interesting lines, however, the previous progress event had been fired around buffered=11s, about 20s earlier.

As far as saying it's not 500ms, there's over 2s worth of logs showing that progress wasn't fired.

There's a bug, it needs fixing thank you.

Comment 10

[JW Wang [:jwwang] [:jw_wang]]

I can repro the issue on 57 but no Nightly.

Can you also listen to the 'suspend' event and capture the logs again?

It looks like our media stack suspends and resumes the download repeatedly (network state switches to IDLE and LOADING back and forth) and therefore the 'progress' event is not fired if network state happens to be IDLE.

Comment 11

[JW Wang [:jwwang] [:jw_wang]]

Never mind, I can repro the issue on Nightly also. Figuring out the root cause...

Comment 12

[JW Wang [:jwwang] [:jw_wang]]

I think I found the root cause:

1. the user click 'play'.
2. a new HTTP channel is created to download data.
3. MediaCache suspends the download when there is 60s worth data ahead of the current playback position.
4. network state is changed to IDLE and mBegun set to false. [1]
5. as playback continues, MediaCache resume the download to fetch more data.
6. HTMLMediaElement::DownloadResumed(false) is called to notify download has resumed [2].
7. since mBegun is false, network state is not changed to LOADING and 'progress' is not fired.

[1] http://searchfox.org/mozilla-central/rev/b53e29293c9e9a2905f4849f4e3c415e2013f0cb/dom/html/HTMLMediaElement.cpp#6077
[2] http://searchfox.org/mozilla-central/rev/b53e29293c9e9a2905f4849f4e3c415e2013f0cb/dom/media/ChannelMediaResource.cpp#716
[3] http://searchfox.org/mozilla-central/rev/b53e29293c9e9a2905f4849f4e3c415e2013f0cb/dom/html/HTMLMediaElement.cpp#5673

http://searchfox.org/mozilla-central/rev/b53e29293c9e9a2905f4849f4e3c415e2013f0cb/dom/html/HTMLMediaElement.cpp#6072
The fix is to remove mBegun which is also a TODO item that should be done long ago.

Comment 13

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Bug 1397708 - remove HTMLMediaElement::mBegun. See comment 12 for the root cause.

Review commit: https://reviewboard.mozilla.org/r/187920/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/187920/

Comment 14

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8916855 [details]
Bug 1397708 - remove HTMLMediaElement::mBegun. See comment 12 for the root cause.

https://reviewboard.mozilla.org/r/187920/#review192982

It would be good if the commit message could be more descriptive please.

Comment 15

[JW Wang [:jwwang] [:jw_wang]]

Thanks! Comment message is updated.

Comment 16

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8916855 [details]
Bug 1397708 - remove HTMLMediaElement::mBegun. See comment 12 for the root cause.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187920/diff/1-2/

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/34bf219e8cbd
remove HTMLMediaElement::mBegun. See comment 12 for the root cause. r=cpearce

Comment 18

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/34bf219e8cbd