HLS: MergingMediaSource with two HlsMediaSources buffers indefinitely near beginning of stream

[brianschrameck]

Our app streams two HLS audio tracks simultaneously that need to stay synchronized with each other. We have implemented custom code in order to keep these two audio tracks synchronized using a single player.

After upgrading from 2.13.2 to 2.13.3 (mainly so we don't need to use the JCenter repos), our app starts streaming HLS content but then starts buffering (endlessly) immediately prior to the third byte range, sometime between 16 seconds and 18 seconds for every stream. If we kill the app, restart, and resume playing where we left off, the rest of the stream continues successfully without buffering.

The following messages appear in the debug console while streaming, but it may be unrelated:

W/AudioTrack: getTimestamp_l(117): retrograde timestamp time corrected, 1976309488228578 < 1976309493652016

I think I've narrowed the problem down to 0d052e0 which was intended to address #8700 and #8372. Pretty sure that the thread is falling into the following block and never getting notified:

while (lastSampleTimestampUs == C.TIME_UNSET) {
    wait();
}

I will be following up via email with the ExoPlayer demo app that's been modified to use our custom player.

• Clear reproduction steps including observed and expected behavior
  Start streaming the example in the demo app. You can see the buffer stops loading between 16 and 18 seconds and once the playback buffer is exhausted, playback stops. It is expected that the stream will continue to completion.
• Output of running "adb bugreport" in the console shortly after encountering the issue
  This will be included in my email correspondence
• URI to test content for reproduction
  These are included in the demo app
• ExoPlayer version number
  2.13.3 (this code works on 2.13.2)
• Android version
  11 (also reproducible on 10 emulator)
• Android device
  Google Pixel 4a (also reproducible on emulator)

Thanks for any assistance!

[icbaker]

Thanks for the demo app to reproduce the issue.

I was able to see the behaviour you report when building against 2.13.3, and also against the dev-v2 version of the commit you identified (6f8a8fb).

When building against its immediate predecessor on dev-v2 (6b63bb2), the playback continued beyond the 18s mark. So I agree this seems to be a regression introduced by that commit.

Assigning to @ojw28 as the author of that commit to investigate further.

[brianschrameck]

Can confirm that this is still an issue in 2.14.0, preventing upgrading past 2.13.2. @ojw28 any progress here? Thanks!

[stevemayhew]

@brianschrameck I'm not sure the ExoPlayer team @ojw28 is working on this or not. We are working on what I suspect (without your app I can't confirm) is a related issue. You can look at my comments on commit (6f8a8fb).

For us allowing audio master (which the commit does) prevents a deadlock when the EXT-X-DISCONTINUITY sequence changes on the audio playlist first. Our issue (see Issue #8952 ) is the side effect, demuxed audio resets the offset from playlist time to media time, causes ugly periods of frozen video with sound playing when discontinuity occurs or during seek.

I am working on a solution where the getNextLoadPosition() in CompositeSequenceableLoader will not move forward if the non-timestamp master loader has had a discontinuity change until all the loaders have seen the discontinuity change then I can return to only allowing video to master.

If I could see some sample playlists from your situation that have this issue I can see if the fix will hurt or help your use case.

[brianschrameck]

Our use case is a little different as we are playing two audio-only streams and synchronizing them using a MergingMediaSource. I've attached two example HLS playlists; we then merge them together and play simultaneously. Both work fine when played individually, though. It's just when merging them and playing simultaneously where there's an issue.

It does sound like an issue with segment alignment between tracks as you mentioned in your comments on the commit. I don't think it's unreasonable to assume that segments may not be aligned as I don't believe there's anything in the spec that say they need to be. FWIW our segments are only very slightly misaligned.

[stevemayhew]

@brianschrameck The playlists you attached do not have any discontinuities. If the actual application is live and has discontinuities that could certainly trigger the timestamp adjustment.

Note the purpose of the TimestampAdjuster is to normalize media sample timestamps across multiple demuxed sample streams that are part of the same HlsMediaPeriod. Unless I'm missing something looks like your example will only have one audio sample stream (playlist) per-HlsMediaPeriod. You use case has multiple HlsMediaPeriod's merged.

At any rate, when the fix for #8952 is ready we'll have a public pull you can try, or if the ExoPlayer team does it first of course.

[brianschrameck]

Correct, no discontinuities in these, but the live app does have them. We don't ever make it that far, though, so the they are irrelevant.

We extended SimpleExoPlayer, DefaultRenderersFactory, MediaCodecAudioRenderer, and TrackSelector with inspiration from the conversation here. We rely on the MediaClock of only one of the two tracks to synchronize playback between the two. I haven't looked into 0d052e0 too closely, but I'm guessing somewhere in there it's expecting the last sample timestamp between the two tracks to always match.

Looking at the two HLS streams, we see Stream 1:

#EXT-X-BYTERANGE:84412@0
.../64k.ts
#EXTINF:9.241545,
#EXT-X-BYTERANGE:82908@84412
.../64k.ts
#EXTINF:9.287977999999999,
#EXT-X-BYTERANGE:83660@167320
.../64k.ts

and Stream 2:

#EXT-X-BYTERANGE:84412@0
.../64k.ts
#EXTINF:9.334411000000001,
#EXT-X-BYTERANGE:84412@84412
.../64k.ts
#EXTINF:9.241544999999999,
#EXT-X-BYTERANGE:83848@168824
.../64k.ts

Notice how the byte ranges match up until the third segment. And it just so happens it seems that this is where playback stalls; sometime around 18 seconds. I don't know enough about how TimestampAdjuster works, but this is as far as I took things.

[stevemayhew]

If the PTS values reset in that third segment it must be marked with an EXT-X-DISCONTINUITY. The job of TimestampAdjuster is to match playlist time (starting PROGRAM-DATE-TIME + sum(duration)) to the PTS in the samples in the segments. Each time this changes (because PTS jumps), it needs to be marked as changed by the EXT-X-DISCONTINUITY

[brianschrameck]

Sorry, I'm not really following. Nothing like that is mentioned in the spec or in Apple's mediastreamvalidator tool. The timestamps are in sequence, and they are not being reset. Byte ranges between sequences don't need to be identical as far as I'm aware.

[stevemayhew]

As long as the timestamps (PTS) in #EXT-X-BYTERANGE:83848@168824 are nearly 9.2415449.. seconds from the timestamps (PTS) in #EXT-X-BYTERANGE:84412@84412 then it is perfectly valid and there is no discontinuity.

So I'm confused as to what is the nature of the "discontinuity" you mentioned:

our app starts streaming HLS content but then starts buffering (endlessly) immediately prior to the second discontinuity, sometime between 16 seconds and 18 seconds for every stream.

[brianschrameck]

Thanks, I've edited the original post to correct the terminology.

[stevemayhew]

Easy to see if you are stuck in the wait. Look for EventLogger loadStarted event that is not followed by an loadCompleted.

I'll keep any eye on this bug too as we prepare a proposed fix for #8952

[brianschrameck]

Yeah, there looks to be missing a loadCompleted event.

2021-05-27 08:45:10.156 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: playWhenReady [eventTime=0.00, mediaPos=0.00, window=0, true, USER_REQUEST]
2021-05-27 08:45:10.197 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: surfaceSize [eventTime=0.05, mediaPos=0.00, window=0, 1080, 2160]
2021-05-27 08:45:10.204 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=0.05, mediaPos=0.00, window=0, bytesLoaded=0, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:10.205 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=0.05, mediaPos=0.00, window=0, bytesLoaded=0, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:10.206 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loading [eventTime=0.05, mediaPos=0.00, window=0, period=0, true]
2021-05-27 08:45:10.682 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=0.53, mediaPos=0.00, window=0, bytesLoaded=0, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:10.683 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadCompleted [eventTime=0.53, mediaPos=0.00, window=0, bytesLoaded=452, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:10.685 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=0.53, mediaPos=0.00, window=0, bytesLoaded=0, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:10.686 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadCompleted [eventTime=0.53, mediaPos=0.00, window=0, bytesLoaded=452, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:10.961 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadCompleted [eventTime=0.81, mediaPos=0.00, window=0, bytesLoaded=3487, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:11.052 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=0.90, mediaPos=0.00, window=0, period=0, bytesLoaded=0, mediaStartTimeMs=0, mediaEndTimeMs=9334]
2021-05-27 08:45:11.052 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=0.90, mediaPos=0.00, window=0, period=0, bytesLoaded=0, mediaStartTimeMs=0, mediaEndTimeMs=9334]
2021-05-27 08:45:11.055 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadCompleted [eventTime=0.90, mediaPos=0.00, window=0, bytesLoaded=3480, mediaStartTimeMs=-9223372036854775807, mediaEndTimeMs=-9223372036854775807]
2021-05-27 08:45:11.056 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: timeline [eventTime=0.90, mediaPos=0.00, window=0, period=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE
2021-05-27 08:45:11.057 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:   period [183.99]
2021-05-27 08:45:11.057 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:   window [183.99, seekable=true, dynamic=false]
2021-05-27 08:45:11.057 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: ]
2021-05-27 08:45:11.206 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadCompleted [eventTime=1.05, mediaPos=0.00, window=0, period=0, bytesLoaded=84412, mediaStartTimeMs=0, mediaEndTimeMs=9334]
2021-05-27 08:45:11.372 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: audioEnabled [eventTime=1.22, mediaPos=0.00, window=0, period=0]
2021-05-27 08:45:11.373 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: audioEnabled [eventTime=1.22, mediaPos=0.00, window=0, period=0]
2021-05-27 08:45:11.374 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: tracks [eventTime=1.22, mediaPos=0.00, window=0, period=0, []]
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: staticMetadata [eventTime=1.23, mediaPos=0.00, window=0, period=0
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:   Metadata:0 [
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:     HlsTrackMetadataEntry [audio-0, Default]
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:   ]
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:   Metadata:1 [
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:     HlsTrackMetadataEntry [audio-0, Default]
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger:   ]
2021-05-27 08:45:11.377 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: ]
2021-05-27 08:45:11.379 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: downstreamFormat [eventTime=1.23, mediaPos=0.00, window=0, period=0, id=audio-0:Default, mimeType=audio/mp4a-latm, codecs=mp4a.40.5, channels=2, language=en, label=Default]
2021-05-27 08:45:11.455 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: audioDecoderInitialized [eventTime=1.30, mediaPos=0.00, window=0, period=0, c2.android.aac.decoder]
2021-05-27 08:45:11.456 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: audioInputFormat [eventTime=1.30, mediaPos=0.00, window=0, period=0, id=audio-0:Default, mimeType=audio/mp4a-latm, codecs=mp4a.40.2, channels=1, sample_rate=22050, language=en, label=Default]
2021-05-27 08:45:11.476 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: audioDecoderInitialized [eventTime=1.32, mediaPos=0.00, window=0, period=0, c2.android.aac.decoder]
2021-05-27 08:45:11.477 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: audioInputFormat [eventTime=1.33, mediaPos=0.00, window=0, period=0, id=audio-0:Default, mimeType=audio/mp4a-latm, codecs=mp4a.40.2, channels=2, sample_rate=22050, language=en, label=Default]
2021-05-27 08:45:11.524 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: state [eventTime=1.37, mediaPos=0.00, window=0, period=0, READY]
2021-05-27 08:45:11.528 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: isPlaying [eventTime=1.38, mediaPos=0.00, window=0, period=0, true]
2021-05-27 08:45:11.529 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadCompleted [eventTime=1.38, mediaPos=0.00, window=0, period=0, bytesLoaded=84412, mediaStartTimeMs=0, mediaEndTimeMs=9334]
2021-05-27 08:45:11.568 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=1.42, mediaPos=0.00, window=0, period=0, bytesLoaded=0, mediaStartTimeMs=9334, mediaEndTimeMs=18668]
2021-05-27 08:45:11.745 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadCompleted [eventTime=1.59, mediaPos=0.05, window=0, period=0, bytesLoaded=84412, mediaStartTimeMs=9334, mediaEndTimeMs=18668]
2021-05-27 08:45:11.749 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: loadStarted [eventTime=1.60, mediaPos=0.05, window=0, period=0, bytesLoaded=0, mediaStartTimeMs=18668, mediaEndTimeMs=27910]
2021-05-27 08:45:29.976 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: state [eventTime=19.82, mediaPos=18.28, window=0, period=0, BUFFERING]
2021-05-27 08:45:29.982 30525-30525/com.google.android.exoplayer2.demo D/EventLogger: isPlaying [eventTime=19.83, mediaPos=18.28, window=0, period=0, false]

[brianschrameck]

Can confirm that this is still a problem on 2.14.2. Any progress looking into this?

[ojw28]

I am looking at some other issues that 0d052e0 caused currently. Once I have a fix for those I'll see if it also fixes this issue at the same time.

[ojw28]

I think this should be fixed by the commit referenced above. Please give it a try!

[brianschrameck]

Looks good here, thank you!