Bug 205117 - [GStreamer][MSE] Player stalling too soon
Summary: [GStreamer][MSE] Player stalling too soon
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: WebKitGTK (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Alicia Boya García
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-12-11 08:37 PST by Charlie Turner
Modified: 2020-01-06 04:24 PST (History)
12 users (show)

See Also:


Attachments
Test case (180.00 KB, application/x-tar)
2019-12-11 08:37 PST, Charlie Turner
no flags Details
Patch (3.71 KB, patch)
2019-12-22 04:44 PST, Alicia Boya García
no flags Details | Formatted Diff | Diff
Patch (198.92 KB, patch)
2019-12-24 17:15 PST, Alicia Boya García
no flags Details | Formatted Diff | Diff
Patch (198.91 KB, patch)
2020-01-02 05:51 PST, Alicia Boya García
no flags Details | Formatted Diff | Diff
Patch (198.93 KB, patch)
2020-01-02 05:57 PST, Alicia Boya García
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Charlie Turner 2019-12-11 08:37:30 PST
Created attachment 385395 [details]
Test case

Attached is a testcase reproducing the bug. Observed bug,

  - MP4 tools think the files combined are 10s long, but they have been truncated to 2.23s in reality.
  - When playing it with GstMSE, the player stops for an unknown reason at 1.07s, it should play through to 2.23s

The testcase is a modified version of clearKey-cenc-video-playback-mse.html, which I was initially investigating. This success condition of that test is to get past 2s of timeupdate's while decrypting ClearKey, which fails because of this MSE bug. The referenced files in there have been decrypted using Bento to provide the tar file attached for pure-MSE investigation.

Outside of WebKit, the segmented files play perfectly fine using `gst-play-1.0 <(cat seg-*.mp4)`, where the movie stops correctly after 2.23s

It was not clear why the pipeline was stalling at 1.07s from the logging, tagging some MSE folk for further investigation.
Comment 1 Alicia Boya García 2019-12-15 16:42:43 PST
This bug is caused by the way some multi-threaded decoder elements like avdec_h264 are implemented: When a h264 frame is received (in the decoder chain function):

1. The new h264 frame is added to a queue that is read from one of many threads that does the actual decoding.
2. Frames that have finished decoding in these threads also go to a queue. The decoder element uses this moment to poll this queue and push downstream *all* the decoded frames in the queue. This is also done when a EOS event is received.

The downside of this design is that a case where there is an interruption of data flow (in the MSE case: no appends), there is a point where there are a lot of decoded frames but they will never go downstream because there is no code getting notified or polling the decoded frame queue.

0:00:02.390591895 582428      0x1d7dde0 TRACE              webkitmse MediaPlayerPrivateGStreamerMSE.cpp:148:debugDataProbe: avdec_h264-0:sink buffer: 0x7fc1c4bc9ea0, pts 0:00:03.000000000, dts 0:00:02.958333333, dur 0:00:00.041666666, size 1024, offset 170374, offset_end none, flags 0x2400
0:00:02.392881899 582428      0x1d7dde0 TRACE              webkitmse MediaPlayerPrivateGStreamerMSE.cpp:148:debugDataProbe: avdec_h264-0:src buffer: 0x7fc1c4bcf900, pts 0:00:01.333333333, dts 99:99:99.999999999, dur 0:00:00.041666666, size 464000, offset none, offset_end none, flags 0x0
Comment 2 Alicia Boya García 2019-12-19 13:46:57 PST
I looked deeper into the ffmpeg-based GStreamer elements, and avcodec itself. The way it actually works is simple but in some ways unexpected.

avcodec makes a ring of threads. Whenever you ask to decode a frame, it's sent to the next thread (now, the "newest"). Also, if we're not on the first loop through the ring, it also waits for the oldest thread to finish decoding, which can then be queried by the application, in this case GStreamer. Note it only waits for one specific thread (the one containing the oldest frame), and no more. Even if the thread holding the second oldest frame has also finished to decode, you *need* to send another frame to ffmpeg to decode in order to get it.

This design is relatively straightforward but it has certain consequences: namely, there is always a latency of as many frames as threads, which in default settings depends on the hardware.

On the other hand, how bad this latency is determined by how many threads are being used. Many browser developers have very powerful computers with many CPU cores/threads, which meant lots of latency and this testcase failing. By limiting the number of decoding threads to 16 (which happens to be the value before ffmpeg gives a warning), the impact of the problem is limited. Also it's just enough for the test to pass. I've sent a merge request to do exactly that: https://gitlab.freedesktop.org/gstreamer/gst-libav/merge_requests/56

Other than that, there is not much that can be done in the case of gst-libav decoder elements, since the avcodec API does not currently give you any alternatives, it's just the way it works.
Comment 3 Alicia Boya García 2019-12-22 04:44:20 PST
Created attachment 386314 [details]
Patch
Comment 4 Xabier Rodríguez Calvar 2019-12-23 07:52:56 PST
LGTM, is there any way to add a test for this?
Comment 5 Alicia Boya García 2019-12-24 17:15:58 PST
Created attachment 386394 [details]
Patch
Comment 6 Alicia Boya García 2019-12-24 17:25:40 PST
Submitted web-platform-tests pull request: https://github.com/web-platform-tests/wpt/pull/20916
Comment 7 Xabier Rodríguez Calvar 2019-12-26 06:47:54 PST
Comment on attachment 386394 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=386394&action=review

> LayoutTests/imported/w3c/web-platform-tests/media-source/mediasource-h264-play-starved.html:55
> +

For coherence, I'd remove this time
Comment 8 Alicia Boya García 2020-01-02 05:51:13 PST
Created attachment 386603 [details]
Patch
Comment 9 Alicia Boya García 2020-01-02 05:57:12 PST
Created attachment 386604 [details]
Patch
Comment 10 WebKit Commit Bot 2020-01-03 05:56:43 PST
Comment on attachment 386604 [details]
Patch

Clearing flags on attachment: 386604

Committed r253995: <https://trac.webkit.org/changeset/253995>
Comment 11 WebKit Commit Bot 2020-01-03 05:56:45 PST
All reviewed patches have been landed.  Closing bug.
Comment 12 Truitt Savell 2020-01-03 14:53:47 PST
It looks like you did not land an expectations file for imported/w3c/web-platform-tests/media-source/mediasource-h264-play-starved.html 

History:
https://results.webkit.org/?suite=layout-tests&test=imported%2Fw3c%2Fweb-platform-tests%2Fmedia-source%2Fmediasource-h264-play-starved.html
Comment 13 Alicia Boya García 2020-01-06 04:24:38 PST
(In reply to Truitt Savell from comment #12)
> It looks like you did not land an expectations file for
> imported/w3c/web-platform-tests/media-source/mediasource-h264-play-starved.
> html 
> 
> History:
> https://results.webkit.org/?suite=layout-tests&test=imported%2Fw3c%2Fweb-
> platform-tests%2Fmedia-source%2Fmediasource-h264-play-starved.html

Indeed. This was already amended in https://bugs.webkit.org/show_bug.cgi?id=205728