MSE: Warn when keyframe after track_buffer is significantly in future

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,
+// 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.
+const int 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,
-};
+// 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.
+const int kMaxSpliceGenerationWarningLogs = 50;
+const int kMaxSpliceGenerationSuccessLogs = 20;
+
+// Limit the number of MEDIA_LOG() logs for track buffer time gaps.
+const int kMaxTrackBufferGapWarningLogs = 20;
 
 // Helper method that returns true if |ranges| is sorted in increasing order,
 // false otherwise.
 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();
@@ skipping 83 matching lines @@
 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),
+      just_exhausted_track_buffer_(false),
       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),
       num_splice_generation_warning_logs_(0),
-      num_splice_generation_success_logs_(0) {
+      num_splice_generation_success_logs_(0),
+      num_track_buffer_gap_warning_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),
+      just_exhausted_track_buffer_(false),
       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),
       num_splice_generation_warning_logs_(0),
-      num_splice_generation_success_logs_(0) {
+      num_splice_generation_success_logs_(0),
+      num_track_buffer_gap_warning_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),
+      just_exhausted_track_buffer_(false),
       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),
       num_splice_generation_warning_logs_(0),
-      num_splice_generation_success_logs_(0) {}
+      num_splice_generation_success_logs_(0),
+      num_track_buffer_gap_warning_logs_(0) {}

[xhwang, 2015/08/11 07:04:36]

For future cleanup, consider using in-class member initialization to simplify
these constructors:

https://google-styleguide.googlecode.com/svn/trunk/cppguide.html#Initialization

[wolenetz, 2015/08/11 15:54:40]

Acknowledged.

[wolenetz, 2015/08/11 17:52:16]

Thanks for pointing out this cleanup opportunity! I've made a start at some of
this cleanup in https://codereview.chromium.org/1278193003/.

 
 SourceBufferStream::~SourceBufferStream() {
   while (!ranges_.empty()) {
     delete ranges_.front();
     ranges_.pop_front();
   }
 }
 
 void SourceBufferStream::OnNewMediaSegment(
     DecodeTimestamp media_segment_start_time) {
@@ skipping 308 matching lines @@
 
   DCHECK(IsRangeListSorted(ranges_));
   DCHECK(OnlySelectedRangeIsSeeked());
 }
 
 void SourceBufferStream::ResetSeekState() {
   SetSelectedRange(NULL);
   track_buffer_.clear();
   config_change_pending_ = false;
   last_output_buffer_timestamp_ = kNoDecodeTimestamp();
+  just_exhausted_track_buffer_ = false;
   splice_buffers_index_ = 0;
   pending_buffer_ = NULL;
   pending_buffers_complete_ = false;
 }
 
 bool SourceBufferStream::ShouldSeekToStartOfBuffered(
     base::TimeDelta seek_timestamp) const {
   if (ranges_.empty())
     return false;
   base::TimeDelta beginning_of_buffered =
@@ skipping 583 matching lines @@
     // comes from the first splice buffer.
     if (next_buffer->GetSpliceBufferConfigId(0) != current_config_index_) {
       config_change_pending_ = true;
       DVLOG(1) << "Config change (track buffer config ID does not match).";
       return kConfigChange;
     }
 
     DVLOG(3) << __FUNCTION__ << " Next buffer coming from track_buffer_";
     *out_buffer = next_buffer;
     track_buffer_.pop_front();
+    WarnIfTrackBufferExhaustionSkipsForward(*out_buffer);
     last_output_buffer_timestamp_ = (*out_buffer)->GetDecodeTimestamp();
 
     // If the track buffer becomes empty, then try to set the selected range
     // based on the timestamp of this buffer being returned.
-    if (track_buffer_.empty())
+    if (track_buffer_.empty()) {
+      just_exhausted_track_buffer_ = true;
       SetSelectedRangeIfNeeded(last_output_buffer_timestamp_);
+    }
 
     return kSuccess;
   }
 
   DCHECK(track_buffer_.empty());
   if (!selected_range_ || !selected_range_->HasNextBuffer()) {
     if (IsEndOfStreamReached()) {
       return kEndOfStream;
     }
     DVLOG(3) << __FUNCTION__ << " " << GetStreamTypeName()
              << ": returning kNeedBuffer "
              << (selected_range_ ? "(selected range has no next buffer)"
                                  : "(no selected range)");
     return kNeedBuffer;
   }
 
   if (selected_range_->GetNextConfigId() != current_config_index_) {
     config_change_pending_ = true;
     DVLOG(1) << "Config change (selected range config ID does not match).";
     return kConfigChange;
   }
 
   CHECK(selected_range_->GetNextBuffer(out_buffer));
+  WarnIfTrackBufferExhaustionSkipsForward(*out_buffer);
   last_output_buffer_timestamp_ = (*out_buffer)->GetDecodeTimestamp();
   return kSuccess;
 }
 
+void SourceBufferStream::WarnIfTrackBufferExhaustionSkipsForward(
+    const scoped_refptr<StreamParserBuffer>& next_buffer) {
+  if (!just_exhausted_track_buffer_)
+    return;
+
+  just_exhausted_track_buffer_ = false;
+  DCHECK(next_buffer->is_key_frame());
+  DecodeTimestamp next_output_buffer_timestamp =
+      next_buffer->GetDecodeTimestamp();
+  base::TimeDelta delta =
+      next_output_buffer_timestamp - last_output_buffer_timestamp_;
+  DCHECK_GE(delta, base::TimeDelta());
+  if (delta > GetMaxInterbufferDistance()) {
+    LIMITED_MEDIA_LOG(DEBUG, media_log_, num_track_buffer_gap_warning_logs_,
+                      kMaxTrackBufferGapWarningLogs)
+        << "Media append that overlapped current playback position caused time "
+           "gap in playing "
+        << GetStreamTypeName() << " stream because the next keyframe is "
+        << delta.InMilliseconds() << "ms beyond last overlapped frame. Media "
+                                     "may appear temporarily frozen.";
+  }
+}
+
 DecodeTimestamp SourceBufferStream::GetNextBufferTimestamp() {
   if (!track_buffer_.empty())
     return track_buffer_.front()->GetDecodeTimestamp();
 
   if (!selected_range_)
     return kNoDecodeTimestamp();
 
   DCHECK(selected_range_->HasNextBufferPosition());
   return selected_range_->GetNextTimestamp();
 }
@@ skipping 485 matching lines @@
     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