Log audio splice sanitizer warnings and errors to media-internals

Plumbs a MediaLog into AudioSplicer's AudioStreamSanitizers and uses it
to log warnings and errors to chrome://media-internals. This should
help ease of diagnosis of potentially badly muxed frame timestamps
and durations. Previously, a repro on a Debug build and inspection
of DVLOG()s was required to get similar logs.

BUG=505931,490144
R=dalecurtis@chromium.org,chcunningham@chromium.org,xhwang@chromium.org
TEST=repro of bug 505931's audio-only gap tolerance decode error shows log in media-internals.

Review URL: https://codereview.chromium.org/1229123002

Cr-Commit-Position: refs/heads/master@{#338233}

3 files changed, 75 insertions, 21 deletions

diff --git a/media/base/audio_splicer.cc b/media/base/audio_splicer.cc
index 9424b0b..accff36 100644
--- a/media/base/audio_splicer.cc
+++ b/media/base/audio_splicer.cc
@@ -12,27 +12,39 @@
 #include "media/base/audio_bus.h"
 #include "media/base/audio_decoder_config.h"
 #include "media/base/audio_timestamp_helper.h"
+#include "media/base/media_log.h"
 #include "media/base/vector_math.h"
 
 namespace media {
 
-// Minimum gap size needed before the splicer will take action to
-// fill a gap. This avoids periodically inserting and then dropping samples
-// when the buffer timestamps are slightly off because of timestamp rounding
-// in the source content. Unit is frames.
-static const int kMinGapSize = 2;
+namespace {
+
+enum {
+  // Minimum gap size needed before the splicer will take action to
+  // fill a gap. This avoids periodically inserting and then dropping samples
+  // when the buffer timestamps are slightly off because of timestamp rounding
+  // in the source content. Unit is frames.
+  kMinGapSize = 2,
+
+  // Limits the number of MEDIA_LOG() per sanitizer instance warning the user
+  // about splicer overlaps within |kMaxTimeDeltaInMilliseconds| or gaps larger
+  // than |kMinGapSize| and less than |kMaxTimeDeltaInMilliseconds|. These
+  // warnings may be frequent for some streams, and number of sanitizer
+  // instances may be high, so keep this limit low to help reduce log spam.
+  kMaxSanitizerWarningLogs = 5,
+};
 
 // AudioBuffer::TrimStart() is not as accurate as the timestamp helper, so
 // manually adjust the duration and timestamp after trimming.
-static void AccurateTrimStart(int frames_to_trim,
-                              const scoped_refptr<AudioBuffer> buffer,
-                              const AudioTimestampHelper& timestamp_helper) {
+void AccurateTrimStart(int frames_to_trim,
+                       const scoped_refptr<AudioBuffer> buffer,
+                       const AudioTimestampHelper& timestamp_helper) {
   buffer->TrimStart(frames_to_trim);
   buffer->set_timestamp(timestamp_helper.GetTimestamp());
 }
 
 // Returns an AudioBus whose frame buffer is backed by the provided AudioBuffer.
-static scoped_ptr<AudioBus> CreateAudioBufferWrapper(
+scoped_ptr<AudioBus> CreateAudioBufferWrapper(
     const scoped_refptr<AudioBuffer>& buffer) {
   scoped_ptr<AudioBus> wrapper =
       AudioBus::CreateWrapper(buffer->channel_count());
@@ -44,9 +56,12 @@ static scoped_ptr<AudioBus> CreateAudioBufferWrapper(
   return wrapper.Pass();
 }
 
+}  // namespace
+
 class AudioStreamSanitizer {
  public:
-  explicit AudioStreamSanitizer(int samples_per_second);
+  AudioStreamSanitizer(int samples_per_second,
+                       const scoped_refptr<MediaLog>& media_log);
   ~AudioStreamSanitizer();
 
   // Resets the sanitizer state by clearing the output buffers queue, and
@@ -89,12 +104,23 @@ class AudioStreamSanitizer {
   typedef std::deque<scoped_refptr<AudioBuffer> > BufferQueue;
   BufferQueue output_buffers_;
 
+  scoped_refptr<MediaLog> media_log_;
+
+  // To prevent log spam, counts the number of audio gap or overlaps warned in
+  // logs.
+  int num_warning_logs_;
+
   DISALLOW_ASSIGN(AudioStreamSanitizer);
 };
 
-AudioStreamSanitizer::AudioStreamSanitizer(int samples_per_second)
+AudioStreamSanitizer::AudioStreamSanitizer(
+    int samples_per_second,
+    const scoped_refptr<MediaLog>& media_log)
     : output_timestamp_helper_(samples_per_second),
-      received_end_of_stream_(false) {}
+      received_end_of_stream_(false),
+      media_log_(media_log),
+      num_warning_logs_(0) {
+}
 
 AudioStreamSanitizer::~AudioStreamSanitizer() {}
 
@@ -128,7 +154,12 @@ bool AudioStreamSanitizer::AddInput(const scoped_refptr<AudioBuffer>& input) {
     output_timestamp_helper_.SetBaseTimestamp(input->timestamp());
 
   if (output_timestamp_helper_.base_timestamp() > input->timestamp()) {
-    DVLOG(1) << "Input timestamp is before the base timestamp.";
+    MEDIA_LOG(ERROR, media_log_)
+        << "Audio splicing failed: unexpected timestamp sequence. base "
+           "timestamp="
+        << output_timestamp_helper_.base_timestamp().InMicroseconds()
+        << "us, input timestamp=" << input->timestamp().InMicroseconds()
+        << "us";
     return false;
   }
 
@@ -139,7 +170,13 @@ bool AudioStreamSanitizer::AddInput(const scoped_refptr<AudioBuffer>& input) {
 
   if (std::abs(delta.InMilliseconds()) >
       AudioSplicer::kMaxTimeDeltaInMilliseconds) {
-    DVLOG(1) << "Timestamp delta too large: " << delta.InMicroseconds() << "us";
+    MEDIA_LOG(ERROR, media_log_)
+        << "Audio splicing failed: coded frame timestamp differs from "
+           "expected timestamp " << expected_timestamp.InMicroseconds()
+        << "us by " << delta.InMicroseconds()
+        << "us, more than threshold of +/-"
+        << AudioSplicer::kMaxTimeDeltaInMilliseconds
+        << "ms. Expected timestamp is based on decoded frames and frame rate.";
     return false;
   }
 
@@ -153,6 +190,11 @@ bool AudioStreamSanitizer::AddInput(const scoped_refptr<AudioBuffer>& input) {
   }
 
   if (frames_to_fill > 0) {
+    LIMITED_MEDIA_LOG(DEBUG, media_log_, num_warning_logs_,
+                      kMaxSanitizerWarningLogs)
+        << "Audio splicer inserting silence for small gap of "
+        << delta.InMicroseconds() << "us at time "
+        << expected_timestamp.InMicroseconds() << "us.";
     DVLOG(1) << "Gap detected @ " << expected_timestamp.InMicroseconds()
              << " us: " << delta.InMicroseconds() << " us";
 
@@ -177,6 +219,11 @@ bool AudioStreamSanitizer::AddInput(const scoped_refptr<AudioBuffer>& input) {
   //
   // A crossfade can't be done here because only the current buffer is available
   // at this point, not previous buffers.
+  LIMITED_MEDIA_LOG(DEBUG, media_log_, num_warning_logs_,
+                    kMaxSanitizerWarningLogs)
+      << "Audio splicer skipping frames for small overlap of "
+      << -delta.InMicroseconds() << "us at time "
+      << expected_timestamp.InMicroseconds() << "us.";
   DVLOG(1) << "Overlap detected @ " << expected_timestamp.InMicroseconds()
            << " us: " << -delta.InMicroseconds() << " us";
 
@@ -227,15 +274,20 @@ bool AudioStreamSanitizer::DrainInto(AudioStreamSanitizer* output) {
   return true;
 }
 
-AudioSplicer::AudioSplicer(int samples_per_second)
+AudioSplicer::AudioSplicer(int samples_per_second,
+                           const scoped_refptr<MediaLog>& media_log)
     : max_crossfade_duration_(
           base::TimeDelta::FromMilliseconds(kCrossfadeDurationInMilliseconds)),
       splice_timestamp_(kNoTimestamp()),
       max_splice_end_timestamp_(kNoTimestamp()),
-      output_sanitizer_(new AudioStreamSanitizer(samples_per_second)),
-      pre_splice_sanitizer_(new AudioStreamSanitizer(samples_per_second)),
-      post_splice_sanitizer_(new AudioStreamSanitizer(samples_per_second)),
-      have_all_pre_splice_buffers_(false) {}
+      output_sanitizer_(
+          new AudioStreamSanitizer(samples_per_second, media_log)),
+      pre_splice_sanitizer_(
+          new AudioStreamSanitizer(samples_per_second, media_log)),
+      post_splice_sanitizer_(
+          new AudioStreamSanitizer(samples_per_second, media_log)),
+      have_all_pre_splice_buffers_(false) {
+}
 
 AudioSplicer::~AudioSplicer() {}
 
diff --git a/media/base/audio_splicer.h b/media/base/audio_splicer.h
index e32a9fd..0d35f60 100644
--- a/media/base/audio_splicer.h
+++ b/media/base/audio_splicer.h
@@ -17,11 +17,13 @@ namespace media {
 class AudioBuffer;
 class AudioBus;
 class AudioStreamSanitizer;
+class MediaLog;
 
 // Helper class that handles filling gaps and resolving overlaps.
 class MEDIA_EXPORT AudioSplicer {
  public:
-  explicit AudioSplicer(int samples_per_second);
+  AudioSplicer(int samples_per_second,
+               const scoped_refptr<MediaLog>& media_log);
   ~AudioSplicer();
 
   enum {
diff --git a/media/base/audio_splicer_unittest.cc b/media/base/audio_splicer_unittest.cc
index d64302c..7b226bb 100644
--- a/media/base/audio_splicer_unittest.cc
+++ b/media/base/audio_splicer_unittest.cc
@@ -25,7 +25,7 @@ static const int kDefaultBufferSize = 100;
 class AudioSplicerTest : public ::testing::Test {
  public:
   AudioSplicerTest()
-      : splicer_(kDefaultSampleRate),
+      : splicer_(kDefaultSampleRate, new MediaLog()),
         input_timestamp_helper_(kDefaultSampleRate) {
     input_timestamp_helper_.SetBaseTimestamp(base::TimeDelta());
   }