Playback stalls forever in buffering with "Music Choice" content tunneling

[stevemayhew]

Content description

The content is a stream generated from Music Choice channels (often found in cable broadcast). What happens is playback stalls in buffering state, the video renderer is stalled (Renderer.isReady() reports false because the sample queue has been completely read) but no more video segments loads are kicked off (LoadControl does not request loading).

I've only reproduced this on Broadcom STB hardware (Broadcom BCM7271 based) with tunneling on.

Link to test content

Provided by email.

[REQUIRED] Version of ExoPlayer being used

Dev-v2-2.10.4 (sha d1ac272)

[REQUIRED] Device(s) and version(s) of Android being used

Android P on an Evolution eSTREAM STB.

[REQUIRED] A full bug report captured from the device

Provided by email.

[stevemayhew]

The issue is caused by the stream, but it points out something worth considering in ExoPlayer's buffering state transitions algorithm...

Because the video frame rate is so low the first segment of video is loaded, decoded and buffered in the video MediaCodec, then the renderer is no longer isReady(). Falling out of the loop it would move the playhead forward enough to cause it to need to load more video, however the video never gets a chance to catch up to the audio because the audio renderer is stoped note even a second into playing.

Here's the PTS from the first segments:

AUDIO

$ ffprobe -v error -select_streams a:0 -show_entries frame=pkt_pts_time,pkt_dts_time,pkt_pos,pkt_size,pict_type,key_frame,width,height -of csv -i AUDIO_eng-Stereo/CCURStream_mcrockstg0-10_261100133.tsa  | head -10
frame,1,50830.694578,50830.694578,376,268
frame,1,50830.715900,50830.715900,752,251
frame,1,50830.737233,50830.737233,1128,237
frame,1,50830.758567,50830.758567,1504,240
frame,1,50830.779900,50830.779900,1880,275
frame,1,50830.801233,50830.801233,2256,268
frame,1,50830.822567,50830.822567,2632,296
frame,1,50830.843900,50830.843900,3008,242
frame,1,50830.865233,50830.865233,3384,247
frame,1,50830.886567,50830.886567,3760,239
...
$ ffprobe -v error -select_streams a:0 -show_entries frame=pkt_pts_time,pkt_dts_time,pkt_pos,pkt_size,pict_type,key_frame,width,height -of csv -i AUDIO_eng-Stereo/CCURStream_mcrockstg0-10_261100133.tsa  | tail -10
frame,1,50836.475900,50836.475900,102272,248
frame,1,50836.497233,50836.497233,102648,259
frame,1,50836.518567,50836.518567,103024,258
frame,1,50836.539900,50836.539900,103400,245
frame,1,50836.561233,50836.561233,103776,267
frame,1,50836.582567,50836.582567,104152,262
frame,1,50836.603900,50836.603900,104528,257
frame,1,50836.625233,50836.625233,104904,265
frame,1,50836.646567,50836.646567,105280,259
frame,1,50836.667900,50836.667900,105656,272

VIDEO

$ ffprobe -v error -select_streams v:0 -show_entries frame=pkt_pts_time,pkt_dts_time,pkt_pos,pkt_size,pict_type,key_frame,width,height -of csv -i 1500000/CCURStream_mcrockstg1-1_261100133.tsv 
frame,1,50831.944444,50830.944444,376,156748,640,480,I
frame,0,50832.944444,50831.944444,160740,156747,640,480,P
frame,1,50833.944444,50832.944444,320916,156748,640,480,I
frame,0,50834.944444,50833.944444,481280,156747,640,480,P
frame,1,50835.944444,50834.944444,641456,156748,640,480,I
frame,0,50836.944444,50835.944444,801820,156747,640,480,P

Because the renderers are stopped when buffering begins, the audio does not play out in tunneling mode, so the current position does not increment.

With this condition setup, the player is stuck in buffering mode.

Fixing the stream will fix it (I'll verify this and close the bug then), but something worth considering dealing with in the buffering state transition algorithm.

[stevemayhew]

@andrewlewis

I'm working with the HW vendor on this so stay tuned.. The bottom line is the player is stuck in buffering mode. I believe this is because it has queued a huge number of frames to the video decoder (because the frame rate is so low) then the audio track stops accepting writes.

09-04 17:46:12.641  9560  9587 D EXO-VIDEO: renderer not ready - readingPositionUs: 44000000  lastInputTimeUs: 44000000 buffersInCodecCount:43
09-04 17:46:12.641  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1022787 bufferIndex: 2 positionUs: 447588 lastQueuedUs: 1214787 isDecodeOnly: false
09-04 17:46:12.644  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1022787 written: 2124 size: 2124 buffer pos/limit: 4096/4096
09-04 17:46:12.644  9560  9587 D EXO-AUDIO: rendered audio output bufferIndex: 2 positionUs: 447588 lastQueuedUs: 1214787 isDecodeOnly: false
09-04 17:46:12.645  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1044120 bufferIndex: 3 positionUs: 447588 lastQueuedUs: 1214787 isDecodeOnly: false
09-04 17:46:12.645  9560  9560 D EventLogger: state [2.82, 0.45, window=0, period=0, true, BUFFERING]
09-04 17:46:12.647  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1044120 written: 4096 size: 4096 buffer pos/limit: 4096/4096
09-04 17:46:12.647  9560  9587 D EXO-AUDIO: rendered audio output bufferIndex: 3 positionUs: 447588 lastQueuedUs: 1214787 isDecodeOnly: false
09-04 17:46:12.648  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1065453 bufferIndex: 0 positionUs: 447588 lastQueuedUs: 1214787 isDecodeOnly: false
09-04 17:46:12.649  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1065453 written: 2380 size: 4096 buffer pos/limit: 2380/4096
09-04 17:46:12.650  9560  9587 D EXO-AUDIO: Queued audio buffer PTS: 1236120 index: 1 buffer size: 335
09-04 17:46:12.652  9560  9587 D EXO-AUDIO: Queued audio buffer PTS: 1257456 index: 2 buffer size: 339
09-04 17:46:12.665  9560  9560 D EventLogger: state [2.85, 0.45, window=0, period=0, true, READY]

---- Pause audio.. 
09-04 17:46:12.674  9560  9587 D EXO-AUDIO: calling audioTrack.pause() - audioTrackPositionTracker.pause() returned:  true
09-04 17:46:12.676  3532  3887 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-04 17:46:12.676  3532  3887 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 4 lines
09-04 17:46:12.676  3532  3887 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-04 17:46:12.677  9560  9587 D EXO-VIDEO: Queued video buffer PTS: 45000000 index: 3 buffer size: 156747
09-04 17:46:12.678  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1065453 bufferIndex: 0 positionUs: 467998 lastQueuedUs: 1257456 isDecodeOnly: false
09-04 17:46:12.680  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1065453 written: 1716 size: 1716 buffer pos/limit: 4096/4096

--- THIS IS THE LAST AUDIO render (last completion for audio), after this writeNonBlockingWithAvSyncV21() stops indicating data has been written
09-04 17:46:12.681  9560  9587 D EXO-AUDIO: rendered audio output bufferIndex: 0 positionUs: 467998 lastQueuedUs: 1257456 isDecodeOnly: false
09-04 17:46:12.682  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1086789 bufferIndex: 1 positionUs: 467998 lastQueuedUs: 1257456 isDecodeOnly: false
09-04 17:46:12.683  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1086789 written: 1144 size: 4096 buffer pos/limit: 1144/4096
09-04 17:46:12.684  9560  9587 D EXO-AUDIO: Queued audio buffer PTS: 1278789 index: 3 buffer size: 311
09-04 17:46:12.686  9560  9587 D EXO-AUDIO: calling audioTrack.play()
09-04 17:46:12.688  3532  3887 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-04 17:46:12.688  3532  3887 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 4 lines
09-04 17:46:12.688  3532  3887 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-04 17:46:12.692  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1086789 bufferIndex: 1 positionUs: 467998 lastQueuedUs: 1278789 isDecodeOnly: false
09-04 17:46:12.693  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1086789 written: 0 size: 2952 buffer pos/limit: 1144/4096
09-04 17:46:12.702  9560  9560 D EventLogger: state [2.88, 0.47, window=0, period=0, true, BUFFERING]
09-04 17:46:12.702  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1086789 bufferIndex: 1 positionUs: 489331 lastQueuedUs: 1278789 isDecodeOnly: false
09-04 17:46:12.703  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1086789 written: 0 size: 2952 buffer pos/limit: 1144/4096
09-04 17:46:12.711  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1086789 bufferIndex: 1 positionUs: 489331 lastQueuedUs: 1278789 isDecodeOnly: false
09-04 17:46:12.712  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1086789 written: 0 size: 2952 buffer pos/limit: 1144/4096
09-04 17:46:12.722  9560  9587 D EXO-VIDEO: Queued video buffer PTS: 46000000 index: 0 buffer size: 156748
09-04 17:46:12.723  9560  9587 D EXO-VIDEO: renderer not ready - readingPositionUs: 46000000  lastInputTimeUs: 46000000 buffersInCodecCount:45
09-04 17:46:12.724  9560  9587 D EXO-AUDIO: Process audio outputBuffer PTS - 1086789 bufferIndex: 1 positionUs: 511202 lastQueuedUs: 1278789 isDecodeOnly: false
09-04 17:46:12.724  9560  9587 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 1086789 written: 0 size: 2952 buffer pos/limit: 1144/4096
09-04 17:46:12.726  9560  9587 D EXO-AUDIO: calling audioTrack.pause() - audioTrackPositionTracker.pause() returned:  true
09-04 17:46:12.727  3532  3887 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-04 17:46:12.728  3532  3887 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 4 lines

I'll keep you in the loop in this bug, my guess is what we could do is limit then number of un-rendered buffers queued to the video codec.

[stevemayhew]

I believe this issue is similar to #1874, but with very different root cause. The conditions to set this up are:

1. Device is in tunneling mode
2. There is a very low video frame rate
3. At some point writes become impotent on the paused audio track (return 0 bytes written)
4. Renderers are stopped for buffering between video frame renders (the buffered limit (as set by LoadControl) of video samples are queued to the decoder, but the time has not yet come to render the next video frame)

Condition 4 causes the doSomeWork() loop to enter Player.STATE_BUFFERING but not to load more samples to the video codec (because current playback time is not advancing)

Condition 3 causes playback time not to advance.

Here's logging for a normal buffering enter/exit sequence:

09-05 13:16:27.275 11083 11110 D EXO-AUDIO: audioSink getCurrentPositionUs() - 1977653
09-05 13:16:27.275 11083 11110 D EXO-AUDIO: calling audioTrack.pause() - audioTrackPositionTracker.pause() returned:  true
09-05 13:16:27.277 11083 11083 D EventLogger: state [2.31, 1.96, window=0, period=0, true, BUFFERING]
09-05 13:16:27.278 11083 11110 D EXO-VIDEO: Queued video buffer PTS: 45000000 index: 2 buffer size: 156748
09-05 13:16:27.279 11083 11110 D EXO-VIDEO: renderer not ready - readingPositionUs: 45000000  lastInputTimeUs: 45000000 buffersInCodecCount:43
09-05 13:16:27.279 11083 11110 D EXO-STUCK: renderer not ready - track type: 2
09-05 13:16:27.279 11083 11110 D EXO-AUDIO: Process audio outputBuffer PTS - 2428122 bufferIndex: 1 positionUs: 1977653 lastQueuedUs: 2620122 isDecodeOnly: false
09-05 13:16:27.286  3536  3854 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-05 13:16:27.286  3536  3854 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 4 lines
09-05 13:16:27.286  3536  3854 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-05 13:16:27.293 11083 11110 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 2428122 written: 1608 size: 1608 buffer pos/limit: 4096/4096
09-05 13:16:27.293 11083 11110 D EXO-AUDIO: rendered audio output bufferIndex: 1 positionUs: 1977653 lastQueuedUs: 2620122 isDecodeOnly: false
09-05 13:16:27.295 11083 11110 D EXO-AUDIO: Process audio outputBuffer PTS - 2449455 bufferIndex: 2 positionUs: 1977653 lastQueuedUs: 2620122 isDecodeOnly: false
09-05 13:16:27.296 11083 11110 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 2449455 written: 1252 size: 4096 buffer pos/limit: 1252/4096
09-05 13:16:27.296 11083 11110 D EXO-AUDIO: Queued audio buffer PTS: 2641455 index: 0 buffer size: 305
09-05 13:16:27.300 11083 11110 D EXO-AUDIO: Process audio outputBuffer PTS - 2449455 bufferIndex: 2 positionUs: 1977653 lastQueuedUs: 2641455 isDecodeOnly: false
09-05 13:16:27.301 11083 11110 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 2449455 written: 0 size: 2844 buffer pos/limit: 1252/4096
09-05 13:16:27.302 11083 11110 D EXO-AUDIO: calling audioTrack.play()
09-05 13:16:27.305  3536  3854 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-05 13:16:27.305  3536  3854 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 4 lines
09-05 13:16:27.305  3536  3854 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-05 13:16:27.315 11083 11083 D EventLogger: state [2.35, 1.98, window=0, period=0, true, READY]
09-05 13:16:27.316 11083 11110 D EXO-AUDIO: audioSink getCurrentPositionUs() - 1854907

And, the failing case, the pause causes the writeNonBlockingWithAvSync21() calls to stop accepting more audio data, so playback contentPositionUs stops moving forever.

09-05 13:16:27.476 11083 11110 D EXO-VIDEO: renderer not ready - readingPositionUs: 49000000  lastInputTimeUs: 49000000 buffersInCodecCount:47
09-05 13:16:27.476 11083 11110 D EXO-STUCK: renderer not ready - track type: 2
09-05 13:16:27.477 11083 11110 D EXO-AUDIO: Process audio outputBuffer PTS - 2620122 bufferIndex: 2 positionUs: 2001331 lastQueuedUs: 2812122 isDecodeOnly: false
09-05 13:16:27.478 11083 11110 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 2620122 written: 0 size: 2172 buffer pos/limit: 1924/4096
09-05 13:16:27.479  3536  3854 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-05 13:16:27.479  3536  3854 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 4 lines
09-05 13:16:27.479  3536  3854 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
09-05 13:16:27.483 11083 11083 D EventLogger: state [2.52, 2.00, window=0, period=0, true, BUFFERING]
09-05 13:16:27.487 11083 11110 D EXO-VIDEO: Queued video buffer PTS: 50000000 index: 3 buffer size: 156747
09-05 13:16:27.488 11083 11110 D EXO-VIDEO: renderer not ready - readingPositionUs: 50000000  lastInputTimeUs: 50000000 buffersInCodecCount:48
09-05 13:16:27.488 11083 11110 D EXO-STUCK: renderer not ready - track type: 2
09-05 13:16:27.488 11083 11110 D EXO-AUDIO: Process audio outputBuffer PTS - 2620122 bufferIndex: 2 positionUs: 2001331 lastQueuedUs: 2812122 isDecodeOnly: false
09-05 13:16:27.489 11083 11110 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 2620122 written: 0 size: 2172 buffer pos/limit: 1924/4096
09-05 13:16:27.497 11083 11110 D EXO-VIDEO: renderer not ready - readingPositionUs: 50000000  lastInputTimeUs: 50000000 buffersInCodecCount:48
09-05 13:16:27.497 11083 11110 D EXO-STUCK: renderer not ready - track type: 2
09-05 13:16:27.498 11083 11110 D EXO-AUDIO: Process audio outputBuffer PTS - 2620122 bufferIndex: 2 positionUs: 2001331 lastQueuedUs: 2812122 isDecodeOnly: false
09-05 13:16:27.499 11083 11110 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 2620122 written: 0 size: 2172 buffer pos/limit: 1924/4096
09-05 13:16:27.505 11083 11083 D EventLogger: loadCompleted [2.54, 2.00, window=0, period=0, load - URI: http://stevemayhewsmacbook/video/mcbug/AUDIO_eng-Stereo-PTS/CCURStream_mcrockstg0-10_261100142.tsa loaded: 110544 duration: 91]
09-05 13:16:27.506 11083 11083 D EventLogger: loading [2.54, 2.00, window=0, period=0, false]

These log lines repeat forever:

09-05 13:16:27.508 11083 11110 D EXO-VIDEO: renderer not ready - readingPositionUs: 50000000  lastInputTimeUs: 50000000 buffersInCodecCount:48
09-05 13:16:27.508 11083 11110 D EXO-STUCK: renderer not ready - track type: 2
09-05 13:16:27.508 11083 11110 D EXO-AUDIO: Process audio outputBuffer PTS - 2620122 bufferIndex: 2 positionUs: 2001331 lastQueuedUs: 2812122 isDecodeOnly: false
09-05 13:16:27.509 11083 11110 D EXO-AUDIO: called writeNonBlockingWithAvSyncV21() PTS - 2620122 written: 0 size: 2172 buffer pos/limit: 1924/4096

[andrewlewis]

I haven't had time to look at this properly yet, but I wonder if this happens because in tunneling mode we never get output buffers from the video codec so the condition here will always be false, which means that the renderer can stop being ready if its source is not ready even if it has a pending output frame to show.

Could you clarify "The issue is caused by the stream" -- were you able to resolve this by fixing the stream?

[stevemayhew]

"The issue is caused by the stream" -- were you able to resolve this by fixing the stream?

I thought so, but no... As long as the audio is close the tunneling code syncs it to the video ok.

And yes, what you say about tunneling is exactly correct. Because libstagefight is syncing audio and handling all processing of the frames we stall forever unless audio is allowed to play.

I closed the old pull request and submitted a more cleaned up fix (pull request #6407)

I'm testing it on FireTV now, it works on Amino and Arris STB's, while you look over the change.

[stevemayhew]

This error could occur on any streams, the Music Choice (https://musicchoice.com, I know, this is a US thing... I think Sky offers similar channels for you UK people ;-) ) streams just aggravate it much quicker. I sent you a URL on my personal S3 bucket with a snippet of the channel.