MEDIA_LOG for large encoded timestamp gaps in decoder stream.

media/filters/decoder_stream.cc

Index: media/filters/decoder_stream.cc
diff --git a/media/filters/decoder_stream.cc b/media/filters/decoder_stream.cc
index 039b2b95f2276517e89902fc4815227d040b6cd4..757692bebb18bec12b951ae347c73d45d59393c5 100644
--- a/media/filters/decoder_stream.cc
+++ b/media/filters/decoder_stream.cc
@@ -24,6 +24,23 @@
 
 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>
@@ -51,6 +68,10 @@ DecoderStream<StreamType>::DecoderStream(
       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)),
@@ -165,6 +186,12 @@ void DecoderStream<StreamType>::Reset(const base::Closure& closure) {
   }
 
   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,
@@ -348,6 +375,8 @@ void DecoderStream<StreamType>::DecodeInternal(
   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(
@@ -476,6 +505,8 @@ void DecoderStream<StreamType>::OnDecodeOutputReady(
   if (!reset_cb_.is_null())
     return;
 
+  RecordOutputDuration(output);
+
   ++decoded_frames_since_fallback_;
 
   // |decoder_| sucessfully decoded a frame. No need to keep buffers for a
@@ -772,6 +803,106 @@ void DecoderStream<StreamType>::OnDecoderReset() {
   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>;