[CMCD] Too many buffer starvation reports

[mikef-dk]

[CMCD] Too many buffer starvation reports

[rohitjoins]

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

[rohitjoins]

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]

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]

@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]

@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?