Bug 166525

Summary: [GStreamer] FillTimer/buffering logic is not correct
Product: WebKit Reporter: Ihor Ivlev <ivlev.igor>
Component: PlatformAssignee: Nobody <webkit-unassigned>
Status: RESOLVED WORKSFORME    
Severity: Normal CC: bugs-noreply, eocanha, ivlev.igor, pnormand
Priority: P2    
Version: WebKit Nightly Build   
Hardware: Unspecified   
OS: Unspecified   
URL: https://github.com/WebKit/webkit/blob/master/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp#L1229
Attachments:
Description Flags
Pipeline dump showing the GstDownloadBuffer element used for on-disk caching and buffer measurement
none
Pipeline dump with GstQueue
none
Log collected when GstQueue was used none

Description Ihor Ivlev 2016-12-28 01:01:19 PST
https://github.com/WebKit/webkit/blob/master/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp#L1229

m_maxTimeLoaded is evaluated by comparing fillStatus value to *total track duration*, which does not make sense:
fillStatus corresponds to bufferization level which is evaluated [in queue element] by
(buffered level)/(max buffer size), but total track duration is not related to these values.
(buffered level) and (max buffer size) are internal values of the queue element.
Comment 1 Enrique Ocaña 2016-12-29 08:39:31 PST
Created attachment 297833 [details]
Pipeline dump showing the GstDownloadBuffer element used for on-disk caching and buffer measurement
Comment 2 Enrique Ocaña 2016-12-29 08:39:58 PST
There are two cases here: on-disk buffering enabled and on-disk buffering disabled. 

I've done several tests in WebKit with some code to force on-disk buffering. A ${HOME}/.cache/WebKitWebProcess-XXXXXX file is created by the GstDownloadBuffer element while the video is shown, and automatically deleted when the player is destroyed. See the pipeline dump in PAUSED state I'm attaching.

I can confirm that in such a scenario, the "buffer size" is actually the whole media size, so it makes sense to correlate "100% buffered" with "all the media has been downloaded". See some logs obtained for a video tag configured with https://download.blender.org/durian/trailer/sintel_trailer-1080p.mp4 (14621544 bytes). The {start,stop} values are in percentage with fixed comma (eg: 123456 is 12.3456%), and the b{start,stop,total} values are in bytes:

### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): Percent buffering query failed
...
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): Percent buffering query failed
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): start: 0, stop: 1120, fillStatus: 0.112000
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): bstart: 0, bstop: 16384, btotal: 133988
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): start: 0, stop: 4482, fillStatus: 0.448200
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): bstart: 0, bstop: 65536, btotal: 135568
...
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): start: 0, stop: 962542, fillStatus: 96.254200
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): bstart: 0, bstop: 14073856, btotal: 579
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): start: 0, stop: 984953, fillStatus: 98.495300
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): bstart: 0, bstop: 14401536, btotal: 223
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): start: 0, stop: 1000000, fillStatus: 100.000000
### void WebCore::MediaPlayerPrivateGStreamer::fillTimerFired(): bstart: 0, bstop: 14621544, btotal: 0

For this reason I think that the current code seems right.

If on-disk buffering is disabled, the fillTimer isn't ever started and nothing related to buffering is reported.

Can you clarify your use case and provide some data which contradicts this analysis?
Comment 3 Ihor Ivlev 2016-12-29 11:30:58 PST
in my case, GstDownloadBuffer was not added to the pipeline, but GstQueue was added instead.
Comment 4 Ihor Ivlev 2017-01-03 00:46:18 PST
Created attachment 297925 [details]
Pipeline dump with GstQueue
Comment 5 Ihor Ivlev 2017-01-03 00:46:55 PST
Created attachment 297926 [details]
Log collected when GstQueue was used
Comment 6 Ihor Ivlev 2017-01-03 00:49:13 PST
I have attached pipeline dump and the log.
It appeared for me as a mainstream issue (I found this using WPE port), but after looking at Enrique's pipeline dump, I am not sure if the issue is reproducible with the mainstream webkit.
Comment 7 Philippe Normand 2018-02-18 23:35:04 PST
Let's close this then. If you find a test showcasing the issue, please re-open!