Log audio splice sanitizer warnings and errors to media-internals

media/base/audio_splicer.cc

 // Copyright (c) 2012 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/base/audio_splicer.h"
 
 #include <cstdlib>
 #include <deque>
 
 #include "base/logging.h"
 #include "media/base/audio_buffer.h"
 #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());
   wrapper->set_frames(buffer->frame_count());
   for (int ch = 0; ch < buffer->channel_count(); ++ch) {
     wrapper->SetChannelData(
         ch, reinterpret_cast<float*>(buffer->channel_data()[ch]));
   }
   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
   // resetting the timestamp helper.
   void Reset();
 
   // Similar to Reset(), but initializes the timestamp helper with the given
   // parameters.
   void ResetTimestampState(int64 frame_count, base::TimeDelta base_timestamp);
 
@@ skipping 22 matching lines @@
 
  private:
   void AddOutputBuffer(const scoped_refptr<AudioBuffer>& buffer);
 
   AudioTimestampHelper output_timestamp_helper_;
   bool received_end_of_stream_;
 
   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() {}
 
 void AudioStreamSanitizer::Reset() {
   ResetTimestampState(0, kNoTimestamp());
 }
 
 void AudioStreamSanitizer::ResetTimestampState(int64 frame_count,
                                                base::TimeDelta base_timestamp) {
   output_buffers_.clear();
@@ skipping 13 matching lines @@
   }
 
   DCHECK(input->timestamp() != kNoTimestamp());
   DCHECK(input->duration() > base::TimeDelta());
   DCHECK_GT(input->frame_count(), 0);
 
   if (output_timestamp_helper_.base_timestamp() == kNoTimestamp())
     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;
   }
 
   const base::TimeDelta timestamp = input->timestamp();
   const base::TimeDelta expected_timestamp =
       output_timestamp_helper_.GetTimestamp();
   const base::TimeDelta delta = timestamp - expected_timestamp;
 
   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;
   }
 
   int frames_to_fill = 0;
   if (delta != base::TimeDelta())
     frames_to_fill = output_timestamp_helper_.GetFramesToTarget(timestamp);
 
   if (frames_to_fill == 0 || std::abs(frames_to_fill) < kMinGapSize) {
     AddOutputBuffer(input);
     return true;
   }
 
   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";
 
     // Create a buffer with enough silence samples to fill the gap and
     // add it to the output buffer.
     scoped_refptr<AudioBuffer> gap =
         AudioBuffer::CreateEmptyBuffer(input->channel_layout(),
                                        input->channel_count(),
                                        input->sample_rate(),
                                        frames_to_fill,
                                        expected_timestamp);
     AddOutputBuffer(gap);
 
     // Add the input buffer now that the gap has been filled.
     AddOutputBuffer(input);
     return true;
   }
 
   // Overlapping buffers marked as splice frames are handled by AudioSplicer,
   // but decoder and demuxer quirks may sometimes produce overlapping samples
   // which need to be sanitized.
   //
   // 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";
 
   const int frames_to_skip = -frames_to_fill;
   if (input->frame_count() <= frames_to_skip) {
     DVLOG(1) << "Dropping whole buffer";
     return true;
   }
 
   // Copy the trailing samples that do not overlap samples already output
@@ skipping 30 matching lines @@
 }
 
 bool AudioStreamSanitizer::DrainInto(AudioStreamSanitizer* output) {
   while (HasNextBuffer()) {
     if (!output->AddInput(GetNextBuffer()))
       return false;
   }
   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() {}
 
 void AudioSplicer::Reset() {
   output_sanitizer_->Reset();
   pre_splice_sanitizer_->Reset();
   post_splice_sanitizer_->Reset();
   have_all_pre_splice_buffers_ = false;
   reset_splice_timestamps();
 }
@@ skipping 249 matching lines @@
     AccurateTrimStart(frames_to_trim, remainder, output_ts_helper);
     CHECK(output_sanitizer_->AddInput(remainder));
   }
 
   // Transfer all remaining buffers out and reset once empty.
   CHECK(post_splice_sanitizer_->DrainInto(output_sanitizer_.get()));
   post_splice_sanitizer_->Reset();
 }
 
 }  // namespace media