MEDIA_LOG for large encoded timestamp gaps in decoder stream.

media/filters/decoder_stream.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "media/filters/decoder_stream.h"
 
 #include <utility>
 
 #include "base/bind.h"
 #include "base/callback_helpers.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/single_thread_task_runner.h"
 #include "base/trace_event/trace_event.h"
 #include "media/base/bind_to_current_loop.h"
 #include "media/base/cdm_context.h"
 #include "media/base/decoder_buffer.h"
 #include "media/base/limits.h"
 #include "media/base/media_log.h"
 #include "media/base/timestamp_constants.h"
 #include "media/base/video_decoder.h"
 #include "media/base/video_frame.h"
 #include "media/filters/decrypting_demuxer_stream.h"
 
 namespace media {
 
+// Defines how many milliseconds of DecoderBuffer timestamp gap will be allowed
+// before warning the user. See CheckForTimestampGap(). Value of 50 chosen, as
+// this is low enough to catch issues early, but high enough to avoid noise for
+// containers like WebM that default to low granularity timestamp precision.
+const int kGapWarningThresholdMsec = 50;
+
+// Limits the number of adjustments to |audio_ts_offset_| in order to reach a
+// stable state where gaps between encoded timestamps match decoded output
+// intervals. See CheckForTimestampGap().
+const int kLimitTriesForStableTiming = 5;
+
+// Limits the milliseconds of difference between expected and actual timestamps
+// gaps to consider timestamp expectations "stable". 1 chosen because some
+// containers (WebM) default to millisecond timestamp precision. See
+// CheckForTimestampGap().
+const int kStableTimeGapThrsholdMsec = 1;
+
 // TODO(rileya): Devise a better way of specifying trace/UMA/etc strings for
 // templated classes such as this.
 template <DemuxerStream::Type StreamType>
 static const char* GetTraceString();
 
 #define FUNCTION_DVLOG(level) \
   DVLOG(level) << __FUNCTION__ << "<" << GetStreamTypeString() << ">"
 
 template <>
 const char* GetTraceString<DemuxerStream::VIDEO>() {
   return "DecoderStream<VIDEO>::Decode";
 }
 
 template <>
 const char* GetTraceString<DemuxerStream::AUDIO>() {
   return "DecoderStream<AUDIO>::Decode";
 }
 
 template <DemuxerStream::Type StreamType>
 DecoderStream<StreamType>::DecoderStream(
     const scoped_refptr<base::SingleThreadTaskRunner>& task_runner,
     ScopedVector<Decoder> decoders,
     const scoped_refptr<MediaLog>& media_log)
     : task_runner_(task_runner),
       media_log_(media_log),
       state_(STATE_UNINITIALIZED),
       stream_(NULL),
+      audio_base_ts_(kNoTimestamp()),
+      stable_audio_times_(false),
+      num_unstable_audio_tries_(0),
+      drift_warning_threshold_msec_(kGapWarningThresholdMsec),
       decoder_selector_(new DecoderSelector<StreamType>(task_runner,
                                                         std::move(decoders),
                                                         media_log)),
       decoded_frames_since_fallback_(0),
       active_splice_(false),
       decoding_eos_(false),
       pending_decode_requests_(0),
       duration_tracker_(8),
       received_config_change_during_reinit_(false),
       pending_demuxer_read_(false),
@@ skipping 94 matching lines @@
 
   reset_cb_ = closure;
 
   if (!read_cb_.is_null()) {
     task_runner_->PostTask(FROM_HERE,
                            base::Bind(base::ResetAndReturn(&read_cb_), ABORTED,
                                       scoped_refptr<Output>()));
   }
 
   ready_outputs_.clear();
+  audio_base_ts_ = kNoTimestamp();
+  audio_ts_offset_ = base::TimeDelta();
+  audio_output_ts_helper_.reset();
+  num_unstable_audio_tries_ = 0;
+  stable_audio_times_ = false;
+  drift_warning_threshold_msec_ = kGapWarningThresholdMsec;
 
   // It's possible to have received a DECODE_ERROR and entered STATE_ERROR right
   // before a Reset() is executed. If we are still waiting for a demuxer read,
   // OnBufferReady() will handle the reset callback.
   // See crbug.com/597605 and crbug.com/607454.
   if (state_ == STATE_ERROR && !pending_demuxer_read_) {
     task_runner_->PostTask(FROM_HERE, base::ResetAndReturn(&reset_cb_));
     return;
   }
 
@@ skipping 163 matching lines @@
 
 template <DemuxerStream::Type StreamType>
 void DecoderStream<StreamType>::DecodeInternal(
     const scoped_refptr<DecoderBuffer>& buffer) {
   FUNCTION_DVLOG(2);
   DCHECK(state_ == STATE_NORMAL || state_ == STATE_FLUSHING_DECODER) << state_;
   DCHECK_LT(pending_decode_requests_, GetMaxDecodeRequests());
   DCHECK(reset_cb_.is_null());
   DCHECK(buffer.get());
 
+  CheckForTimestampGap(buffer);
+
   int buffer_size = buffer->end_of_stream() ? 0 : buffer->data_size();
 
   TRACE_EVENT_ASYNC_BEGIN2(
       "media", GetTraceString<StreamType>(), this, "key frame",
       !buffer->end_of_stream() && buffer->is_key_frame(), "timestamp (ms)",
       !buffer->end_of_stream() ? buffer->timestamp().InMilliseconds() : 0);
 
   if (buffer->end_of_stream())
     decoding_eos_ = true;
   else if (buffer->duration() != kNoTimestamp())
@@ skipping 108 matching lines @@
   if (state_ == STATE_ERROR) {
     DCHECK(read_cb_.is_null());
     return;
   }
 
   // Drop decoding result if Reset() was called during decoding.
   // The resetting process will be handled when the decoder is reset.
   if (!reset_cb_.is_null())
     return;
 
+  RecordOutputDuration(output);
+
   ++decoded_frames_since_fallback_;
 
   // |decoder_| sucessfully decoded a frame. No need to keep buffers for a
   // fallback decoder.
   // Note: |fallback_buffers_| might still have buffers, and we will keep
   // reading from there before requesting new buffers from |stream_|.
   pending_buffers_.clear();
 
   if (!read_cb_.is_null()) {
     // If |ready_outputs_| was non-empty, the read would have already been
@@ skipping 276 matching lines @@
     state_ = STATE_NORMAL;
     active_splice_ = false;
     base::ResetAndReturn(&reset_cb_).Run();
     return;
   }
 
   // The resetting process will be continued in OnDecoderReinitialized().
   ReinitializeDecoder();
 }
 
+template <>
+void DecoderStream<DemuxerStream::VIDEO>::CheckForTimestampGap(
+    const scoped_refptr<DecoderBuffer>& buffer) {}
+
+template <>
+void DecoderStream<DemuxerStream::VIDEO>::RecordOutputDuration(
+    const scoped_refptr<Output>& output) {}
+
+template <>
+void DecoderStream<DemuxerStream::AUDIO>::CheckForTimestampGap(
+    const scoped_refptr<DecoderBuffer>& buffer) {
+  if (buffer->end_of_stream())
+    return;
+  DCHECK_NE(kNoTimestamp(), buffer->timestamp());
+
+  // Don't continue checking timestamps if we've exhausted tries to reach stable
+  // state. This suggests the media's encoded timestamps are way off.
+  if (num_unstable_audio_tries_ > kLimitTriesForStableTiming)
+    return;
+
+  // Keep resetting encode base ts until we start getting decode output. Some
+  // codecs/containers (e.g. chained Ogg) will take several encoded buffers
+  // before producing the first decoded output.
+  if (!audio_output_ts_helper_) {
+    audio_base_ts_ = buffer->timestamp();
+    DVLOG(3) << __FUNCTION__
+             << " setting audio_base:" << audio_base_ts_.InMicroseconds();
+    // Wait for decoded output to form expectations to verify timestamps.
+    return;
+  }
+
+  base::TimeDelta expected_ts =
+      audio_output_ts_helper_->GetTimestamp() + audio_ts_offset_;
+  base::TimeDelta ts_delta = buffer->timestamp() - expected_ts;
+
+  // Reconciling encoded buffer timestamps with decoded output often requires

[DaleCurtis, 2016/05/17 21:32:54]

Notably this also hides errors at the beginning of the file where timestamps are
wrong but no discard padding or codec delay are present.

[chcunningham, 2016/05/18 00:18:00]

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. 

+  // adjusting expectations by some offset. This accounts for varied (and at
+  // this point unknown) handling of front trimming and codec delay. Codec delay
+  // and skip trimming may or may not be accounted for in the encoded timestamps
+  // depending on the codec (e.g. MP3 vs Opus) and  demuxers used (e.g. FFmpeg
+  // vs MSE stream parsers).
+  if (!stable_audio_times_) {
+    if (std::abs(ts_delta.InMilliseconds()) < kStableTimeGapThrsholdMsec) {
+      stable_audio_times_ = true;
+      DVLOG(3) << __FUNCTION__
+               << " stabilized! tries:" << num_unstable_audio_tries_
+               << " offset:" << audio_ts_offset_.InMicroseconds();
+    } else {
+      base::TimeDelta orig_offset = audio_ts_offset_;
+      audio_ts_offset_ += ts_delta;

[DaleCurtis, 2016/05/17 21:32:54]

Seems like you should just set the base timestamp on the helper with each
update?

[chcunningham, 2016/05/18 00:18:00]

Done.

+      DVLOG(3) << __FUNCTION__
+               << " NOT stabilized. tries:" << num_unstable_audio_tries_
+               << " offset was:" << orig_offset.InMicroseconds()
+               << " now:" << audio_ts_offset_.InMicroseconds();
+      num_unstable_audio_tries_++;
+
+      // Let developers know if their files timestamps are way off from
+      if (num_unstable_audio_tries_ > kLimitTriesForStableTiming)

[DaleCurtis, 2016/05/17 21:32:54]

Needs {}

[chcunningham, 2016/05/18 00:18:00]

Done.

+        MEDIA_LOG(ERROR, media_log_)
+            << "Failed to reconcile encoded audio times with decoded output.";
+    }
+
+    // Don't bother with further checking until we reach stable state.
+    return;
+  }
+
+  if (std::abs(ts_delta.InMilliseconds()) > drift_warning_threshold_msec_) {
+    MEDIA_LOG(ERROR, media_log_)
+        << " Large timestamp gap detected; may cause AV sync to drift."
+        << " time:" << buffer->timestamp()
+        << " expected:" << expected_ts.InMicroseconds()
+        << " delta:" << ts_delta.InMicroseconds();
+    // Increase threshold to avoid log spam but, let us know if gap widens.
+    drift_warning_threshold_msec_ = std::abs(ts_delta.InMilliseconds());
+  }
+  DVLOG(3) << __FUNCTION__ << " delta:" << ts_delta.InMicroseconds()
+           << " expected_ts:" << expected_ts.InMicroseconds()
+           << " actual_ts:" << buffer->timestamp().InMicroseconds()
+           << " audio_ts_offset:" << audio_ts_offset_.InMicroseconds()
+           << " base_ts:" << audio_base_ts_.InMicroseconds();
+}
+
+template <>
+void DecoderStream<DemuxerStream::AUDIO>::RecordOutputDuration(
+    const scoped_refptr<Output>& output) {
+  if (output.get()) {
+    AudioBuffer* audio_buffer = static_cast<AudioBuffer*>(output.get());
+
+    if (!audio_output_ts_helper_) {
+      DCHECK_NE(audio_base_ts_, kNoTimestamp());
+      audio_output_ts_helper_.reset(
+          new AudioTimestampHelper(audio_buffer->sample_rate()));
+      audio_output_ts_helper_->SetBaseTimestamp(audio_base_ts_);
+    }
+
+    DVLOG(3) << __FUNCTION__ << " " << audio_buffer->frame_count() << " frames";
+    audio_output_ts_helper_->AddFrames(audio_buffer->frame_count());
+  }
+}
+
 template class DecoderStream<DemuxerStream::VIDEO>;
 template class DecoderStream<DemuxerStream::AUDIO>;
 
 }  // namespace media