search

WebPlatformForEmbedded / WPEWebKit

WPE WebKit port (downstream)
210 stars 135 forks source link

[2.38] Seek is completed before dispatching 'seeking' event #1347

Open asurdej-comcast opened 3 weeks ago

asurdej-comcast commented 3 weeks ago

We have an issue in Spotify app that progress bar doesn't show correct value after seeking in webkit 2.38. The app relies on "seeking" and "seeked" events and also checking "video.seeking" property. Based on that it changes progress bar position.

The issue with 2.38 is that MSE seek into buffered range is finished before "seeking" event is dispatched to JavaScript. As a result video.seeking is always "false" that is confusing to the app. Seeking sequence looks like below: 1) Seek is requested by Spotify 2) HTMLMediaElement schedules "seeking" event and starts player seeking 3) Player flushes gst pipeline, provides new data and reports finishSeek() to HTMLMediaElement (from ASYNC_DONE -> didPreroll() -> timeChanged() -> mediaPlayerTimeChanged -> finishSeek() 4) "seeking" event is finally delivered to JavaScript but video.seeking property was reset to 'false' in finishSeek() above It all runs in the main thread. HTML media element uses different task queue to dispatch events and GST messages are handled first.

At glance it looks like application issue but on the other hand application has no way to notice video.seeking property. We had similar issue for audio-only streams fixed by https://github.com/WebPlatformForEmbedded/WPEWebKit/pull/1232 but in that case whole seeking flow was handled in single task so all other queues were blocked until seek is finished.

Can you please advise if there is anything to be improved on webkit side here? Should we maybe try to synchronize MediaPlayer updates with HTMLMedieElement events to ensure proper order. What do you think

asurdej-comcast commented 3 weeks ago

Full logs attached. spotify_progressbar_logs.txt

Seek start:

Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::seek(AF8F473F) {"value":0}
Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::seekWithTolerance(AF8F473F) time = {"value":0}, negativeTolerance = {"value":0,"numerator":0,"denominator":1,"flags":1}, positiveTolerance = {"value":0,"numerator":0,"denominator":1,"flags":1}
Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: 0:00:51.781915499    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:685:currentMediaTime:<MSE-media-player-0> seeking: false, seekTime: {0}
Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: 0:00:51.781967811    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1435:playbackPosition:<MSE-media-player-0> isEndReached: false, seeking: false, seekTime: {0}
Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: 0:00:51.782149631    20  0x1d9fd20 INFO              GST_STATES gstbin.c:2115:gst_bin_get_state_func:<MSE-media-player-0> getting state

Seek task:

Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::seekTask(AF8F473F)
Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: 0:00:51.812337333    20  0x1d9fd20 DEBUG              webkitmse MediaPlayerPrivateGStreamerMSE.cpp:246:seek:<MSE-media-player-0> Requested seek to {0}
Jun 14 11:22:26 hisense-v2 HtmlApp-0[5779]: 0:00:51.812393730    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:685:currentMediaTime:<MSE-media-player-0> seeking: false, seekTime: {0}

Seek completed:

Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.446954823    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1454:playbackPosition:<MSE-media-player-0> Position 0:00:00.200200000, canFallBackToLastFinishedSeekPosition: true
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.446999632    20  0x1d9fd20 DEBUG              webkitmse MediaPlayerPrivateGStreamerMSE.cpp:386:didPreroll: Seek complete because of preroll. currentMediaTime = {200200000/1000000000 = 0.2002}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::mediaPlayerTimeChanged(AF8F473F)
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::currentMediaTime(AF8F473F) seeking, returning{"value":0}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.447123138    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:685:currentMediaTime:<MSE-media-player-0> seeking: false, seekTime: {0}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.447155984    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1435:playbackPosition:<MSE-media-player-0> isEndReached: false, seeking: false, seekTime: {0}
Jun 14 11:22:28 hisense-v2 audio_server[5739]: [11312.623432]: INFO  handle_mode_change_a:1496: [1]av_sync amode 1 mode 1 v/a/vt 1/1/0 stat 2
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.447189747    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1448:playbackPosition:<MSE-media-player-0> Returning cached position: {200200000/1000000000 = 0.2002}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::finishSeek(AF8F473F) current time = {"value":0.2002,"numerator":200200000,"denominator":1000000000,"flags":1}

'seeking' event dispatched:

Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.452674282    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1435:playbackPosition:<MSE-media-player-0> isEndReached: false, seeking: false, seekTime: {0}
Jun 14 11:22:28 hisense-v2 audio_server[5739]: [11312.653730]: INFO  handle_mode_change_a:1496: [1]av_sync amode 1 mode 1 v/a/vt 1/1/0 stat 2
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.452703960    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1448:playbackPosition:<MSE-media-player-0> Returning cached position: {200200000/1000000000 = 0.2002}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: [HtmlApp-0]:0 HTMLMediaElement::seekTask(AF8F473F)
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::dispatchEvent(AF8F473F) seeking
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.453082106    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:685:currentMediaTime:<MSE-media-player-0> seeking: false, seekTime: {0}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.453194733    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1435:playbackPosition:<MSE-media-player-0> isEndReached: false, seeking: false, seekTime: {0}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: 0:00:52.453230872    20  0x1d9fd20 TRACE      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1448:playbackPosition:<MSE-media-player-0> Returning cached position: {200200000/1000000000 = 0.2002}
Jun 14 11:22:28 hisense-v2 HtmlApp-0[5779]: [WPEWebKit:Media:-] HTMLMediaElement::setPlaybackRate(AF8F473F) 1
calvaris commented 2 days ago

Can you please provide a standalone html file testing this?