Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[CMCD] Too many buffer starvation reports #1124

Closed
1 task done
mikef-dk opened this issue Feb 22, 2024 · 10 comments
Closed
1 task done

[CMCD] Too many buffer starvation reports #1124

mikef-dk opened this issue Feb 22, 2024 · 10 comments
Assignees

Comments

@mikef-dk
Copy link

Version

Media3 1.2.1

More version details

No response

Devices that reproduce the issue

Reproducible on any device

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

Yes

Reproduction steps

Prerequisite: Add CmcdConfiguration.Factory.DEFAULT to DefaultMediaSourceFactory in PlayerActivity and optionally logs to LoadingInfo#rebufferedSince

  1. Open App
  2. Select UHD (cbcs)
  3. Check CMCD data

Expected result

One Buffer Starvation (bs) event in the CMCD data (video needs to load therefore I would expect only one)

Actual result

Two Buffer Starvation (bs) CMCD events are reported

Looking at the logs I can see that rebufferedSince was called twice:
1st time: realtimeMs = 299910722
2nd time: realtimeMs = 299910780
In both cases the lastRebufferRealtimeMs was 299911159 so the method returned true. So in the end two buffer starvations are reported but in fact only one rebuffering happened.

Media

UHD (cbcs)
HD (cbcs)

Bug Report

  • You will email the zip file produced by adb bugreport to [email protected] after filing this issue.
@rohitjoins
Copy link
Contributor

Hi @mikef-dk,

The behavior is actually working as intended. CMCD data is reported whenever a request is made to get a chunk. When starvation occurs, there are actually two requests made to fetch chunks i.e. one for audio and the other for video.

If you observe closely, CMCD data reported also contains a field called objectType which is different (a and v) for these two reports.

@mikef-dk
Copy link
Author

Hi @rohitjoins,

thanks for looking into this and your explanation. Maybe my "expectation" as outlined in the issue description was a bit misleading: In fact I would expect 0 "buffer starvations". If the media didn't even start - so not a single chunk has been loaded before because it's the initial loading - why would you consider this as a "buffer starvation"? There was never any data in the buffer before. By doing this basically every stream would report 1-2 buffer starvations leading to faulty reports.

As an additional note: Afaik, Shaka Player doesn't have this "issue" - they don't report any buffer starvation during the initial setup/loading.

@rohitjoins
Copy link
Contributor

@mikef-dk,

The buffer starvation is not reported before the initial loading. If you log the playbackPositionUs when buffer starvation is reported, it is approximately at 1.39 seconds. You can also briefly see the buffering icon in the above playback in the demo app.

@mikef-dk
Copy link
Author

@rohitjoins I don't see any buffering Icon and the playbackState doesn't indicate a BUFFERING except the initial one. Here is an example log when starting the Stream:

15:37:17.144 Tracing                androidx.media3.demo.main            D  State transition to STATE_BUFFERING (realtimeMs: 315234453)                                     
15:37:18.152 Tracing                androidx.media3.demo.main            D  State transition to STATE_READY (realtimeMs: 315235462)                                         
15:37:19.360 Tracing                androidx.media3.demo.main            D  didRebuffer: realtimeMs: 315234801 lastRebufferRealtimeMs: 315235363 playbackPositionUs: 1152445
15:37:19.361 Tracing                androidx.media3.demo.main            D  didRebuffer: realtimeMs: 315235336 lastRebufferRealtimeMs: 315235363 playbackPositionUs: 1152445

There is no additional transition to STATE_BUFFERING happening nor does the playback pause/stop which in my world implies that there is still some content left in the Buffer. Isn't the "buffer starvation" supposed to tell us that there is a problem on client side? E.g. internet was too slow to load the next chunk. If this happens even with the best internet in the world, then this CMCD field is basically useless.

I've also added logs to the EventLogger#onLoadCompleted to check for the buffer duration:

15:45:15.758 Tracing                androidx.media3.demo.main            D  State transition to STATE_BUFFERING (realtimeMs: 315713068)                                    
15:45:15.905 Tracing                androidx.media3.demo.main            D  #onLoadCompleted, totalBufferedDurationMs: 0                                                   
15:45:16.100 Tracing                androidx.media3.demo.main            D  #onLoadCompleted, totalBufferedDurationMs: 0                                                   
15:45:16.220 Tracing                androidx.media3.demo.main            D  #onLoadCompleted, totalBufferedDurationMs: 0                                                   
15:45:16.935 Tracing                androidx.media3.demo.main            D  #onLoadCompleted, totalBufferedDurationMs: 2600                                                
15:45:16.936 Tracing                androidx.media3.demo.main            D  State transition to STATE_READY (realtimeMs: 315714246)                                        
15:45:17.382 Tracing                androidx.media3.demo.main            D  #onLoadCompleted, totalBufferedDurationMs: 7192                                                
15:45:17.431 Tracing                androidx.media3.demo.main            D  didRebuffer: realtimeMs: 315713409 lastRebufferRealtimeMs: 315714190 playbackPositionUs: 529651
15:45:17.432 Tracing                androidx.media3.demo.main            D  #onLoadCompleted, totalBufferedDurationMs: 7337                                                
15:45:17.433 Tracing                androidx.media3.demo.main            D  didRebuffer: realtimeMs: 315714184 lastRebufferRealtimeMs: 315714190 playbackPositionUs: 529651

Before the first CMCD report we apparently already have 7 seconds of buffer. Do I interpret the data wrong?

@rohitjoins
Copy link
Contributor

Thanks for the detailed info. I'll debug this further to reach a conclusion and will keep you posted.

@totallyunknown
Copy link

Are there any updates on this? For us, the CMCD data is useless without the correct buffer starvations.

@rohitjoins
Copy link
Contributor

Hi @totallyunknown,

I'm working on this and will soon provide a fix for this.

copybara-service bot pushed a commit that referenced this issue May 1, 2024
The last rebuffer time was being updated erroneously, even in the absence of rebuffering events, resulting in incorrect `bs` (buffer starvation) key in CMCD.

Issue: #1124
PiperOrigin-RevId: 629731796
@rohitjoins
Copy link
Contributor

A fix has been submitted to the main branch for this issue and will be included in the next release. Thanks for reporting once again.

@mikef-dk
Copy link
Author

mikef-dk commented May 6, 2024

@rohitjoins Thanks for the fix - really appreciate it. 🙏

Will there be another 1.3.x release with this fix or is it only coming to the 1.4.0 version that is currently in alpha?

@rohitjoins
Copy link
Contributor

@mikef-dk, I believe there won't be any further bug fix releases. The fix will be included in any new release related to version 1.4.0.

@androidx androidx locked and limited conversation to collaborators Jul 9, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants