WebPlatformForEmbedded / WPEWebKit

WPE WebKit port (downstream)
213 stars 136 forks source link

WPE 2.22 - Missing mechanism "pause for buffering" #792

Closed przemyslaw-gorszkowski-red closed 2 years ago

przemyslaw-gorszkowski-red commented 2 years ago

When the internet connection is poor, the playback is not paused for buffering which leads to playing the playback without audio and with some kind of slower video.

The problem can be observed on CNN app:

https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#app:com.metrological.app.CNN

Just try to play any content with poor internet connection.

I attached the recording of this case:

https://user-images.githubusercontent.com/47318228/155150273-87d4a5bc-344f-420f-a47e-2b5678833cd8.mp4

The problem is observed on WPE 2.22

przemyslaw-gorszkowski-red commented 2 years ago

It seems that there are few fixes available on newer version WPE which partially can help in this case:

  1. first updates in MediaPlayerPrivateGStreamer::processBufferingStats: https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/41c2c9a3dd17906af7e313a7d467ca74c9806a83
  2. Several buffering fixes : https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/810d92c69f4fde34a5f735dd795b5ff02b8eabf7
  3. Gathering information about number of bytes downloaded and totalBytes by webkitwebsrc element : https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/7d478016417a09d9575814c19e7cb744db5699bc

The fix 2. turn on the "pause for buffering" mechanism, but in case of BRC+gstreamer, the pipeline with qstueue2 with queue this fix is not perfect because the GST_MESSAGE_BUFFERING can fluctuate especially after first start or seek. The fix from: https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/14f712084b349ab70e87352d73dc02ee42c1a99e can help here somehow but also is not perfect.

The fix 3 can be used to calculate/estimate how much data is downloaded and ready to be pushed to playpump. It can be used to decide should we go in "pause for buffering" or not (additional condition if we know that gstqueue2 is not full and playpump also not fill enough but we have data downloaded and soon it will be provided to playpump)

eocanha commented 2 years ago

I've been able to reproduce the issue here and I'm currently looking into it.

It's true that the buffering code as it is in wpe-2.22 seems only focused on managing the initial buffering and has no algorithm in place to detect buffering underrun and pause the playback. There used to be code for that, but @woutermeek removed it in https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/10f97c849c8c4693986060a2ef7ab8316dc74ebb, I don't know or remember why. An evolution of that code chunk is still present upstream.

@woutermeek, would it be wise to readd that code? Can you remember any reason why it was removed in the first place?

Still reverting that patch doesn't seem to be enough here and I would need to keep debugging why.

przemyslaw-gorszkowski-red commented 2 years ago

I think the reason was some "hiccups" of the playback after seek or start the playback. The reason can be playpump which consumes very fast data until it fills its buffers. So after starting the playback(queue2 reports 100%, and the playback starts), then playpump consumes data which causes that queue2 reports <100% of buffers what causes the pause - so we have playing->pause->playing->pause.... It can happen few times at the beginning of the playback - which is seen as "hiccup".

Probably the fix from https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/14f712084b349ab70e87352d73dc02ee42c1a99e can minimize this, but maybe before WPE goes in "pause for buffering" it should also check how much data are downloaded and base on that decides about "pause for buffering".

woutermeek commented 2 years ago

As far as I can recall it was indeed to have a smoother the start of playback, maybe it is not needed anymore with https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/14f712084b349ab70e87352d73dc02ee42c1a99e

przemyslaw-gorszkowski-red commented 2 years ago

I did tests with fix from https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/14f712084b349ab70e87352d73dc02ee42c1a99e but the hiccups are still there.

woutermeek commented 2 years ago

Maybe we should fix the hiccups in a different way, and add this code back for pause during buffering. What do you think @eocanha ?

przemyslaw-gorszkowski-red commented 2 years ago

Here you have our fixes which update m_maxTimeLoaded bases on network stats in case of disable buffering on disk: https://github.com/LibertyGlobal/WPEWebKit/commit/f2eac16c26526dc518164732b094bedd20487625 - it also fixes getting the buffered range function(MediaPlayerPrivateGStreamer::buffered) and some updates/fixes for it: https://github.com/LibertyGlobal/WPEWebKit/commit/5303dd00323bbd6e983a77293e61a4433fe00cea https://github.com/LibertyGlobal/WPEWebKit/commit/324d9f4941b888fff702cce22f098df70b60853c

eocanha commented 2 years ago

I've just porce-pushed https://github.com/WebPlatformForEmbedded/WPEWebKit/commits/eocanha/eocanha-114, where I did a minor cosmetic change to the buffering correction patch and added a new commit to pause the pipeline when buffering reaches 0%.

Here the pausing/restarting scheme is working fine for me. The video will pause when there's 0% global (queue2 + playpump) buffering, and restart again when global buffering reaches 100% again. As the extreme percentages are used, the pause<->play changes are more spaced. If video bandwidth is low, the video will play for a while (as full buffer allows), pause for a while, and then play for a while again, but no stuttering like before.

Please, give it a try and tell me if it works fine in your case.

przemyslaw-gorszkowski-red commented 2 years ago

I tested these two fixes during the weekend with few of our applications and different type of the streams (progressive, adaptive streaming - MSS - handled by gstreamer). I tested it with and without limited internet connection.

My test was done without buffering on disk (so queue2 with queue and GST_BUFFERING_STREAM buffering mode).

It seems to work without any serious regressions. As you mentioned, with limited internet connection the playback plays for a while and then pause for buffering, and re-play again for a while.

When the playback starts for the first time or after seek it takes a while till it starts to play but with limited internet it is expected.

Do you think that this solution can be applied also for non GST_BUFFERING_STREAM mode of the buffering?

przemyslaw-gorszkowski-red commented 2 years ago

Ok, I think I found some issue with MPEG-DASH (handled by gstreamer). Example: https://bitmovin-a.akamaihd.net/content/sintel/sintel.mpd It starts without any problems but if I change the currentTime it goes to that new position and pause. Without "pause for buffering" after new position it starts play without problem. I am checking what can be the reason of this issue.

przemyslaw-gorszkowski-red commented 2 years ago

It seems that the problem with PAUSED state after seek is common for adaptive: MPEG-DASH, MSS, and non adaptive: progressive streams (one mp4 file).

It seems that after "pause for buffering" and "restarting playback after pause for buffering" the pipeline changes the state from PAUSE to PLAYING but right after that due to : HTMLMediaElement::setReadyState and HTMLMediaElement::updatePlayState the pipeline changes the state one more time from PLAYING to PAUSED - which causes this PAUSED state of the pipeline after seek

przemyslaw-gorszkowski-red commented 2 years ago

@eocanha : I added a comment to your proposal: https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/c7c35c641ca31eae1100e07e0995292df162655b which can fix the regression after your proposal.

eocanha commented 2 years ago

I've force-pushed again https://github.com/WebPlatformForEmbedded/WPEWebKit/commits/eocanha/eocanha-114 and added lines to update m_currentState, which has been enough to solve the "paused after seek" issues.

Let me know if the current state of the branch is good enough for your use case. I've successfully tested it with seeks on regular video, mpeg-dash and on your CNN app test case (with and without bandwidth changes to trigger rebuffering).

przemyslaw-gorszkowski-red commented 2 years ago

@eocanha thanks for the updated fix. We are testing it. During these tests we observe some "additional" breaks(because of "pause for buffering") at the beginning of the playback. I think that this is a negative consequence of "pause for buffering" mechanism. It happens even with good network connection condition (7-8 MB/s). The problem with additional breaks(pause for buffering) is seen much more on apps: MoodLounge or Euronews

The reason of that is probably because at the beginning of playback the data can be somewhere between queue2 and vidfilter, or the data are downloaded by not yet pushed to queue2.

rychem commented 2 years ago

@eocanha can we ask for your feedback on Przemyslaw's description of side efect?

eocanha commented 2 years ago

Sorry, I couldn't devote time to this issue in the past days.

I've tried to reproduce the issues without success in the apps you mentioned, using a bandwidth of 7 MB/s.

It's true that I noticed some back and forth buffer level before the initial paused-playing change, but after the change to playing the video never had to return to paused for rebuffering. In theory, the total buffer level (including playpump corrections) should have been monotonically increasing, but it wasn't. In your specific videos, there's a multiqueue between queue2 and aud/vidfilter that can hold up to 2MB of data, and maybe that's what causes those differences.

Having into account all the possible intermediate queues is going to be a bit hard to scale, since they depend on the specific kind of video being played (regular video, several adaptive streaming variants (DASH, HLS, MS SmoothStreaming), etc.)

Could you please provide some logs with GST_DEBUG='queue2:DEBUG,webkit*:DEBUG' for me to analyze? The goal for me would be to process it and get the buffering and state changing evolution like in the log.zip attached example, where I'm experiencing no pause for rebuffering when playing the "red shoes video" in MoodLounge.

przemyslaw-gorszkowski-red commented 2 years ago

In this logs from the "fireplace" video we can observe one "pause for buffering" right after it starts to play. I added logs which tell us the value of the "buffered-bytes" from vid filter when the queue2 reports the level of its buffers. It seems that in some cases the queue2 and playpump can be empty right after the playback starts to play. Logs: fireplace_hiccups.log

przemyslaw-gorszkowski-red commented 2 years ago

The logs with queue2: fireplace_hiccups_with_queue2.log It seems that when MediaPlayerPrivateGStreamer starts to process received GST_MESSAGE_BUFFERING the actual bytes buffer level is/can be completely different(which is rather obvious). My proposal is that maybe in case reported 0% we can double check the actual bytes buffer level on queue2 by getting the property "current-level-bytes".

przemyslaw-gorszkowski-red commented 2 years ago

So diff of my proposal is:

diff --git a/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp b/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
index ff6180e3cbde..53f08c27a8a8 100644
--- a/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
+++ b/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
@@ -1538,6 +1538,14 @@ void MediaPlayerPrivateGStreamer::processBufferingStats(GstMessage* message)
         // Current-level-bytes seems to be inacurate, so we compute its value from the buffering percentage
         g_object_get(queue2, "max-size-bytes", &maxSizeBytes, nullptr);

+        if (m_bufferingPercentage == 0) {
+            guint currentLevelBytes = 0;
+            g_object_get(queue2, "current-level-bytes", &currentLevelBytes, nullptr);
+            GST_DEBUG("[Buffering] currentLevelBytes: %d.", currentLevelBytes);
+            m_bufferingPercentage = currentLevelBytes > maxSizeBytes ? 100 : (int)(currentLevelBytes*100/maxSizeBytes);
+            GST_DEBUG("[Buffering] UPDATED m_bufferingPercentage: %d.", m_bufferingPercentage);
+        }
+
         guint playpumpBufferedBytes = 0;
         g_object_get(GST_OBJECT(m_vidfilter.get()), "buffered-bytes", &playpumpBufferedBytes, nullptr);
eocanha commented 2 years ago

That's a good measure that I'm going to add to the code.

Still, after analyzing the provided log, I saw a weird situation: queue2 filled (and playpump empty), then emptied (allegedly because it outputed all its content to downstream elements) but with playpump still empty. Looks like the buffers have vanished, but they're likely in multiqueue, in an up to 2MB unaccounted limbo:

pipeline.svg

eocanha commented 2 years ago

I've updated the https://github.com/WebPlatformForEmbedded/WPEWebKit/commits/eocanha/eocanha-114 branch with two new commits. One includes the change you propose, and the other tries to get the buffered bytes from the multiqueue (when present) and account them as part of the buffered percentage.

Unfortunately, the latter requires the "stats" multiqueue property to be implemented (it just does nothing if it isn't). The property appeared in this commit and is present only since gst 1.18. We're still using 1.16, so we can't take advantage of that feature.

If your proposed solutions keeps not being enough, maybe I could try to backport that commit as a buildroot gstreamer1 customization and see if accounting for multiqueue buffering definitely solves the issue.

przemyslaw-gorszkowski-red commented 2 years ago

Unfortunately we use gstreamer 1.10.4, but backporting the "stats" multiqueue property is not problematic.

The combo fix (multiqueue, current-level-byte from queue2 and playpump buffers) gives much better results. From logs I can see that sometimes current-level-byte from queue2 and playpump buffers are empty but there are some bytes in multiqueue(base on "stats" property). We will do much more tests for this solution and give you feedback about the result and then we can push these fixes.

przemyslaw-gorszkowski-red commented 2 years ago

Unfortunately we found that there are still some additional "pause for buffering" with normal network connection. Here you can find logs with that cases(I added there some more logs which show the buffers levels - for queue2, multiqueue and playpump): euronews_pause_for_buffering_queue2_playpump_multiqueue.txt

eocanha commented 2 years ago

What I see there is that playpump goes from 836435 bytes to 0 between 1:32:42.596885827 and 1:32:42.696915800 (extremely quickly) and almost never recovers from that situation until the video is paused by buffer starving (1:32:42.916838400).

Also, the queue2 maxSizeBytes capacity goes from 2MB to 1MB at some point, giving much less buffering margin to compensate for network bumps. I don't understand why that happens, since uridecodebin just sets queue2 max-size-bytes with the value of its own buffer-size property, which in turn is the value of playbin's buffer-size, which isn't ever set by MediaPlayerPrivateGStreamer. I might try to debug a little more here to understand who might be changing and deciding the internal queue2/uridecodebin/playbin buffer size and "convince" it to choose a larger buffer to have more stability.

At this point I don't know either why playpump consumes its data so quickly. Do you know any other way (alternative to querying playpump) to get a better estimation of the internal Nexus buffering level?

przemyslaw-gorszkowski-red commented 2 years ago

Yes, I also noticed this strange change of the maxSizeBytes capacity from 2MB to 1MB but not investigate it too much. What I observed is that this change is around the time when the pipeline goes to PLAYING state.

I will try to find the reason of that quick consumption of data by playpump and maybe other way for estimation of the buffering level of Nexus.

przemyslaw-gorszkowski-red commented 2 years ago

I found the reason of that maxSizeBytes capacity change, It is reset in configure_stream_buffering function of the gsturidecodebin.:


0:00:27.478966532    16   0x207060 DEBUG           uridecodebin gsturidecodebin.c:1067:configure_stream_buffering:<uridecodebin0> overall bitrate 6137874
0:00:27.478996050    16   0x207060 DEBUG                 queue2 gstqueue2.c:3822:gst_queue2_get_property:<queue2-0> gst_queue2_get_property prop_id:6
0:00:27.479018347    16   0x207060 DEBUG           uridecodebin gsturidecodebin.c:1079:configure_stream_buffering:<uridecodebin0> queue buffering time 0:00:02.000000000
0:00:27.479052754    16   0x207060 DEBUG           uridecodebin gsturidecodebin.c:1097:configure_stream_buffering:<uridecodebin0> corresponds to buffer size 1534468
0:00:27.479085051    16   0x207060 DEBUG                 queue2 gstqueue2.c:3732:gst_queue2_set_property:<queue2-0> gst_queue2_set_property prop_id:5
0:00:27.479103236    16   0x207060 DEBUG                 queue2 gstqueue2.c:3741:gst_queue2_set_property:<queue2-0>  PROP_MAX_SIZE_BYTES queue->max_level.bytes:1534468
eocanha commented 2 years ago

Looking at the code, it seems that automatic configuration can be overridden by setting the buffer-size property in decodebin, which in turn is controlled by the buffer-size property in playbin. We have two options now:

przemyslaw-gorszkowski-red commented 2 years ago

@eocanha : regarding to vidfilter buffer - at the beginnig of playback it can be quickly consumed by viddecoder. viddecoder consumes the data from vidfilter till it fills its own buffer. So propably we need to check also viddecoder buffer to check its buffer level.

I tested also does this changing of the queue2 buffer size(from 2->1MB) have impact on the hiccups with normal network connection: even the buffer size is always 2MB the hiccups still appear(I did it by ignoring the set property in case of queue2 and PROP_MAX_SIZE_BYTES).

My next tests will be taking into consideration the viddecoder buffer level before "pause for buffering"(together with queue2, multiqueue and vidfilter buffer level).

eocanha commented 2 years ago

I wasn't fully aware about the Nexus video decoder having (or at least considering) its own buffering level, but I've now seen the buffered-bytes property in the code. The interactions I've had with Nexus in the past just showed me that once a GStreamer buffer enters aud/vidfilter, it's already into Nexus and out of the control of GStreamer (the buffers that GStreamer sees beyond the filter are just dummy buffers). That's why I thought that the only relevant buffering was done by playpump (related in some way to the filters). Now that I know that this new way to ask for other internal buffering levels that add to playpump one exists, I see that it can be very useful to solve the problem.

przemyslaw-gorszkowski-red commented 2 years ago

I tested the implementation of the "pause for buffering" with: buffering level from queue2 + multiqueue + vid filter + vid decoder.

There are still some not needed "pause for buffering" in case of good network condition (~12MB/s for problematic file: https://video-partners.euronews.com/mp4/1080p/EN/NW/SU/22/03/25/en/220325_NWSU_45673495_45673498_190160_224202_en.mp4)

The logs from this case: euronews_pause_for_buffering_queue2_playpump_multiqueue_vidfilter_viddecoder.txt

Additionally with slow network, sometime the "pause for buffering" works as expected but sometime I observe the behaviour as it was without this mechanism which is slow motion without audio (probably underflow on the decoder side). I will gather the lgs from that case and provide here.

przemyslaw-gorszkowski-red commented 2 years ago

Here you can find the logs with underflows when "pause for buffering" bases on buffering level from queue2 + multiqueue + vid filter + vid decoder and the network connection is slow. euronews_pause_for_buffering_queue2_playpump_multiqueue_vidfilter_viddecoder_underflows.txt.zip

rychem commented 2 years ago

@eocanha would you please be kind to check recent Przemyslaw comments ?

przemyslaw-gorszkowski-red commented 2 years ago

My suggestion in such case is to remove buffered_bytes taken from vid decoder and maybe take the change from https://github.com/LibertyGlobal/WPEWebKit/pull/50/commits/574e05cbe0428112c02827ec8ce835f460a1cbcf and reuse it in "pause for buffering" decision.

So base on network-statistics we can calculate/estimate the m_maxTimeLoaded, before "pause for buffering" we can check also how much data(time) we have and compare to current time of playback(so we will know how much time we have buffered from network) and with some threshold we can decide to go or not in "pause for buffering" (it can be done only when queue2, multiqueue and vidfilter buffers are empty).

eocanha commented 2 years ago

Sorry, I've been swamped in other tasks these days and haven't had the opportunity to move this task forward yet.

eocanha commented 2 years ago

What I see in the euronews_pause_for_buffering_queue2_playpump_multiqueue_vidfilter_viddecoder.txt test case is that the final computed buffering is always too close to 0%, but only reaching the actual 0% value a few times and not in a sustained way long enough to trigger the "pause for rebuffering" mechanism. Hence, the pipeline is kept in playing and video stuttering caused by starvation may appear.

I only see a way forward for this case: On the one hand, artificially increasing the queue2 size (increase the buffering, or what we consider as a full buffer, no matter if the data is actually in queue2, multiqueue, playpump or the video decoder). On the other hand, consider a safer low watermark for triggering "pause for rebuffering". For instance, below 5 or 10%, instead of when reaching 0%. That way Nexus still has a little video to play when rebuffering is triggered.

About your suggestion of using m_maxTimeLoaded for the slow network case, I'm not sure: you want to be protected from underflows, but suggest to only apply the alternative m_maxTimeLoaded buffer estimation (which will only increase the computed buffered percentage) when the regular buffer is already 0%. Please correct me if I understood any of the assumptions wrong, but that's only going to make the underflow problem worse. Something to trigger rebuffering earlier is what would actually be needed in this case. That's why I think the proposal I made above about increasing the low water mark to 5-10% would be more beneficial to also prevent this case from happening.

przemyslaw-gorszkowski-red commented 2 years ago

@eocanha : sorry for late response but I was analyzing your suggestions and I am still testing some options (also with increasing the queue2 size and increasing the low watermark for trigerring "pause for buffering").

My main concern here is that by increasing the low watermark for triggering "pause for buffering" we will increase also a probability of not needed "pause for buffering" in case of good network connection.

Regarding to maxTimeLoaded solution: it i snot necessary would increase the problem with underflow. The reason can be that if we have some data downloaded but not yet in queue2, multiqueue or vidfilter(I will ignore the status of the buffer in viddecoder) - for example 2 seconds after the current time - it will tell us that soon the data will be available in rest of the buffers. The pause of buffering will be triggered only if the queue2, multiqueue and vidfilter are empty and there is no at least 2 seconds data more than current time.

I am testing all solutions:

  1. increase queue2 buffer size,
  2. increase low watermark for triggering "pause for buffering"
  3. use maxTimeLoaded in case queue2, multiqueue and vidfilter are empty When I gather results I will provide the feedback.
przemyslaw-gorszkowski-red commented 2 years ago

In the file euronews_pause_for_buffering_queue2_playpump_multiqueue_vidfilter_viddecoder_maxtimeloaded.txt you can find logs which I gathered with disabled mechanism "pause for buffering" and increased queue2 size to 6MB. I disabled it to gather more information about the buffers level in case of problematic case. We can observe there that the problem with 0% of the buffers(0:04:01.825181558) can be observed even with the increased queue2 buffer level to 6MB and when the pipeline is in PLAYING state( 0:04:01.028530991). Additionally we can see there that in that time the maxTimeLoaded is 6.380216s(it is estimated base on how much data is downloaded with the size of the mp4 file) while the current position is: 0.400000. This shows us that there are a lot of data which are not transferred yet to pipeline but already downloaded.

przemyslaw-gorszkowski-red commented 2 years ago

I tested the build which base on fix(https://github.com/LibertyGlobal/WPEWebKit/commit/211b8d61bf5a610179af680d7537cd69529a6c27) from branch: https://github.com/LibertyGlobal/WPEWebKit/tree/pgorszkowski/ARRISEOS-41318/1 and during that tests I didn't observe the problem with not needed "pause for buffering" in case of good network connection. It behaves also as expected in case bad network connection - "pause for buffering" -> play some content -> "pause for buffering" -> play some content....

przemyslaw-gorszkowski-red commented 2 years ago

One more thing which I observed during my tests: there is a problem when the playback starts and the playback is manually paused and then WPE gets the message with buffering 100% - this causes that playback starts to play - which is wrong because it was intentionally paused by the user.

This issue is observed with and without my fix from https://github.com/LibertyGlobal/WPEWebKit/commit/211b8d61bf5a610179af680d7537cd69529a6c27. It is also observed on WPE which bases on branch from 2017.

I assume that the reason of this issue(unpausing the paused manually playback when it starts) is that WPE tries to start the playback when it gets message that the buffers are full and it is currently in PAUSED state.

@eocanha : do you think I should create a separate ticket for this?

przemyslaw-gorszkowski-red commented 2 years ago

I reported the problem with restarting automatically the playback after manual pause: https://github.com/WebPlatformForEmbedded/WPEWebKit/issues/831

eocanha commented 2 years ago

In the file euronews_pause_for_buffering_queue2_playpump_multiqueue_vidfilter_viddecoder_maxtimeloaded.txt you can find logs which I gathered with disabled mechanism "pause for buffering" and increased queue2 size to 6MB. I disabled it to gather more information about the buffers level in case of problematic case. We can observe there that the problem with 0% of the buffers(0:04:01.825181558) can be observed even with the increased queue2 buffer level to 6MB and when the pipeline is in PLAYING state( 0:04:01.028530991). Additionally we can see there that in that time the maxTimeLoaded is 6.380216s(it is estimated base on how much data is downloaded with the size of the mp4 file) while the current position is: 0.400000. This shows us that there are a lot of data which are not transferred yet to pipeline but already downloaded.

I suspected that the pending data might be buffered by the appsrc inside WebKitWebSrc, so I added extra code here to ask for current-level-bytes to WebKitWebSrc (which asks to its appsrc). However, I'm always seeing 0 current-level-bytes buffered in that appsrc. I need to double check my code because it has to be some kind of bug.

There's one corner case that doesn't convince me completely about computing maxTimeLoaded using offset and size of the network request, though. You're assuming that there's a single big download of all the file but... what happens on seeks? If you seek near the middle or end of the file, the demuxer will request the file from the middle/end and the offset and size might not correspond anymore to absolute offsets in the file, but relative to the place where the new playback is starting.

I tested the build which base on fix(https://github.com/LibertyGlobal/WPEWebKit/commit/211b8d61bf5a610179af680d7537cd69529a6c27) from branch: https://github.com/LibertyGlobal/WPEWebKit/tree/pgorszkowski/ARRISEOS-41318/1 and during that tests I didn't observe the problem with not needed "pause for buffering" in case of good network connection. It behaves also as expected in case bad network connection - "pause for buffering" -> play some content -> "pause for buffering" -> play some content....

So, does that branch solve the problem? That's good news.

I reported the problem with restarting automatically the playback after manual pause: https://github.com/WebPlatformForEmbedded/WPEWebKit/issues/831

Ok, I'll look into it separately.

przemyslaw-gorszkowski-red commented 2 years ago

There's one corner case that doesn't convince me completely about computing maxTimeLoaded using offset and size of the network request, though. You're assuming that there's a single big download of all the file but... what happens on seeks? If you seek near the middle or end of the file, the demuxer will request the file from the middle/end and the offset and size might not correspond anymore to absolute offsets in the file, but relative to the place where the new playback is starting.

We get from webkitwebsrc always the absolute offset in the file and its size in "webkit-network-statistics" structure of the GST_MESSAGE_ELEMENT. So it works as expected also in case of seeks (also tested). Here is example case with seek to almost at the end of file:


0:29:02.503810361    16    0x6ebc0 INFO       webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:658:seek: [Seek] seeking to {3500.000000}
0:29:03.358648126    16    0x6ebc0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1567:handleMessage:<play_0x85e18900> Updated network read position 896602655, size: 923208974
0:29:03.487820803    16    0x6ebc0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1567:handleMessage:<play_0x85e18900> Updated network read position 896925559, size: 923208974
0:29:03.578901097    16    0x6ebc0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1567:handleMessage:<play_0x85e18900> Updated network read position 897581056, size: 923208974```
przemyslaw-gorszkowski-red commented 2 years ago

So, does that branch solve the problem? That's good news.

Yes, with changes from that branch it seems to work as expected in both cases, with good and bad network connection

przemyslaw-gorszkowski-red commented 2 years ago

I suspected that the pending data might be buffered by the appsrc inside WebKitWebSrc, so I added extra code here to ask for current-level-bytes to WebKitWebSrc (which asks to its appsrc). However, I'm always seeing 0 current-level-bytes buffered in that appsrc. I need to double check my code because it has to be some kind of bug.

With this change:

index 166149bbd590..ca0b6fc1563b 100644
--- a/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
+++ b/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
@@ -1404,6 +1404,12 @@ void MediaPlayerPrivateGStreamer::handleMessage(GstMessage* message)
 #endif

 #if PLATFORM(BCM_NEXUS) || PLATFORM(BROADCOM)
+        if (currentState == GST_STATE_NULL && newState == GST_STATE_READY && g_strstr_len(GST_MESSAGE_SRC_NAME(message), 6, "appsrc")) {
+            GST_LOG("Find appsrc");
+            m_appsrc = GST_ELEMENT(GST_MESSAGE_SRC(message));
+        }
+
+
         if (currentState == GST_STATE_NULL && newState == GST_STATE_READY && g_strstr_len(GST_MESSAGE_SRC_NAME(message), 13, "brcmvidfilter")) {
             m_vidfilter = GST_ELEMENT(GST_MESSAGE_SRC(message));

@@ -1713,6 +1719,12 @@ void MediaPlayerPrivateGStreamer::processBufferingStats(GstMessage* message)
             GST_DEBUG("[Buffering] buffered bytes by multiqueue: %d", multiqueueBufferedBytes);
         }

+        if (m_appsrc) {
+            guint currentLevelBytes = 0;
+            g_object_get(m_appsrc.get(), "current-level-bytes", &currentLevelBytes, nullptr);
+            GST_DEBUG("[Buffering] current bytes level of appsrc: %d", currentLevelBytes);
+        }
+
         size_t currentLevelBytes = (size_t)maxSizeBytes * (size_t)m_bufferingPercentage / (size_t)100
                 + (size_t)playpumpBufferedBytes + (size_t)multiqueueBufferedBytes;
         correctedBufferingPercentage = currentLevelBytes > maxSizeBytes ? 100 : (int)(currentLevelBytes * 100 / maxSizeBytes);
diff --git a/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.h b/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.h
index 7cdb7ba9c63b..a0150b0019cb 100644
--- a/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.h
+++ b/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.h
@@ -316,6 +316,7 @@ private:
 #endif
 #endif
 #if PLATFORM(BCM_NEXUS) || PLATFORM(BROADCOM)
+    GRefPtr<GstElement> m_appsrc;
     GRefPtr<GstElement> m_vidfilter;
     GRefPtr<GstElement> m_multiqueue;
 #endif

I can see logs with some values for buffer level of the webkitwebsrc(appsrc):

 0:00:39.952626795    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 0
 0:00:39.952892054    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 0
 0:00:40.042077331    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 478368
 0:00:40.152544518    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 1622832
 0:00:40.155238150    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 1622832
 0:00:40.578806806    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 4540944
 0:00:40.579576621    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 4540944
 0:00:40.580099215    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 4540944
 0:00:40.759052101    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 3656177
 0:00:40.761119400    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 3656177
 0:00:40.762289031    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 3656177
 0:00:41.012995472    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 3656177
 0:00:41.013798362    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 998480
 0:00:41.014319437    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 998480
 0:00:41.105335900    16    0x786a0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1725:processBufferingStats: [Buffering] current bytes level of appsrc: 393216
eocanha commented 2 years ago

I've cherry-picked https://github.com/LibertyGlobal/WPEWebKit/commit/574e05cbe0428112c02827ec8ce835f460a1cbcf, https://github.com/LibertyGlobal/WPEWebKit/commit/211b8d61bf5a610179af680d7537cd69529a6c27 (with some modifications, like assiging a TRACE level instead of DEBUG to less interesting messages) and https://github.com/LibertyGlobal/WPEWebKit/commit/324d9f4941b888fff702cce22f098df70b60853c into wpe-2.22 as:

I think we can close this issue and continue in issue #831.

przemyslaw-gorszkowski-red commented 2 years ago

Keep in mind that we need also change/backport for multiqueue - adding the stats property: https://github.com/GStreamer/gstreamer/commit/74938f07c2a9b3411716fa7595178942c80e20f4

eocanha commented 2 years ago

Committed to buildroot main as:

przemyslaw-gorszkowski-red commented 2 years ago

@eocanha : probably you need also cherry-pick https://github.com/LibertyGlobal/WPEWebKit/commit/324d9f4941b888fff702cce22f098df70b60853c after https://github.com/WebPlatformForEmbedded/WPEWebKit/commit/b4fdd980207af05ce9cc295eb4710160bb04db4b

eocanha commented 2 years ago

Thanks! Done. I updated the list of ported commits above.