MEDIA_LOG for large encoded timestamp gaps in decoder stream. (issue 1954633002 by chcunningham@chromium.org)

[chcunn...@chromium.org]

Reviewers: DaleCurtis
CL: https://codereview.chromium.org/1954633002/

Description:
MEDIA_LOG for large encoded timestamp gaps in decoder stream.

Gaps in the encoded timestamps are likely to cause AV sync drift. AV
sync issues are a pain to debug, so this log should save developers
considerable time by highlighting exactly where in their media things
went wrong.

BUG=527990

Base URL: https://chromium.googlesource.com/chromium/src.git@master

Affected files (+104, -0 lines):
M media/base/audio_discard_helper.cc
M media/filters/decoder_stream.h
M media/filters/decoder_stream.cc

[chcunn...@chromium.org]

This is working well to catch the issues in the associated bug. After an hour or
so of playback I see these media logs:

00:48:58 408 error Large timestamp gap detected. May cause AV sync to drift.
Expected next time:36299006150403, given next time:36299006278404, delta:128001

00:49:58 723 error Large timestamp gap detected. May cause AV sync to drift.
Expected next time:36299066438403, given next time:36299066694404, delta:256001


https://codereview.chromium.org/1954633002/

[dalec...@chromium.org]

Are you still iterating on this?

https://codereview.chromium.org/1954633002/

[Chris Cunningham]

yes. will have an update today

[chcunn...@chromium.org]

Ok, finally an update. This strategy works nicely to smooth out the differences
in pre-skip and codec delay handling. For instance here is a log of an 8Khz src=
mp3.

CheckForTimestampGap setting audio_base:0
CheckForTimestampGap setting audio_base:72000
RecordOutputDuration 47 frames
CheckForTimestampGap NOT stabilized. tries:0 offset was:0 now:66125 <----
expectations not met because of discard, adjust offset to account
RecordOutputDuration 576 frames
CheckForTimestampGap stabilized! tries:1 offset:66125 <---- now with offset,
things wokring out nicely
RecordOutputDuration 576 frames
CheckForTimestampGap delta:0 expected_ts:288000 actual_ts:288000
audio_ts_offset:66125 base_ts:72000
RecordOutputDuration 576 frames
CheckForTimestampGap delta:0 expected_ts:360000 actual_ts:360000
audio_ts_offset:66125 base_ts:72000
... (delta: 0 for remaining logs)




https://codereview.chromium.org/1954633002/

[chcunn...@chromium.org]

Similarly, here is the same for trimming.opus via src=

CheckForTimestampGap setting audio_base:0
CheckForTimestampGap setting audio_base:120000
CheckForTimestampGap setting audio_base:240000
CheckForTimestampGap setting audio_base:360000
CheckForTimestampGap setting audio_base:480000
CheckForTimestampGap setting audio_base:600000
CheckForTimestampGap setting audio_base:720000
CheckForTimestampGap setting audio_base:840000
CheckForTimestampGap setting audio_base:960000
CheckForTimestampGap setting audio_base:1080000
CheckForTimestampGap setting audio_base:1200000
CheckForTimestampGap setting audio_base:1320000
RecordOutputDuration 3585 frames
CheckForTimestampGap NOT stabilized. tries:0 offset was:0 now:45314
RecordOutputDuration 5760 frames
CheckForTimestampGap stabilized! tries:1 offset:45314
RecordOutputDuration 5760 frames
CheckForTimestampGap delta:0 expected_ts:1680001 actual_ts:1680001
audio_ts_offset:45314 base_ts:1320000
RecordOutputDuration 5760 frames
CheckForTimestampGap delta:0 expected_ts:1800001 actual_ts:1800001
audio_ts_offset:45314 base_ts:1320000

[chcunn...@chromium.org]

Even better, lets demo an mp3 that has preskip (the earlier appears to not have
had it). This way we see the handling create different offsets for MSE and SRC=

Using MSE (pre-skip not removed)

[1:10:0517/141219:VERBOSE3:decoder_stream.cc(831)] CheckForTimestampGap setting
audio_base:0
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 623
frames
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(856)] CheckForTimestampGap NOT
stabilized. tries:0 offset was:0 now:11996
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 1152
frames
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(850)] CheckForTimestampGap
stabilized! tries:1 offset:11996
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 1152
frames
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(881)] CheckForTimestampGap delta:0
expected_ts:78367 actual_ts:78367 audio_ts_offset:11996 base_ts:0
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 1152
frames
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(881)] CheckForTimestampGap delta:-1
expected_ts:104490 actual_ts:104489 audio_ts_offset:11996 base_ts:0
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 1152
frames
[1:10:0517/141219:VERBOSE3:decoder_stream.cc(881)] CheckForTimestampGap delta:0
expected_ts:130612 actual_ts:130612 audio_ts_offset:11996 base_ts:0


Same file using SRC= (pre-skip and codec delay removed)

[1:10:0517/141302:VERBOSE3:decoder_stream.cc(831)] CheckForTimestampGap setting
audio_base:0
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 47
frames
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(856)] CheckForTimestampGap NOT
stabilized. tries:0 offset was:0 now:25057
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 1152
frames
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(850)] CheckForTimestampGap
stabilized! tries:1 offset:25057
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 1152
frames
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(881)] CheckForTimestampGap delta:0
expected_ts:78367 actual_ts:78367 audio_ts_offset:25057 base_ts:0
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(901)] RecordOutputDuration 1152
frames
[1:10:0517/141302:VERBOSE3:decoder_stream.cc(881)] CheckForTimestampGap delta:0
expected_ts:104490 actual_ts:104490 audio_ts_offset:25057 base_ts:0

https://codereview.chromium.org/1954633002/

[dalec...@chromium.org]

The approach seems okay modulo the case I pointed out. Review wise, this is too
much code to add to the decoder stream which is agnostic to audio/video. Please
refactor this out into a self-contained class and add appropriate call sites to
DecoderStreamTraits for its use.

By abstracting it into its own class you can add a few tests for your logic as
well.


https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc
File media/filters/decoder_stream.cc (right):

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc#newcode841
media/filters/decoder_stream.cc:841: // Reconciling encoded buffer
timestamps with decoded output often requires
Notably this also hides errors at the beginning of the file where
timestamps are wrong but no discard padding or codec delay are present.

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc#newcode855
media/filters/decoder_stream.cc:855: audio_ts_offset_ += ts_delta;
Seems like you should just set the base timestamp on the helper with
each update?

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc#newcode863
media/filters/decoder_stream.cc:863: if (num_unstable_audio_tries_ >
kLimitTriesForStableTiming)
Needs {}

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.h
File media/filters/decoder_stream.h (right):

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.h#newcode231
media/filters/decoder_stream.h:231: // Initially zero, we adjust the
offset as needed for the first few buffers
Am I understanding correctly that this is equivalent to the following:

|last_provided_input_ts_ - first_output_buffer_ts|?

https://codereview.chromium.org/1954633002/

[chcunn...@chromium.org]

On 2016/05/17 21:32:54, DaleCurtis wrote:
> The approach seems okay modulo the case I pointed out. Review wise, this is
too
> much code to add to the decoder stream which is agnostic to audio/video.
Please
> refactor this out into a self-contained class and add appropriate call sites
to
> DecoderStreamTraits for its use.

Can you clarify what you mean by appropriate call sites? IIUC
DecoderStreamTraits is entirely static methods, so I can add a static factory
method like DST::MakeTimestampChecker(), but the resulting object would become a
member of DecoderStream and we would still make calls to it directly inside
DecoderStream in the same places where CheckForTimestampGap/RecordOuputDuration
are currently called. Is this what you intend?

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc
File media/filters/decoder_stream.cc (right):

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc#newcode841
media/filters/decoder_stream.cc:841: // Reconciling encoded buffer
timestamps with decoded output often requires

On 2016/05/17 21:32:54, DaleCurtis wrote:
> Notably this also hides errors at the beginning of the file where
timestamps are
> wrong but no discard padding or codec delay are present.

Will try to do what we discussed, where we expect to be in an initially
stable state whenever we find codec delay and discard unset.

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc#newcode855
media/filters/decoder_stream.cc:855: audio_ts_offset_ += ts_delta;

On 2016/05/17 21:32:54, DaleCurtis wrote:
> Seems like you should just set the base timestamp on the helper with
each
> update?

Done.

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.cc#newcode863
media/filters/decoder_stream.cc:863: if (num_unstable_audio_tries_ >
kLimitTriesForStableTiming)

On 2016/05/17 21:32:54, DaleCurtis wrote:
> Needs {}

Done.

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.h
File media/filters/decoder_stream.h (right):

https://codereview.chromium.org/1954633002/diff/60001/media/filters/decoder_stream.h#newcode231
media/filters/decoder_stream.h:231: // Initially zero, we adjust the
offset as needed for the first few buffers

On 2016/05/17 21:32:54, DaleCurtis wrote:
> Am I understanding correctly that this is equivalent to the following:
>
> |last_provided_input_ts_ - first_output_buffer_ts|?

I would say that, once stable, this is
= last_provided_input_ts - expected_input_ts_based_on_output_frames.

https://codereview.chromium.org/1954633002/

[dalec...@chromium.org]

Well there are a few ways you could do it, so I leave it to your judgement. One
way now that we have C++11 constexpr is you could have something like

constexpr DecoderStreamTraits::kShouldUseValidator = (true|false);

Withing DecoderStream, you'd have a std::unique_ptr<...> validator_ that you
construct or not based on this flag, you would also use that constexpr in the
call sites you added within this patch to call into your validator class. Using
a constexpr lets the video template drop the unused code.

https://codereview.chromium.org/1954633002/

[chcunn...@chromium.org]

PTAL


https://codereview.chromium.org/1954633002/diff/120001/media/filters/decoder_stream.cc
File media/filters/decoder_stream.cc (right):

https://codereview.chromium.org/1954633002/diff/120001/media/filters/decoder_stream.cc#newcode503
media/filters/decoder_stream.cc:503: // error: static_cast from
'media::VideoFrame *' to 'media::AudioBuffer *',
This comment is just for CR discussion. I was surprised to see this
error because I expected the constexpr kShouldValidateTimestamps to
cause these lines to be compiled out for the VideoFrame case. Am I doing
it right?

The GetAudioBuffer call is my hacky workaround.

https://codereview.chromium.org/1954633002/

[dalec...@chromium.org]

The constexpr will only help linking, things must still compile.

https://codereview.chromium.org/1954633002/

[chcunn...@chromium.org]

On 2016/05/31 22:23:16, DaleCurtis wrote:
> The constexpr will only help linking, things must still compile.

I see. Are you ok with GetAudioBuffer, or do you have a better workaround?

https://codereview.chromium.org/1954633002/

[chcunn...@chromium.org]

Forgot to mention: With the new code to assert initial-stabilization when no
codec-delay/skip, we have a few unittests that never stabilize (either
initially, or after a seek). The tests still pass, but this might be a good time
to discuss why the timestamps are so bad...


bear-320x240*.webm - the timestamps in this file (and derivatives) are regularly
10 - 20 ms off. They swing back and forth, so it doesn't accumulate, but its
more than enough to cause problems for the validator.
PipelineIntegrationTest.ChunkDemuxerAbortRead_AudioOnly
(../../media/test/pipeline_integration_test.cc:2011)
PipelineIntegrationTest.SeekWhilePaused
(../../media/test/pipeline_integration_test.cc:1914)
PipelineIntegrationTest.SeekWhilePlaying
(../../media/test/pipeline_integration_test.cc:1937)
PipelineIntegrationTest.SuspendWhilePaused
(../../media/test/pipeline_integration_test.cc:1956)
PipelineIntegrationTest.SuspendWhilePlaying
(../../media/test/pipeline_integration_test.cc:1973)


bear-1280x720-a_frag-cenc*.mp4 - the timestamps in these files are mostly fine,
but the second buffer has a timestamp that is only 23 mu away from the first in
spite of the decoded output being much larger. No codec-delay / skip, so the
validator gives up when it sees that second timestamp. I'm not sure if this is
actually a bad file or if this instead suggests that the lack of codec-delay
does not really mean we can assume no stabilization time is needed.
PipelineIntegrationTest.EncryptedPlayback_MP4_CENC_AudioOnly
(../../media/test/pipeline_integration_test.cc:1759)
PipelineIntegrationTest.EncryptedPlayback_MP4_CENC_KeyRotation_Audio
(../../media/test/pipeline_integration_test.cc:1844)

PipelineIntegrationTest.EncryptedPlayback_NoEncryptedFrames_MP4_CENC_AudioOnly
(../../media/test/pipeline_integration_test.cc:1793)

https://codereview.chromium.org/1954633002/

[dalec...@chromium.org]

I think a DecoderStreamTraits::ValidateBuffer(validator*, buffer*) function
would be better, it can just noop for video.

https://codereview.chromium.org/1954633002/

[dalec...@chromium.org]

Not sure what to do about the files. I'd take a look to see if they're actually
bad encodings or if we have legitimate bugs.

https://codereview.chromium.org/1954633002/

[chcunn...@chromium.org]

> I think a DecoderStreamTraits::ValidateBuffer(validator*, buffer*) function
> would be better, it can just noop for video.

I thought about this some - I think its worse than the GetAudioBuffer. For one,
decoder stream makes two different calls to the validator: CheckForTimestampGap
(which really does the validating) and RecordOutputDuration (which is where I
need this cast to get the actual number of frames in the AudioBuffer). This
means I cant just throw a single Validate method into decoder stream. I either
need to add 2 methods, or perhaps just one for RecordOutput - IMHO both of these
options are uglier than GetAudioBuffer just living in an anon namespace at the
top of DecoderStream (much more concise and isolated). If its OK, I'd like to
just remove the compiler error comment from above GetAudioBuffer (replace with
something nicer).

> Not sure what to do about the files. I'd take a look to see if they're
actually
> bad encodings or if we have legitimate bugs.

I checked the files with Mp4box and HachoirUrwid - both tools show the
timestamps exactly as we're seeing them, so its likely that the files are just
bad. We can update the files later... doesn't block this CL.

https://codereview.chromium.org/1954633002/

[dalec...@chromium.org]

I think we can do better; it's a bit crufty cramming audio stuff into the
generic DecoderStream just for logging.

What do you think about converting DecoderStreamTraits<StreamType> to a member
variable held by DecoderStream and DecoderSelector. I.e. add something like
"StreamTraits traits_". You'll need to drop the static designation on the
methods and find/replace all instances of StreamTraits::### with traits_.###"
With this you can now have the traits class own the AudioTimestampValidator and
video just has nothing.

You'd then add two methods OnDecode() and OnDecodedOutputReady() which would use
the timestamp validator for audio and do nothing for video. You can construct
the validator on every call to InitializeDecoder().

I don't think this should change anything with performance but if you time a
clockless playback and it has an impact we can inline the methods in the traits
file.

https://codereview.chromium.org/1954633002/

[chcunn...@chromium.org]

Ok, I'll give this a shot.

https://codereview.chromium.org/1954633002/