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>
 
@@ skipping 12 matching lines @@
   // 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,
+
+  // Limit the number of MEDIA_LOG() logs for track buffer time gaps.
+  kMaxTrackBufferGapWarningLogs = 20,
 };

[xhwang, 2015/08/10 23:51:08]

nit: As discussed before, these could just be "const int"s.

[wolenetz, 2015/08/11 02:53:31]

Oops! Done :)

 
 // 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) {}
 
 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 587 matching lines @@
       return kConfigChange;
     }
 
     DVLOG(3) << __FUNCTION__ << " Next buffer coming from track_buffer_";
     *out_buffer = next_buffer;
     track_buffer_.pop_front();
     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));
+
+  DecodeTimestamp next_output_buffer_timestamp =
+      (*out_buffer)->GetDecodeTimestamp();
+  if (just_exhausted_track_buffer_) {
+    DCHECK((*out_buffer)->is_key_frame());
+    just_exhausted_track_buffer_ = false;
+    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.";
+    }
+  }
+
   last_output_buffer_timestamp_ = (*out_buffer)->GetDecodeTimestamp();
   return kSuccess;
 }
 
 DecodeTimestamp SourceBufferStream::GetNextBufferTimestamp() {
   if (!track_buffer_.empty())
     return track_buffer_.front()->GetDecodeTimestamp();
 
   if (!selected_range_)
     return kNoDecodeTimestamp();
@@ skipping 489 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