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

Fix to allow Audio timestampMaster causes stream startup delay #8952

Open
stevemayhew opened this issue May 17, 2021 · 15 comments
Open

Fix to allow Audio timestampMaster causes stream startup delay #8952

stevemayhew opened this issue May 17, 2021 · 15 comments
Assignees
Labels

Comments

@stevemayhew
Copy link
Contributor

The patch, allow audio master, commit 6f8a8f, fixes stall issues with ordering of updates of the DSN in segments across demuxed renditions however the cost is the seconds of delay on channel change or stream startup, a bad user experience.

To reproduce this bug start playback of any HLS live stream where audio timestamps precede video in the sequence of segments.

  • Expected:

    1. Initial load of video sets start time reference
    2. Audio render is not started (samples are discarded, until they match video time)
    3. Playback starts immediately after first frame shows (early audio samples are discarded)
  • Actual:

    1. Audio playback starts immediately
    2. First frame shows immediately (as this is a forced render, MediaCodecVideoRenderer forces first frame in processOutputBuffer()
    3. First frame is frozen until all audio preceding it plays out

This change to allow audio variants to reset timestamp adjustment fixes issues we have with live playback and marked discontinuities, so any fix must still address that issue. The bug here is simple.

  1. Demuxed audio rendition playlist is updated, changing the discontinuity sequence (DSN)
  2. Next audio segment blocks for timestamps (as a freshly minted TimestampAdjuster is picked up)
  3. Video fetches continue on a stale DSN / TimestampAdjuster (cached version, or just the time ordering of the origin writing the playlists) so playback freezes

Because audio and video are kept in step by the CompositeSequenceableLoader (not allowing timeline progress) then playback is frozen forever.

Note the video rendition playlist will update to the new DSN, but the player does not see it.

stevemayhew referenced this issue May 17, 2021
This makes HLS playback less liable to become stuck if discontinuity
tags are inserted at different times across media playlists.

Issue: #8700
Issue: #8372
PiperOrigin-RevId: 362903428
@stevemayhew

This comment has been minimized.

@stevemayhew
Copy link
Contributor Author

@AquilesCanta

Assuming the best fix is to return to using video must master timestamps. This is the best fix I believe, and the timestamp master certainly should not change during playback, only on track selection if the track that was timestamp master is unselected.

This statement seems an interesting path:

The alternative that was considered was having the code that selects the next chunk to load be smart enough to not select a chunk which is not the timestampAdjuster master and has a new discontinuity sequence number

This could work, at least for our use case, the trick is we need to refresh the timestamp master's playlist in order to have it pickup the correct updated DSN. Here's why

If you mean to do this the HlsSampleStreamWrapper, that is HlsChunkSource.getNextChunk() returns a null loadable if the DSN changed and it's not a master:

 @Override
  public boolean continueLoading(long positionUs) {
    if (loadingFinished || loader.isLoading() || loader.hasFatalError()) {
      return false;
    }
    ...
    chunkSource.getNextChunk(
        positionUs,
        loadPositionUs,
        chunkQueue,
        /* allowEndOfStream= */ prepared || !chunkQueue.isEmpty(),
        nextChunkHolder);
    boolean endOfStream = nextChunkHolder.endOfStream;
    Chunk loadable = nextChunkHolder.chunk;
    // The loadable is null if the ChunkSource determined the DSN had changed and it was not a master
    ...

    // So this code would refresh playlist, which keeps the continue loading happening
    if (loadable == null) {
      if (playlistUrlToLoad != null) {
        callback.onPlaylistRefreshRequired(playlistUrlToLoad);
      }
      return false;
    }

The problem is refreshing the non-master playlist will not help. We need these two things to happen before continuing loading of this non-master rendition:

  1. Refresh the timestamp master playlist (so it picks up the new DSN)
  2. Start loading a timestamp master chunk so it will create and initialize the new TimestampAdjuster

Its possible the logic in CompositeSequenceableLoader.continueLoading() possibly in chorus with the timed refresh of the primary playlist in HlsPlaylistTracker but it would be good to have a way to actually trigger this.

I'll experiment with this a bit and let you know.

@AquilesCanta
Copy link
Contributor

If you mean to do this the HlsSampleStreamWrapper, that is HlsChunkSource.getNextChunk() returns a null loadable if the DSN changed and it's not a master:

Nono, the proposal is that HlsSampleStreamWrapper.getNextLoadPosition asks its HlsChunksSource for the position of the next segment to load, and if that segment belongs to an uninitialized discontinuity sequence, and the chunk source is not an adjuster master, then HlsChunkSource will return an "infinite" value so that the composite sequenceable loader keeps loading from the master until the new discontinuity sequence number is initialized. Does this make sense?

@stevemayhew
Copy link
Contributor Author

stevemayhew commented May 17, 2021

yes, that makes much more sense. As part of the Un-Reported discontinuity handling I was looking at making a hook for the CompositeSequenceableLoader to do something like this. Basically the idea is loading can't continue until someone is prepared to re-initialize the time offset (create and master a new TimestampAdjuster).

I'm assuming you want to add a new sentinel value returned from getLoadPosition(), Negative infinity and is already end of source, so define a:

  public static final long  LOAD_POSITION_BLOCKED = Long.MAX_VALUE

If this is returned, you need to either stay in the inner loop or break out and return true (so loading will callback):

    do {
      madeProgressThisIteration = false;
      long nextLoadPositionUs = getNextLoadPositionUs();
      if (nextLoadPositionUs == C.TIME_END_OF_SOURCE) {
        break;
      }
      for (SequenceableLoader loader : loaders) {
        long loaderNextLoadPositionUs = loader.getNextLoadPositionUs();
        boolean isLoaderBehind =
            loaderNextLoadPositionUs != C.TIME_END_OF_SOURCE
                && loaderNextLoadPositionUs <= positionUs;
        if (loaderNextLoadPositionUs == nextLoadPositionUs || isLoaderBehind) {
          madeProgressThisIteration |= loader.continueLoading(positionUs);
        }
      }
      madeProgress |= madeProgressThisIteration;
    } while (madeProgressThisIteration);

So, yes I think this will work great. Obviously the contract of the SequenceableLoader needs to change a bit, even though non-HLS implementation will never see the new sentinel value.

I'll implement it and test it with our use case, I'll push a branch as well if you still have the sources that reproduce Issue #8700 as well, or if you can share them with me I can re-test with this fix too.

The more I think about it the timestamp master should never change after playback starts. Other nasty things can happen if the adjustment value changes from video to audio or visa-versa, basically there will be a gap where there is no A/V sync which will cause playback stalls of one stream or the other.

The rest of the changes @ojw28 made to TimestampAdjuster are fine, just we should restrict the mastering to only one track following track selection and not allow a non-master chunk source to change the DSN.

@stevemayhew
Copy link
Contributor Author

Certainly @ojw28, sorry for the confusion, the off topic comments are still linked above. And yes, from my read of #8850 the only similarity to this issue is the root cause is the same.

My questions for this issue remains the same:

  1. Can you please share your plan?(hopefully it is close to what @AquilesCanta and I discussed above)
  2. Is there anything else you need from me to recreate this issue?

Thanks!

@ojw28
Copy link
Contributor

ojw28 commented Aug 2, 2021

We've submitted 4013612 to fix some other issues introduced by 6f8a8fb. I don't think it does anything to address the issue here though.

What's happening in this case is that there are two segments (one audio, one video) that need to be loaded to start playback. The HLS playlists suggest that they both start at exactly the same point in time, but the audio segment appears to contain PTS values starting ~1 second earlier than the video segment. Which ever segment "wins" the race to initialize TimestampAdjuster effectively gets to align its first PTS with the start of the media. If the video segment wins then the ~1 second of audio samples that precede it end up with negative timestamps, and get discarded at some point rather than being played out (I didn't check exactly where or why this happens, but it's probably because the negative timestamps are before the t=0 initial playback position). If the audio segment wins then nothing is discarded, and video playback starts at t=1.

  1. It seems like a content problem that both segments have exactly the same EXT-X-PROGRAM-DATE-TIME if they actually start 1 second apart. Is there a reason that the video playlist doesn't have an EXT-X-PROGRAM-DATE-TIME that's one second larger? I think that's what we'd expect to see, given the HLS specification:

The EXT-X-PROGRAM-DATE-TIME tag associates the first sample of a Media Segment with an absolute date and/or time

  1. I'm not certain what would happen if you were to modify the EXT-X-PROGRAM-DATE-TIME to be one second later, except that it would remove the race condition where the segment that "wins" determines what ends up happening. My guess would be that we'd end up with the behaviour that currently occurs if audio wins (i.e., not what you want), however changing it to behave as you expect will be much easier once the signalling in the playlist accurately reflects what's in the underlying segments. If possible, and even if it's not feasible for your production system, it would be useful if you could make a copy of your test content with the video EXT-X-PROGRAM-DATE-TIME adjusted, so that we can test this out.

As for how we should actually go about fixing this: I'm not sure that changing how the TimestampAdjuster is initialized is the correct solution. The TimestampAdjuster isn't supposed to implement clipping of an elementary stream, which is what you really want here. The fact that it used to end up doing this was by chance rather than by design. This issue has more in common with #5024 than with any of the other issues related to 6f8a8fb.

@stevemayhew
Copy link
Contributor Author

I'll have a look at 4013612 and add it to our testing.

If the video segment wins then the ~1 second of audio samples that precede it end up with negative timestamps, and get discarded at some point rather than being played out (I didn't check exactly where or why this happens, but it's probably because the negative timestamps are before the t=0 initial playback position). I

This is exactly correct. In the old design, the video always set the time so audio before that time is discarded. The discard happens in the SampleQueue because the time is before the startTimeUs of the SampleQueue. This block in readSampleMetadata():

    buffer.timeUs = timesUs[relativeReadIndex];
    if (buffer.timeUs < startTimeUs) {
      buffer.addFlag(C.BUFFER_FLAG_DECODE_ONLY);
    }

This happens on starting playback or a seek, easy of these of course reset the startTimeUs for the SampleQueue

Interesting point on EXT-X-PROGRAM-DATE-TIME, the offset comes from the way the transcoder works in this case and apparently the packager/segmenter does not reconcile this to the playlist (many origin vendors are sloppy about the segment start times and durations). At any rate, the way HlsPlaylistTracker works only the current primary playlist determines the value for getInitialStartTimeUs() (and all the variants better have the same time for this). I'll play with this a bit, but it shouldn't affect which sample stream 'wins' the master election. Because both Loader's are started together and audio is most always a smaller first sample to load, audio wins.

If possible, and even if it's not feasible for your production system, it would be useful if you could make a copy of your test content with the video EXT-X-PROGRAM-DATE-TIME adjusted, so that we can test this out.

Happy to do this. I'll send a URL to the dev email list.

The biggest drawback to audio mastering is that video first frame render is un-conditional (complicated logic in MediaCodecVideoRenderer makes this happen) And once it does happen, no other frames are rendered until the MediaClock indicates it is time.

I agree the TimestampAdjuster is not the place for this 'clipping', but clipping is certainly a better user experience than playing one stream while the other catches up. In an ideal world all transcoders would align the demuxed elementary streams perfectly, but that is not the world we live in.

Also, we need to consider what the tunneling codecs will do with this, as here we have no control over the render sequence. We have seen where BRCM codec will stutter out bursts of frames at random frame rates when presented with large time offsets like this.

Lastly, issue #5024 looks exactly like this one, so feel free to combine or mark them as a duplicate.

Thanks for opening the discussion on this, it does seem like some way to select how we clip the streams to bring them into alignment might be a better solution. Currently the SampleQueue is doing this, as I described above.

@stevemayhew
Copy link
Contributor Author

I think you may be looking at the wrong demo URL, I sent a new pair to the developer mailing list. There are no PROGRAM-DATE-TIME tags, basically the sample is 60 seconds of VOD.

Try with disabling chunkless prepare and turning off CC. Basically the selection of timestamp master is left to chance depending on the first playlist to start load of a media chunk. As you can see from the logs below, choosing audio as master (for this sample set at least) costs nearly double the time to first frame and start of playback.

  1. The URL with one variant causes video master, playback starts in 495ms
  2. The URL with two variants cause audio master, playback doesn't start till 913ms

Which ever load is not master will be forced to wait to even make the HTTP request for the segment, if this is video then obviously this will impact first frame time. One solution for this (if we decide to continue to randomize master) would be to block the first sample commit rather then the segment request (this way at least both reads are in progress)

Here's the log data, added log where TS master is chosen in loadMedia() and in the SampleQueue's commitSample() method.

Audio Master

0.0 08-04 12:40:26.016 27626 27626 I EventLogger: state [eventTime=0.04, mediaPos=0.00, buffered=0.00, window=0, BUFFERING]
236.0 08-04 12:40:26.252 27626 27856 D HlsMediaChunk: chunk http://192.168.5.13/.../1-10_T1620866277030122~D6006000.tsa set first ts in adjuster TimestampAdjuster@f861fe2
302.0 08-04 12:40:26.318 27626 27856 D SampleQueue: commitSample() - time: 0, id:1/15, flags:1, size:318, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
303.0 08-04 12:40:26.319 27626 27856 D SampleQueue: commitSample() - time: 21, id:1/15, flags:1, size:319, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
303.0 08-04 12:40:26.319 27626 27856 D SampleQueue: commitSample() - time: 42, id:1/15, flags:1, size:317, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
303.0 08-04 12:40:26.319 27626 27856 D SampleQueue: commitSample() - time: 64, id:1/15, flags:1, size:257, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
304.0 08-04 12:40:26.320 27626 27856 D SampleQueue: commitSample() - time: 85, id:1/15, flags:1, size:206, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
...
323.0 08-04 12:40:26.339 27626 27856 D SampleQueue: commitSample() - time: 1365, id:1/15, flags:1, size:329, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
323.0 08-04 12:40:26.339 27626 27856 D SampleQueue: commitSample() - time: 1386, id:1/15, flags:1, size:290, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
323.0 08-04 12:40:26.339 27626 27856 D SampleQueue: commitSample() - time: 1408, id:1/15, flags:1, size:335, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
325.0 08-04 12:40:26.341 27626 27856 D SampleQueue: commitSample() - time: 1429, id:1/15, flags:1, size:327, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
325.0 08-04 12:40:26.341 27626 27857 D SampleQueue: commitSample() - time: 1786, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
326.0 08-04 12:40:26.342 27626 27856 D SampleQueue: commitSample() - time: 1450, id:1/15, flags:1, size:323, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
326.0 08-04 12:40:26.342 27626 27856 D SampleQueue: commitSample() - time: 1472, id:1/15, flags:1, size:349, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
326.0 08-04 12:40:26.342 27626 27856 D SampleQueue: commitSample() - time: 1493, id:1/15, flags:1, size:243, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
...
365.0 08-04 12:40:26.381 27626 27856 D SampleQueue: commitSample() - time: 2602, id:1/15, flags:1, size:322, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
366.0 08-04 12:40:26.382 27626 27856 D SampleQueue: commitSample() - time: 2624, id:1/15, flags:1, size:321, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
367.0 08-04 12:40:26.383 27626 27857 D SampleQueue: commitSample() - time: 1786, id:1/27, flags:1, size:172800, mime: video/avc, upstreamKeyframeRequired: false
368.0 08-04 12:40:26.384 27626 27857 D SampleQueue: commitSample() - time: 1853, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
369.0 08-04 12:40:26.385 27626 27856 D SampleQueue: commitSample() - time: 2645, id:1/15, flags:1, size:397, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
373.0 08-04 12:40:26.389 27626 27856 D SampleQueue: commitSample() - time: 2666, id:1/15, flags:1, size:319, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
375.0 08-04 12:40:26.391 27626 27856 D SampleQueue: commitSample() - time: 2688, id:1/15, flags:1, size:318, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
377.0 08-04 12:40:26.393 27626 27856 D SampleQueue: commitSample() - time: 2709, id:1/15, flags:1, size:323, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
383.0 08-04 12:40:26.399 27626 27857 D SampleQueue: commitSample() - time: 1853, id:1/27, flags:0, size:59302, mime: video/avc, upstreamKeyframeRequired: false
385.0 08-04 12:40:26.401 27626 27857 D SampleQueue: commitSample() - time: 1820, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
388.0 08-04 12:40:26.404 27626 27856 D SampleQueue: commitSample() - time: 2730, id:1/15, flags:1, size:317, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
388.0 08-04 12:40:26.404 27626 27856 D SampleQueue: commitSample() - time: 2752, id:1/15, flags:1, size:324, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
...
403.0 08-04 12:40:26.419 27626 27856 D SampleQueue: commitSample() - time: 3882, id:1/15, flags:1, size:333, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
403.0 08-04 12:40:26.419 27626 27857 D SampleQueue: commitSample() - time: 1820, id:1/27, flags:0, size:23159, mime: video/avc, upstreamKeyframeRequired: false
403.0 08-04 12:40:26.419 27626 27856 D SampleQueue: commitSample() - time: 3904, id:1/15, flags:1, size:364, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
403.0 08-04 12:40:26.419 27626 27857 D SampleQueue: commitSample() - time: 1920, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
403.0 08-04 12:40:26.419 27626 27856 D SampleQueue: commitSample() - time: 3925, id:1/15, flags:1, size:385, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
...
411.0 08-04 12:40:26.427 27626 27856 D SampleQueue: commitSample() - time: 4416, id:1/15, flags:1, size:350, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
412.0 08-04 12:40:26.428 27626 27856 D SampleQueue: commitSample() - time: 4437, id:1/15, flags:1, size:356, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
427.0 08-04 12:40:26.443 27626 27857 D SampleQueue: commitSample() - time: 1920, id:1/27, flags:0, size:53458, mime: video/avc, upstreamKeyframeRequired: false
427.0 08-04 12:40:26.443 27626 27857 D SampleQueue: commitSample() - time: 1886, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
413.0 08-04 12:40:26.429 27626 27856 D SampleQueue: commitSample() - time: 4458, id:1/15, flags:1, size:302, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
432.0 08-04 12:40:26.448 27626 27857 D SampleQueue: commitSample() - time: 1886, id:1/27, flags:0, size:27770, mime: video/avc, upstreamKeyframeRequired: false
432.0 08-04 12:40:26.448 27626 27857 D SampleQueue: commitSample() - time: 1986, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
442.0 08-04 12:40:26.458 27626 27856 D SampleQueue: commitSample() - time: 4480, id:1/15, flags:1, size:351, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
447.0 08-04 12:40:26.463 27626 27857 D SampleQueue: commitSample() - time: 1986, id:1/27, flags:0, size:43404, mime: video/avc, upstreamKeyframeRequired: false
447.0 08-04 12:40:26.463 27626 27857 D SampleQueue: commitSample() - time: 1953, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
450.0 08-04 12:40:26.466 27626 27856 D SampleQueue: commitSample() - time: 4501, id:1/15, flags:1, size:333, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
451.0 08-04 12:40:26.467 27626 27856 D SampleQueue: commitSample() - time: 4522, id:1/15, flags:1, size:297, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
451.0 08-04 12:40:26.467 27626 27856 D SampleQueue: commitSample() - time: 4544, id:1/15, flags:1, size:371, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
451.0 08-04 12:40:26.467 27626 27856 D SampleQueue: commitSample() - time: 4565, id:1/15, flags:1, size:379, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
451.0 08-04 12:40:26.467 27626 27856 D SampleQueue: commitSample() - time: 4586, id:1/15, flags:1, size:443, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
451.0 08-04 12:40:26.467 27626 27856 D SampleQueue: commitSample() - time: 4608, id:1/15, flags:1, size:420, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
451.0 08-04 12:40:26.467 27626 27856 D SampleQueue: commitSample() - time: 4629, id:1/15, flags:1, size:366, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
454.0 08-04 12:40:26.470 27626 27857 D SampleQueue: commitSample() - time: 1953, id:1/27, flags:0, size:18884, mime: video/avc, upstreamKeyframeRequired: false
454.0 08-04 12:40:26.470 27626 27857 D SampleQueue: commitSample() - time: 2053, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
452.0 08-04 12:40:26.468 27626 27856 D SampleQueue: commitSample() - time: 4650, id:1/15, flags:1, size:367, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
...
462.0 08-04 12:40:26.478 27626 27856 D SampleQueue: commitSample() - time: 4800, id:1/15, flags:1, size:327, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
462.0 08-04 12:40:26.478 27626 27856 D SampleQueue: commitSample() - time: 4821, id:1/15, flags:1, size:340, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
464.0 08-04 12:40:26.480 27626 27857 D SampleQueue: commitSample() - time: 2053, id:1/27, flags:0, size:51283, mime: video/avc, upstreamKeyframeRequired: false
464.0 08-04 12:40:26.480 27626 27857 D SampleQueue: commitSample() - time: 2020, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
464.0 08-04 12:40:26.480 27626 27856 D SampleQueue: commitSample() - time: 4842, id:1/15, flags:1, size:348, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
466.0 08-04 12:40:26.482 27626 27856 D SampleQueue: commitSample() - time: 4864, id:1/15, flags:1, size:336, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
470.0 08-04 12:40:26.486 27626 27856 D SampleQueue: commitSample() - time: 4885, id:1/15, flags:1, size:337, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
474.0 08-04 12:40:26.490 27626 27857 D SampleQueue: commitSample() - time: 2020, id:1/27, flags:0, size:19002, mime: video/avc, upstreamKeyframeRequired: false
474.0 08-04 12:40:26.490 27626 27856 D SampleQueue: commitSample() - time: 4906, id:1/15, flags:1, size:339, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
475.0 08-04 12:40:26.491 27626 27857 D SampleQueue: commitSample() - time: 2120, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
475.0 08-04 12:40:26.491 27626 27856 D SampleQueue: commitSample() - time: 4928, id:1/15, flags:1, size:317, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
...
480.0 08-04 12:40:26.496 27626 27856 D SampleQueue: commitSample() - time: 5824, id:1/15, flags:1, size:322, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
480.0 08-04 12:40:26.496 27626 27856 D SampleQueue: commitSample() - time: 5845, id:1/15, flags:1, size:296, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
484.0 08-04 12:40:26.500 27626 27856 D SampleQueue: commitSample() - time: 5866, id:1/15, flags:1, size:341, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
491.0 08-04 12:40:26.507 27626 27857 D SampleQueue: commitSample() - time: 2120, id:1/27, flags:0, size:56303, mime: video/avc, upstreamKeyframeRequired: false
491.0 08-04 12:40:26.507 27626 27857 D SampleQueue: commitSample() - time: 2087, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
492.0 08-04 12:40:26.508 27626 27856 D SampleQueue: commitSample() - time: 5888, id:1/15, flags:1, size:313, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
493.0 08-04 12:40:26.509 27626 27856 D SampleQueue: commitSample() - time: 5909, id:1/15, flags:1, size:314, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
493.0 08-04 12:40:26.509 27626 27856 D SampleQueue: commitSample() - time: 5930, id:1/15, flags:1, size:316, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
494.0 08-04 12:40:26.510 27626 27856 D SampleQueue: commitSample() - time: 5952, id:1/15, flags:1, size:324, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
496.0 08-04 12:40:26.512 27626 27856 D SampleQueue: commitSample() - time: 5973, id:1/15, flags:1, size:335, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
498.0 08-04 12:40:26.514 27626 27856 D SampleQueue: commitSample() - time: 5994, id:1/15, flags:1, size:324, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
507.0 08-04 12:40:26.523 27626 27857 D SampleQueue: commitSample() - time: 2087, id:1/27, flags:0, size:22589, mime: video/avc, upstreamKeyframeRequired: false
507.0 08-04 12:40:26.523 27626 27857 D SampleQueue: commitSample() - time: 2187, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
...
863.0 08-04 12:40:26.879 27626 27857 D SampleQueue: commitSample() - time: 2687, id:1/27, flags:0, size:15747, mime: video/avc, upstreamKeyframeRequired: false
863.0 08-04 12:40:26.879 27626 27857 D SampleQueue: commitSample() - time: 2787, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
877.0 08-04 12:40:26.893 27626 27626 D EventLogger: renderedFirstFrame [eventTime=0.92, mediaPos=0.00, buffered=2.72, window=0, period=0, Surface(name=null)/@0xcb9bfcf]
908.0 08-04 12:40:26.924 27626 27626 I EventLogger: state [eventTime=0.95, mediaPos=0.00, buffered=2.79, window=0, period=0, READY]
913.0 08-04 12:40:26.929 27626 27626 D EventLogger: isPlaying [eventTime=0.95, mediaPos=0.00, buffered=2.79, window=0, period=0, true]

Video Master

0.0 08-04 12:43:50.179 27626 27626 I EventLogger: state [eventTime=204.21, mediaPos=0.00, buffered=0.00, window=0, BUFFERING]
165.0 08-04 12:43:50.344 27626 27899 D HlsMediaChunk: chunk http://.../T1620866277030122~D6006000.tsv set first ts in adjuster TimestampAdjuster@669658c
200.0 08-04 12:43:50.379 27626 27899 D SampleQueue: commitSample() - time: 33, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
253.0 08-04 12:43:50.432 27626 27899 D SampleQueue: commitSample() - time: 33, id:1/27, flags:1, size:172800, mime: video/avc, upstreamKeyframeRequired: false
...
294.0 08-04 12:43:50.473 27626 27899 D SampleQueue: commitSample() - time: 300, id:1/27, flags:0, size:51283, mime: video/avc, upstreamKeyframeRequired: false
294.0 08-04 12:43:50.473 27626 27899 D SampleQueue: commitSample() - time: 266, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
296.0 08-04 12:43:50.475 27626 27626 D EventLogger: renderedFirstFrame [eventTime=204.50, mediaPos=0.00, buffered=0.00, window=0, period=0, Surface(name=null)/@0xcb9bfcf]
300.0 08-04 12:43:50.479 27626 27899 D SampleQueue: commitSample() - time: 266, id:1/27, flags:0, size:19002, mime: video/avc, upstreamKeyframeRequired: false
...
447.0 08-04 12:43:50.626 27626 27899 D SampleQueue: commitSample() - time: 1634, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
450.0 08-04 12:43:50.629 27626 27899 D SampleQueue: commitSample() - time: 1634, id:1/27, flags:0, size:34305, mime: video/avc, upstreamKeyframeRequired: false
450.0 08-04 12:43:50.629 27626 27899 D SampleQueue: commitSample() - time: 1601, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
452.0 08-04 12:43:50.631 27626 27901 D SampleQueue: commitSample() - time: -1753, id:1/15, flags:1, size:318, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
452.0 08-04 12:43:50.631 27626 27901 D SampleQueue: commitSample() - time: -1732, id:1/15, flags:1, size:319, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
453.0 08-04 12:43:50.632 27626 27901 D SampleQueue: commitSample() - time: -1710, id:1/15, flags:1, size:317, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
453.0 08-04 12:43:50.632 27626 27901 D SampleQueue: commitSample() - time: -1689, id:1/15, flags:1, size:257, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
454.0 08-04 12:43:50.633 27626 27899 D SampleQueue: commitSample() - time: 1601, id:1/27, flags:0, size:33269, mime: video/avc, upstreamKeyframeRequired: false
454.0 08-04 12:43:50.633 27626 27901 D SampleQueue: commitSample() - time: -1668, id:1/15, flags:1, size:206, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
454.0 08-04 12:43:50.633 27626 27901 D SampleQueue: commitSample() - time: -1646, id:1/15, flags:1, size:288, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
454.0 08-04 12:43:50.633 27626 27901 D SampleQueue: commitSample() - time: -1625, id:1/15, flags:1, size:326, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
454.0 08-04 12:43:50.633 27626 27901 D SampleQueue: commitSample() - time: -1604, id:1/15, flags:1, size:334, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
455.0 08-04 12:43:50.634 27626 27899 D SampleQueue: commitSample() - time: 1701, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
455.0 08-04 12:43:50.634 27626 27901 D SampleQueue: commitSample() - time: -1582, id:1/15, flags:1, size:342, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
..
459.0 08-04 12:43:50.638 27626 27901 D SampleQueue: commitSample() - time: -1220, id:1/15, flags:1, size:347, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
459.0 08-04 12:43:50.638 27626 27901 D SampleQueue: commitSample() - time: -1198, id:1/15, flags:1, size:338, mime: audio/mp4a-latm, upstreamKeyframeRequired: false
465.0 08-04 12:43:50.644 27626 27899 D SampleQueue: commitSample() - time: 1701, id:1/27, flags:0, size:48896, mime: video/avc, upstreamKeyframeRequired: false
465.0 08-04 12:43:50.644 27626 27899 D SampleQueue: commitSample() - time: 1668, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
467.0 08-04 12:43:50.646 27626 27899 D SampleQueue: commitSample() - time: 1668, id:1/27, flags:0, size:18678, mime: video/avc, upstreamKeyframeRequired: false
467.0 08-04 12:43:50.646 27626 27899 D SampleQueue: commitSample() - time: 1768, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
482.0 08-04 12:43:50.661 27626 27899 D SampleQueue: commitSample() - time: 1768, id:1/27, flags:0, size:51960, mime: video/avc, upstreamKeyframeRequired: false
482.0 08-04 12:43:50.661 27626 27899 D SampleQueue: commitSample() - time: 1735, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
485.0 08-04 12:43:50.664 27626 27899 D SampleQueue: commitSample() - time: 1735, id:1/27, flags:0, size:19299, mime: video/avc, upstreamKeyframeRequired: false
485.0 08-04 12:43:50.664 27626 27899 D SampleQueue: commitSample() - time: 1835, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
485.0 08-04 12:43:50.664 27626 27626 I EventLogger: state [eventTime=204.69, mediaPos=-1.75, buffered=1.75, window=0, period=0, READY]
494.0 08-04 12:43:50.673 27626 27899 D SampleQueue: commitSample() - time: 1835, id:1/27, flags:0, size:51291, mime: video/avc, upstreamKeyframeRequired: false
494.0 08-04 12:43:50.673 27626 27899 D SampleQueue: commitSample() - time: 1801, id:1/8219, flags:1, size:60, mime: application/cea-608, upstreamKeyframeRequired: false
495.0 08-04 12:43:50.674 27626 27626 D EventLogger: isPlaying [eventTime=204.70, mediaPos=-1.75, buffered=1.75, window=0, period=0, true]

@ojw28
Copy link
Contributor

ojw28 commented Aug 5, 2021

Lastly, issue #5024 looks exactly like this one, so feel free to combine or mark them as a duplicate.

The difference is that this issue is dealing with demuxed audio and video segments, where-as #5024 is asking about audio and video muxed into a single TS stream. It may be that we can fix both issues in the same way, which is why I was referring to it as being similar. I think an ideal fix would probably have this property. However, it's not necessarily the case that a fix for this issue will definitely fix #5024, or vice-versa. E.g., reverting how TimestampAdjuster is being used back to how it was before would fix this issue, but would not fix #5024. Conversely, making a change in TsExtractor would be one way of fixing #5024 that would not fix this issue. So we'll keep them separate for now.

I agree the TimestampAdjuster is not the place for this 'clipping', but clipping is certainly a better user experience than playing one stream while the other catches up. In an ideal world all transcoders would align the demuxed elementary streams perfectly, but that is not the world we live in.

I think there's agreement that aligning audio and video to start from the same place is preferable, both for this case and for the case in #5024. What we haven't figured out yet is what the best way of achieving that is, and whether it makes sense to fix them separately or together.

@stevemayhew
Copy link
Contributor Author

That sounds good, thanks again for spending some time with this, lots of good ideas come from discussions like this.

BTW, I think there is a simple fix for this:

Which ever load is not master will be forced to wait to even make the HTTP request for the segment, if this is video then obviously this will impact first frame time.

I've got a build of code that move the call to sharedInitializeOrWait() from loadMedia() to prepareExtractor() after the initial open() this saves about 100ms off of channel change because the http requests for all streams are issued earlier. I'll spend some time on it before a pull request, here's the sequence digram prior. Timestamps are not used until call to setSampleOffsetUs()

As for the trimming / aligning functionality....

What we haven't figured out yet is what the best way of achieving that is, and whether it makes sense to fix them separately or together.

Yes, either:

  1. on egress from the SampleStream (basically readData() can mark as BUFFER_FLAG_DECODE_ONLY, what was happening as a happy accident of video master)
  2. on ingress to the SampleQueue (tricky as it would take coordinating across all of them)

Our BRCM guru (Sada, @sneelavara) tells me that the Broadcom codec has a similar function that discards audio timestamped before the first valid video frame.

@ojw28
Copy link
Contributor

ojw28 commented Aug 9, 2021

BTW, I think there is a simple fix for this [...]

Sending a pull request for this sounds good to me.

Note that you'll probably need to start passing a boolean down through feedDataToExtractor -> prepareExtraction to make sure that the relocated block of code doesn't get executed when maybeLoadInitData is called (i.e., you'd pass false from maybeLoadInitData and true from loadMedia).

@ojw28
Copy link
Contributor

ojw28 commented Sep 7, 2021

@stevemayhew - Do you plan on sending a pull request for the first issue (as per my comment above)? Thanks!

@stevemayhew
Copy link
Contributor Author

@ojw28 I've got it without the boolean now, I'm adding that and testing with it. I've been slowed down fixing some bugs with live playback that came from the MaskingMediaPeriod changes to support IMA/playlists, Pull 9386 fixes issue #9347 is already in our source base, I'm writing a test case to show the bug now, after that I'll submit this one.

@stevemayhew
Copy link
Contributor Author

Here's some background from Apple Developer Notes why the transcoders and packagers do this.

Trimming should occur on SampleStream until first video frame is committed, that's the current thought. Like the SequencableLoader, some object will need to coordinate the set of media streams to do this

@ojw28
Copy link
Contributor

ojw28 commented Nov 22, 2021

Here's some background from Apple Developer Notes why the transcoders and packagers do this.

If you're referring to the need for priming samples, then I don't think it does explain why audio segments would contain samples starting from ~1 second earlier than the advertised segment start time, as we were seeing according to #8952 (comment). As far as I'm aware, the priming duration will always be much smaller than that (somewhere in the order of ~20ms).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants