[wpe-2.38] Fix flushing

varumugam123 commented 11 months ago

This PR has two commits to deal with below scenarios: 1) Seeking to unbuffered range doesn't succeed (playback resumes from different position than the requested one)

gst seek is performed and MSE waits for buffer for the seek position
when data arrives, seek completion path reenqueues data in turn triggers flush
flush resets segment.time & segment.base with the current playback time
buffer is pushed downstream
Segment event is sent with the current playback time (which is not desired)
the log excerpts can be found @ https://github.com/WebPlatformForEmbedded/WPEWebKit/pull/1157#issuecomment-1722979577

2) Audio language switch during playback causes playback to start from beginning (in Prime video app)

Some sinks, like westerossink on amlogic platform, rely on segment.position for playback position calculation
when language switch is made by user, application clears audio buffer, flushing audio track
audio sink reports 0 position (after flush)
this results in westerossink's position to be returned as the playback position (as it is the greatest of the two sinks)
but westerossink's position is not correct either (as the segments we have sent before didn't have position field set)
when application queries the current position, this incorrect value is returned
app then makes a seek slightly before the correct position (100 micro second)
this ends up in a completely different playback position from where we switched the audio language

varumugam123 commented 11 months ago

Logs for the second case:

2023 Sep 20 15:17:47.057019 WPEFramework[16101]:  0:00:08.618709821 20380 0xaa105c90 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:752:webKitMediaSrcLoop:<source:src_A0> Need new SEGMENT event, pushing it: time segment start=0:01:41.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:01:41.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
2023 Sep 20 15:17:47.095958 WPEFramework[16101]:  0:00:08.637367855 20380 0x7e27dc00 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:752:webKitMediaSrcLoop:<source:src_V0> Need new SEGMENT event, pushing it: time segment start=0:01:41.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:01:41.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
2023 Sep 20 15:17:47.336958 WPEFramework[16101]:  0:00:08.830154263 20380 0x8cf44e90 DEBUG            amlhalasink gstamlhalasink_new.c:2364:gst_aml_hal_asink_pad_event:<audiosink-actual-sink-amlhala> received event 0xa5f0a4c8 segment event: 0xa5f0a4c8, time 99:99:99.999999999, seq-num 280, GstEventSegment, segment=(GstSegment)"segment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)time, base=(guint64)0, offset=(guint64)0, start=(guint64)101000000000, stop=(guint64)18446744073709551615, time=(guint64)101000000000, position=(guint64)0, duration=(guint64)18446744073709551615;";
2023 Sep 20 15:17:47.337138 WPEFramework[16101]:  0:00:08.830202306 20380 0x8cf44e90 DEBUG            amlhalasink gstamlhalasink_new.c:2150:gst_aml_hal_asink_event:<audiosink-actual-sink-amlhala> configured segment time segment start=0:01:41.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:01:41.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999

Initial position report
2023 Sep 20 15:17:48.331131 WPEFramework[16101]:  HTML5 video: Pause [mediasourceblob:https://avpk-a12ttfat8x8j46-0.api.amazonvideo.com/fe8c1b1c-1fb5-467c-9fd9-6678772f781a]
2023 Sep 20 15:17:48.331749 WPEFramework[16101]:  0:00:09.874488851 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1387:gstreamerPositionFromSinks:<MSE-media-player-0> Audio position 0:01:41.000000000, valid=1
2023 Sep 20 15:17:48.331816 WPEFramework[16101]:  0:00:09.874573978 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1393:gstreamerPositionFromSinks:<MSE-media-player-0> Video position 0:00:00.000000000, valid=1

After few seconds of playback (note, westerossink returns just the time elapsed / running time equivalent instead of the actual playback position)
2023 Sep 20 15:18:01.378085 WPEFramework[16101]:  0:00:22.941854423 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1387:gstreamerPositionFromSinks:<MSE-media-player-0> Audio position 0:01:49.061000000, valid=1
2023 Sep 20 15:18:01.378155 WPEFramework[16101]:  0:00:22.941898424 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1393:gstreamerPositionFromSinks:<MSE-media-player-0> Video position 0:00:08.083333000, valid=1

Re-enqueue flushes audio buffer, this clears audio sink's position value. From this point onwards position query on video element would return 8.125
2023 Sep 20 15:18:01.412658 WPEFramework[16101]:  [WPEWebKit:MediaSource:-] SourceBufferPrivateGStreamer::reenqueueMediaIfNeeded(7AEA0001) reenqueuing at time {"value":109.061,"numerator":109061000000,"denominator":1000000000,"flags":1}
2023 Sep 20 15:18:01.415574 WPEFramework[16101]:  0:00:22.979413343 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:887:webKitMediaSrcStreamFlush:<source> Resetting segment to current pipeline running time (0:00:08.061000000) and stream time (0:01:49.061000000)
2023 Sep 20 15:18:01.568403 WPEFramework[16101]:  0:00:23.131909760 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:919:webKitMediaSrcStreamFlush:<source> Flush request for stream 'A0' (isSeekingFlush = false) satisfied.
2023 Sep 20 15:18:01.592457 WPEFramework[16101]:  0:00:23.153351071 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1387:gstreamerPositionFromSinks:<MSE-media-player-0> Audio position 0:00:00.006812500, valid=1
2023 Sep 20 15:18:01.592616 WPEFramework[16101]:  0:00:23.153390739 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1393:gstreamerPositionFromSinks:<MSE-media-player-0> Video position 0:00:08.125000000, valid=1

App performs seek 100ms before the incorrect playback position
2023 Sep 20 15:18:01.735691 WPEFramework[16101]:  HTML5 video: Seeking from {8125000000/1000000000 = 8.125000} to {8.124900} seconds [mediasourceblob:https://avpk-a12ttfat8x8j46-0.api.amazonvideo.com/fe8c1b1c-1fb5-467c-9fd9-6678772f781a]
2023 Sep 20 15:18:01.735814 WPEFramework[16101]:  0:00:23.298883028 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:1003:webKitMediaSrcSendEvent:<source> Handling seek event: seek event: 0x7e6938a0, time 99:9
2023 Sep 20 15:18:01.894450 WPEFramework[16101]:  0:00:23.451876960 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:919:webKitMediaSrcStreamFlush:<source> Flush request for stream 'A0' (isSeekingFlush = true) satisfied.
2023 Sep 20 15:18:01.976963 WPEFramework[16101]:  0:00:23.541006555 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:919:webKitMediaSrcStreamFlush:<source> Flush request for stream 'V0' (isSeekingFlush = true) satisfied.

2023 Sep 20 15:18:02.078412 WPEFramework[16101]:  HTML5 video: Seeking from {8.124900} to {8.124800} seconds [mediasourceblob:https://avpk-a12ttfat8x8j46-0.api.amazonvideo.com/fe8c1b1c-1fb5-467c-9fd9-6678772f781a]
2023 Sep 20 15:18:02.078479 WPEFramework[16101]:  0:00:23.642314763 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:1003:webKitMediaSrcSendEvent:<source> Handling seek event: seek event: 0x7e693a08, time 99:99:99.999999999, seq-num 816, GstEventSeek, rate=(double)1, format=(GstFormat)time, flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH, cur-type=(GstSeekType)set, cur=(gint64)8124800000, stop-type=(GstSeekType)none, stop=(gint64)0, trickmode-interval=(guint64)0;
2023 Sep 20 15:18:02.232655 WPEFramework[16101]:  0:00:23.795921371 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:919:webKitMediaSrcStreamFlush:<source> Flush request for stream 'A0' (isSeekingFlush = true) satisfied.
2023 Sep 20 15:18:02.235083 WPEFramework[16101]:  0:00:23.798917919 20380 0xaa0040a0 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:919:webKitMediaSrcStreamFlush:<source> Flush request for stream 'V0' (isSeekingFlush = true) satisfied.

2023 Sep 20 15:18:02.861148 WPEFramework[16101]:  [WPEWebKit:MediaSource:-] MediaSource::completeSeek(0) {"value":8.1248}
2023 Sep 20 15:18:02.861261 WPEFramework[16101]:  [WPEWebKit:MediaSource:-] SourceBuffer::seekToTime(7AEA0001) {"value":8.1248}
2023 Sep 20 15:18:02.861330 WPEFramework[16101]:  [WPEWebKit:MediaSource:-] SourceBufferPrivateGStreamer::seekToTime(7AEA0001) Reenqueue samples in track "A0", {"value":8.1248}
2023 Sep 20 15:18:02.862484 WPEFramework[16101]:  0:00:24.416829832 20380 0xaa105c90 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:752:webKitMediaSrcLoop:<source:src_A0> Need new SEGMENT event, pushing it: time segment start=0:00:08.124800000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:08.124800000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
2023 Sep 20 15:18:02.884165 WPEFramework[16101]:  0:00:24.424586564 20380 0x8cf44e90 DEBUG            amlhalasink gstamlhalasink_new.c:2150:gst_aml_hal_asink_event:<audiosink-actual-sink-amlhala> configured segment time segment start=0:00:08.124800000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:08.124800000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
2023 Sep 20 15:18:02.912893 WPEFramework[16101]:  0:00:24.442209635 20380 0x7e27dc00 DEBUG         webkitmediasrc WebKitMediaSourceGStreamer.cpp:752:webKitMediaSrcLoop:<source:src_V0> Need new SEGMENT event, pushing it: time segment start=0:00:08.124800000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:08.124800000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999

2023 Sep 20 15:18:04.462352 WPEFramework[16101]:  0:00:26.020865641 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1387:gstreamerPositionFromSinks:<MSE-media-player-0> Audio position 0:00:08.124800000, valid=1
2023 Sep 20 15:18:04.462610 WPEFramework[16101]:  0:00:26.020906309 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1393:gstreamerPositionFromSinks:<MSE-media-player-0> Video position 0:00:00.000000000, valid=1
2023 Sep 20 15:18:04.463256 WPEFramework[16101]:  0:00:26.020933393 20380 0xaa0040a0 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1434:playbackPosition:<MSE-media-player-0> Position 0:00:08.124800000, canFallBackToLastFinish

calvaris commented 11 months ago

@varumugam123 . I understand the use cases but I would appreciate if you could provide some files to trigger them.

varumugam123 commented 11 months ago

Hi, @calvaris The incorrect seeking & position reports issue could be reproduced with below test apps: seek-to-unbuffered-range.html.txt audio-switch.html.txt

calvaris commented 11 months ago

@varumugam123 I was trying in the reference box with westeros sink with a custom test that did and without using these patches:

play
seek
check the segments in westeros sink.

And with that I can't see any issue. I'll try with the examples you mention but if there is something in my setup that I am missing, please let me know.

varumugam123 commented 11 months ago

Hi @calvaris, I have been trying them on AMlogic device which has a westerossink (which internally uses v4l2). Could you please try below sample and share if the forward & rewind seeking are working fine on the reference board? On my device, the forward seek to 12.5 itself didn't succeed.

seek-to-unbuffered-range-rewind.html.txt

For the "Issue during audio language switch" case, please monitor the currentTime post the audio data replacement. It returns incorrect position.

calvaris commented 11 months ago

I just pushed 8a6a01511e58f0a42c98084938e759938c4ec1f8 that should fix this issue. Closing.

varumugam123 commented 10 months ago

Hi @calvaris, I tried the commit, but I run into issues with below use cases

URL	Issue
audio-switch.html	After sample replacement, reported currentTime went back for a short period
sample-replacement.html?reenqueueVideoAt=3	Video Repetition i.e 0-3, 0-12
sample-replacement.html?reenqueueVideoAt=3&removeDataOnReenqueue=true	Playback gets stuck @ 3 seconds (after video buffer replacement) randomly
sample-replacement.html?reenqueueVideoAt=3&reenqueueAudioAt=3&removeDataOnReenqueue=true	(1) Short video repetition (2) Video gets stuck @ 3 seconds and audio continues to play

audio-switch.html.txt sample-replacement.html.txt

Could you check?

calvaris commented 10 months ago

@varumugam123 in which platform are you trying?

varumugam123 commented 10 months ago

XClass TV which has AMLogic SoC. This device uses westerossink & amlhalasink for playback

calvaris commented 10 months ago

Just pushed 98827e77d1f9d263ec769632f59d9c27d6b19c08 that should fix this. Closing.

varumugam123 commented 10 months ago

Hi @calvaris Thanks for the fix.

May I know if there are any cases this commit is breaking 91573329077e1219d306f088db62f3cf717686dc?

calvaris commented 10 months ago

I don't know if there are any use cases breaking with that commit but it was not the proper solution.

varumugam123 commented 10 months ago

Pardon me, I meant to ask about this 7b3682a9e84d54173e266967b72c2c27f1c18a66. Could you help to understand why this one is not considered to be taken?

calvaris commented 10 months ago

Mainly because one reason: this should be fixed in the sink itself. Sinks should not rely in Segment.position.

WebPlatformForEmbedded / WPEWebKit

[wpe-2.38] Fix flushing #1196