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;
 
+// 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.
+static const int kMaxSanitizerWarningLogs = 5;

[xhwang, 2015/07/09 21:30:59]

nit: here and on line 24, not need to use "static" as namespace level consts are
automatically static.

[wolenetz, 2015/07/09 22:45:00]

Good point. Further, to prevent (and give build err if it happens) aliasing
perhaps of some other [media::]kMinGapSize or [media::]kMaxSanitizerWarningLogs,
and since it's deprecated to use static at namespace level to make local to
source file, I'll use anonymous namespace scope. And I see no reason to also not
make these an enum, and to move AccurateTimeStart and CreateAudioBufferWrapper
into the anonymous namespace.

[xhwang, 2015/07/09 22:59:36]

The last time I looked at this, there's pretty much no difference between an
integer constant and an enum. Personally I like const int better, but this is up
to you :)

+
 // 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) {
   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(
     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();
 }
 
 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";

[xhwang, 2015/07/09 21:30:59]

Is it necessary to use "us" in the last part? I found "1304226961684us" not very
readable. But it's fine if you really need that precision.

[wolenetz, 2015/07/09 22:45:00]

That high time timestamp (~15 days) is not a common occurrence in normal streams
(though is supported, of course). There have been issues in our stack with the
default TimeDelta() operator<< granularity not showing more precision than 10s
of milliseconds, when sometimes off-by-one-microsecond is enough to trigger a
different code path. Yes, I think it's necessary in the cases in this CL. I
prefer to indicate units, and think "us" is better than " microseconds" in the
context of reducing log spam. I'm uncertain that "µs" would work everywhere, so
chose the fairly common "us" abbreviation for microseconds.

     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()

[wolenetz, 2015/07/09 19:28:19]

I'm keeping the warnings DVLOGged for now, since they are capped per-sanitizer
instance at max 5 in media-internals.

              << " 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) {

[xhwang, 2015/07/09 21:30:59]

How often do these logs happen in normal cases? Are they only happening on
websites with badly muxed content? 

We only store 128 logs per process [1]. We'll need to figure out some better way
to store logs when we have more and more logs overtime. For example, we could
keep only non-debug events.

[1]
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/me...

[wolenetz, 2015/07/09 22:45:00]

If content is muxed correctly, and if the splicer is behaving as intended, there
should not be any of these messages. I played a few minutes of YT live and
recorded video and found none of the logs were triggered.

If spam becomes an issue, we could elevate the num_warning_logs_ counter to be a
pointer to a shared counter across an AudioSplicer instance, or even better, a
counter specific to an AudioRendererImpl instance (so long as the counter is
always accessed on the same thread).

I was also thinking similarly that we should do perhaps some log entry
coalescing (like devtools), where we keep a count of consecutive messages of the
same type beyond some cap (and only keep details per entry for those encountered
below a cap), and have a cap on message types across the player instance. This
would be a larger refactoring.

Also, bug 492833 tracks adding some specific media-internals properties around
audio-splicer behavior that we could use along with a shared cap to give greater
depth of splicer function detail without spamming the log.

In short, yes there could be spam for badly muxed streams. I don't expect common
streams to be so badly muxed (since we would have likely heard more complaints
about audio_splicer decode errors). We don't have UMA to confirm these
expectations though.

I also like your idea of selectively dropping [INFO and] DEBUG log messages (if
we start to run out of space, perhaps). sgtm :)

+}
 
 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