Log audio splice sanitizer warnings and errors to media-internals

media/base/audio_splicer.cc

Index: media/base/audio_splicer.cc
diff --git a/media/base/audio_splicer.cc b/media/base/audio_splicer.cc
index 9424b0b39d602a601587182e6cff755a18dfa069..4d36ed744b5e0d9459618eee620478dde2c70b6b 100644
--- a/media/base/audio_splicer.cc
+++ b/media/base/audio_splicer.cc
@@ -12,6 +12,7 @@
 #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 {
@@ -22,6 +23,13 @@ namespace media {
 // 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,
@@ -46,7 +54,8 @@ static scoped_ptr<AudioBus> CreateAudioBufferWrapper(
 
 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 +98,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 +148,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";

[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;
   }
 
@@ -139,7 +164,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 +184,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()

[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";
 
@@ -177,6 +213,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 +268,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) {

[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() {}