MSE: Log buffered audio splice generation to media-internals

media/filters/source_buffer_stream.cc

Index: media/filters/source_buffer_stream.cc
diff --git a/media/filters/source_buffer_stream.cc b/media/filters/source_buffer_stream.cc
index d20969f00c96c81089b8a94436700cf6aee9c5bf..e0f7266c2c267a91bd2c6caeda442491c2dd25e6 100644
--- a/media/filters/source_buffer_stream.cc
+++ b/media/filters/source_buffer_stream.cc
@@ -50,6 +50,11 @@ static base::TimeDelta ComputeFudgeRoom(base::TimeDelta approximate_duration) {
 // is set and there's not enough information to get a better estimate.
 static int kDefaultBufferDurationInMs = 125;

[DaleCurtis, 2015/07/16 20:39:22]

These three should all be marked const.

[wolenetz, 2015/07/17 17:38:15]

Good catch! I've converted these to enum values, and put all of these impl
statics into an unnamed namespace.

 
+// Limit the number of MEDIA_LOG() logs for splice buffer generation warnings

[DaleCurtis, 2015/07/16 20:39:21]

I feel like these will be hit really fast.

[chcunningham, 2015/07/17 01:36:26]

I wouldn't have guessed so. Do you expect we have a lot of splicing out there in
the wild? I guess, for people that intentionally splice, they may splice a lot
(play music). But 5 unintentional splices seems like a lot, no?

[wolenetz, 2015/07/17 17:38:15]

I think there is room to increase, though there is a trade-off. Increasing these
values in release builds is nigh impossible, so if they are too low, the value
of these logs to developers (instead of just debug-build + DVLOGs) is greatly
reduced. Badly muxed media is unfortunately causing pain to multiple developers
due to downstream decode errors in audio splice sanitizers, and more of these
logs upstream when the buffers are appended will help. However, we don't want to
exhaust the saved event cache (currently 128 events) in media-internals. I've
increased these values to 50 and 20, respectively, and added a comment.

I'm beginning to wonder if, instead of not emitting logs (and reducing IPC
churn), media-internals itself should own the policy of capping various log
types. Then, no caps would be applied to logs being rendered real-time to
chrome://media-internals, but caps could simultaneously be applied to the events
being saved (for later chrome://media-internals viewing or tab refresh). This
seems a more flexible approach, allowing developers who really need uncapped log
events to get them if they first open a media-internals. xhwang@: would the
specific player in chrome://media-internals need to be opened first, too? (This
idea is out of scope of this CL, but I think might be quite helpful.)

[DaleCurtis, 2015/07/17 18:22:34]

Yes I definitely think we need a more programmatic limit. What ffmpeg does would
be fine (last message repeats x times)

+// and successes.
+static int kMaxSpliceGenerationWarningLogs = 5;
+static int kMaxSpliceGenerationSuccessLogs = 5;
+
 // The amount of time the beginning of the buffered data can differ from the
 // start time in order to still be considered the start of stream.
 static base::TimeDelta kSeekToStartFudgeRoom() {
@@ -114,7 +119,9 @@ SourceBufferStream::SourceBufferStream(const AudioDecoderConfig& audio_config,
       config_change_pending_(false),
       splice_buffers_index_(0),
       pending_buffers_complete_(false),
-      splice_frames_enabled_(splice_frames_enabled) {
+      splice_frames_enabled_(splice_frames_enabled),
+      num_splice_generation_warning_logs_(0),
+      num_splice_generation_success_logs_(0) {
   DCHECK(audio_config.IsValidConfig());
   audio_configs_.push_back(audio_config);
 }
@@ -140,7 +147,9 @@ SourceBufferStream::SourceBufferStream(const VideoDecoderConfig& video_config,
       config_change_pending_(false),
       splice_buffers_index_(0),
       pending_buffers_complete_(false),
-      splice_frames_enabled_(splice_frames_enabled) {
+      splice_frames_enabled_(splice_frames_enabled),
+      num_splice_generation_warning_logs_(0),
+      num_splice_generation_success_logs_(0) {
   DCHECK(video_config.IsValidConfig());
   video_configs_.push_back(video_config);
 }
@@ -167,8 +176,9 @@ SourceBufferStream::SourceBufferStream(const TextTrackConfig& text_config,
       config_change_pending_(false),
       splice_buffers_index_(0),
       pending_buffers_complete_(false),
-      splice_frames_enabled_(splice_frames_enabled) {
-}
+      splice_frames_enabled_(splice_frames_enabled),
+      num_splice_generation_warning_logs_(0),
+      num_splice_generation_success_logs_(0) {}
 
 SourceBufferStream::~SourceBufferStream() {
   while (!ranges_.empty()) {
@@ -1548,8 +1558,17 @@ void SourceBufferStream::GenerateSpliceFrame(const BufferQueue& new_buffers) {
   //
   // We also do not want to generate splices if the first new buffer replaces an
   // existing buffer exactly.
-  if (pre_splice_buffers.front()->timestamp() >= splice_timestamp)
+  if (pre_splice_buffers.front()->timestamp() >= splice_timestamp) {
+    LIMITED_MEDIA_LOG(DEBUG, media_log_, num_splice_generation_warning_logs_,
+                      kMaxSpliceGenerationWarningLogs)
+        << "Skipping splice frame buffering: first new buffer at "

[DaleCurtis, 2015/07/16 20:39:22]

s/buffering/generation/ ditto for all the rest.

[wolenetz, 2015/07/17 17:38:15]

Done

+        << splice_timestamp.InMicroseconds()
+        << "us begins at or before existing buffer at "
+        << pre_splice_buffers.front()->timestamp().InMicroseconds() << "us.";
+    DVLOG(1) << "Skipping splice: overlapped buffers begin at or after the "

[DaleCurtis, 2015/07/16 20:39:21]

Do we need both of these?

[wolenetz, 2015/07/17 17:38:15]

I think the DVLOGs have value still (in the LIMITED_MEDIA_LOG case, but not
really if we used uncapped MEDIA_LOG): If a developer exceeded the
LIMITED_MEDIA_LOG cap, but had a debug build, no change other than cmdline
including something like --v=1 --vmodule=source_buffer_stream*=1,*=0 would be
needed to still get some log detail here. I went with similar approach
previously in the AudioSplicer LIMITED_MEDIA_LOG CL's warning logs
(https://codereview.chromium.org/1229123002/diff/20001/media/base/audio_splice...).

+                "first new buffer.";
     return;
+  }
 
   // If any |pre_splice_buffers| are already splices or preroll, do not generate
   // a splice.
@@ -1557,12 +1576,22 @@ void SourceBufferStream::GenerateSpliceFrame(const BufferQueue& new_buffers) {
     const BufferQueue& original_splice_buffers =
         pre_splice_buffers[i]->splice_buffers();
     if (!original_splice_buffers.empty()) {
+      LIMITED_MEDIA_LOG(DEBUG, media_log_, num_splice_generation_warning_logs_,
+                        kMaxSpliceGenerationWarningLogs)
+          << "Skipping splice frame buffering: overlapped buffers at "
+          << pre_splice_buffers[i]->timestamp().InMicroseconds()
+          << "us are in a previously buffered splice.";
       DVLOG(1) << "Can't generate splice: overlapped buffers contain a "
                   "pre-existing splice.";
       return;
     }
 
     if (pre_splice_buffers[i]->preroll_buffer().get()) {
+      LIMITED_MEDIA_LOG(DEBUG, media_log_, num_splice_generation_warning_logs_,
+                        kMaxSpliceGenerationWarningLogs)
+          << "Skipping splice frame buffering: overlapped buffers at "
+          << pre_splice_buffers[i]->timestamp().InMicroseconds()
+          << "us contain preroll.";
       DVLOG(1) << "Can't generate splice: overlapped buffers contain preroll.";
       return;
     }
@@ -1579,15 +1608,27 @@ void SourceBufferStream::GenerateSpliceFrame(const BufferQueue& new_buffers) {
       base::TimeDelta::FromSecondsD(
           2.0 / audio_configs_[append_config_index_].samples_per_second()));
   if (splice_duration < minimum_splice_duration) {
+    LIMITED_MEDIA_LOG(DEBUG, media_log_, num_splice_generation_warning_logs_,
+                      kMaxSpliceGenerationWarningLogs)
+        << "Skipping splice frame buffering: not enough samples for splicing "
+           "new buffer at "
+        << splice_timestamp.InMicroseconds() << "us. Have "
+        << splice_duration.InMicroseconds() << "us, but need "
+        << minimum_splice_duration.InMicroseconds() << "us.";
     DVLOG(1) << "Can't generate splice: not enough samples for crossfade; have "
-             << splice_duration.InMicroseconds() << " us, but need "
-             << minimum_splice_duration.InMicroseconds() << " us.";
+             << splice_duration.InMicroseconds() << "us, but need "
+             << minimum_splice_duration.InMicroseconds() << "us.";
     return;
   }
 
   DVLOG(1) << "Generating splice frame @ " << new_buffers.front()->timestamp()
            << ", splice duration: " << splice_duration.InMicroseconds()
            << " us";
+  LIMITED_MEDIA_LOG(DEBUG, media_log_, num_splice_generation_success_logs_,
+                    kMaxSpliceGenerationSuccessLogs)
+      << "Generated splice of overlap duration "
+      << splice_duration.InMicroseconds() << "us into new buffer at "
+      << splice_timestamp.InMicroseconds() << "us.";
   new_buffers.front()->ConvertToSpliceBuffer(pre_splice_buffers);
 }