MSE: Log buffered audio splice generation to media-internals

media/filters/source_buffer_stream.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/filters/source_buffer_stream.h"
 
 #include <algorithm>
 #include <map>
 #include <sstream>
 
@@ skipping 30 matching lines @@
 // See http://crbug.com/351489 and http://crbug.com/351166.
 static base::TimeDelta ComputeFudgeRoom(base::TimeDelta approximate_duration) {
   // Because we do not know exactly when is the next timestamp, any buffer
   // that starts within 2x the approximate duration of a buffer is considered
   // within this range.
   return 2 * approximate_duration;
 }
 
 // An arbitrarily-chosen number to estimate the duration of a buffer if none
 // 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() {
   return base::TimeDelta::FromMilliseconds(1000);
 }
 
 // Helper method for logging, converts a range into a readable string.
 static std::string RangeToString(const SourceBufferRange& range) {
   std::stringstream ss;
   ss << "[" << range.GetStartTimestamp().InSecondsF()
@@ skipping 44 matching lines @@
       range_for_next_append_(ranges_.end()),
       new_media_segment_(false),
       last_appended_buffer_timestamp_(kNoDecodeTimestamp()),
       last_appended_buffer_is_keyframe_(false),
       last_output_buffer_timestamp_(kNoDecodeTimestamp()),
       max_interbuffer_distance_(kNoTimestamp()),
       memory_limit_(kSourceBufferAudioMemoryLimit),
       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);
 }
 
 SourceBufferStream::SourceBufferStream(const VideoDecoderConfig& video_config,
                                        const scoped_refptr<MediaLog>& media_log,
                                        bool splice_frames_enabled)
     : media_log_(media_log),
       current_config_index_(0),
       append_config_index_(0),
       seek_pending_(false),
       end_of_stream_(false),
       seek_buffer_timestamp_(kNoTimestamp()),
       selected_range_(NULL),
       media_segment_start_time_(kNoDecodeTimestamp()),
       range_for_next_append_(ranges_.end()),
       new_media_segment_(false),
       last_appended_buffer_timestamp_(kNoDecodeTimestamp()),
       last_appended_buffer_is_keyframe_(false),
       last_output_buffer_timestamp_(kNoDecodeTimestamp()),
       max_interbuffer_distance_(kNoTimestamp()),
       memory_limit_(kSourceBufferVideoMemoryLimit),
       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);
 }
 
 SourceBufferStream::SourceBufferStream(const TextTrackConfig& text_config,
                                        const scoped_refptr<MediaLog>& media_log,
                                        bool splice_frames_enabled)
     : media_log_(media_log),
       current_config_index_(0),
       append_config_index_(0),
       text_track_config_(text_config),
       seek_pending_(false),
       end_of_stream_(false),
       seek_buffer_timestamp_(kNoTimestamp()),
       selected_range_(NULL),
       media_segment_start_time_(kNoDecodeTimestamp()),
       range_for_next_append_(ranges_.end()),
       new_media_segment_(false),
       last_appended_buffer_timestamp_(kNoDecodeTimestamp()),
       last_appended_buffer_is_keyframe_(false),
       last_output_buffer_timestamp_(kNoDecodeTimestamp()),
       max_interbuffer_distance_(kNoTimestamp()),
       memory_limit_(kSourceBufferAudioMemoryLimit),
       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()) {
     delete ranges_.front();
     ranges_.pop_front();
   }
 }
 
 void SourceBufferStream::OnNewMediaSegment(
     DecodeTimestamp media_segment_start_time) {
@@ skipping 1359 matching lines @@
           splice_dts, max_splice_end_dts, &pre_splice_buffers)) {
     return;
   }
 
   // If there are gaps in the timeline, it's possible that we only find buffers
   // after the splice point but within the splice range.  For simplicity, we do
   // not generate splice frames in this case.
   //
   // 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.
   for (size_t i = 0; i < pre_splice_buffers.size(); ++i) {
     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;
     }
   }
 
   // Don't generate splice frames which represent less than a millisecond (which
   // is frequently the extent of timestamp resolution for poorly encoded media)
   // or less than two frames (need at least two to crossfade).
   const base::TimeDelta splice_duration =
       pre_splice_buffers.back()->timestamp() +
       pre_splice_buffers.back()->duration() - splice_timestamp;
   const base::TimeDelta minimum_splice_duration = std::max(
       base::TimeDelta::FromMilliseconds(1),
       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);
 }
 
 bool SourceBufferStream::SetPendingBuffer(
     scoped_refptr<StreamParserBuffer>* out_buffer) {
   DCHECK(out_buffer->get());
   DCHECK(!pending_buffer_.get());
 
   const bool have_splice_buffers = !(*out_buffer)->splice_buffers().empty();
   const bool have_preroll_buffer = !!(*out_buffer)->preroll_buffer().get();
 
   if (!have_splice_buffers && !have_preroll_buffer)
     return false;
 
   DCHECK_NE(have_splice_buffers, have_preroll_buffer);
   splice_buffers_index_ = 0;
   pending_buffer_.swap(*out_buffer);
   pending_buffers_complete_ = false;
   return true;
 }
 
 }  // namespace media