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>
 
 #include "base/bind.h"
 #include "base/logging.h"
 #include "base/trace_event/trace_event.h"
 #include "media/base/audio_splicer.h"
 #include "media/filters/source_buffer_platform.h"
 #include "media/filters/source_buffer_range.h"
 
 namespace media {
 
+namespace {
+
+enum {
+  // 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.
+  kDefaultBufferDurationInMs = 125,
+
+  // Limit the number of MEDIA_LOG() logs for splice buffer generation warnings
+  // and successes. Though these values are high enough to possibly exhaust the
+  // media internals event cache (along with other events), these logs are
+  // important for debugging splice generation.
+  kMaxSpliceGenerationWarningLogs = 50,
+  kMaxSpliceGenerationSuccessLogs = 20,
+};
+
 // Helper method that returns true if |ranges| is sorted in increasing order,
 // false otherwise.
-static bool IsRangeListSorted(
-    const std::list<media::SourceBufferRange*>& ranges) {
+bool IsRangeListSorted(const std::list<media::SourceBufferRange*>& ranges) {
   DecodeTimestamp prev = kNoDecodeTimestamp();
   for (std::list<SourceBufferRange*>::const_iterator itr =
        ranges.begin(); itr != ranges.end(); ++itr) {
     if (prev != kNoDecodeTimestamp() && prev >= (*itr)->GetStartTimestamp())
       return false;
     prev = (*itr)->GetEndTimestamp();
   }
   return true;
 }
 
 // Returns an estimate of how far from the beginning or end of a range a buffer
 // can be to still be considered in the range, given the |approximate_duration|
 // of a buffer in the stream.
 // TODO(wolenetz): Once all stream parsers emit accurate frame durations, use
 // logic like FrameProcessor (2*last_frame_duration + last_decode_timestamp)
 // instead of an overall maximum interbuffer delta for range discontinuity
 // detection, and adjust similarly for splice frame discontinuity detection.
 // See http://crbug.com/351489 and http://crbug.com/351166.
-static base::TimeDelta ComputeFudgeRoom(base::TimeDelta approximate_duration) {
+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;
-
 // 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() {
+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::string RangeToString(const SourceBufferRange& range) {
   std::stringstream ss;
   ss << "[" << range.GetStartTimestamp().InSecondsF()
      << ";" << range.GetEndTimestamp().InSecondsF()
      << "(" << range.GetBufferedEndTimestamp().InSecondsF() << ")]";
   return ss.str();
 }
 
 // Helper method for logging, converts a set of ranges into a readable string.
-static std::string RangesToString(const SourceBufferStream::RangeList& ranges) {
+std::string RangesToString(const SourceBufferStream::RangeList& ranges) {
   if (ranges.empty())
     return "<EMPTY>";
 
   std::stringstream ss;
   for (const auto* range_ptr : ranges) {
     if (range_ptr != ranges.front())
       ss << " ";
     ss << RangeToString(*range_ptr);
   }
   return ss.str();
 }
 
-static SourceBufferRange::GapPolicy TypeToGapPolicy(
-    SourceBufferStream::Type type) {
+SourceBufferRange::GapPolicy TypeToGapPolicy(SourceBufferStream::Type type) {
   switch (type) {
     case SourceBufferStream::kAudio:
     case SourceBufferStream::kVideo:
       return SourceBufferRange::NO_GAPS_ALLOWED;
     case SourceBufferStream::kText:
       return SourceBufferRange::ALLOW_GAPS;
   }
 
   NOTREACHED();
   return SourceBufferRange::NO_GAPS_ALLOWED;
 }
 
+}  // namespace
+
 SourceBufferStream::SourceBufferStream(const AudioDecoderConfig& audio_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_(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 generation: first new buffer at "
+        << 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 "
+                "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 generation: 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 generation: 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).
+  // or less than two samples (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 generation: 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