MSE: Warn when keyframe after track_buffer is significantly in future

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 75c9c31fd344fab814e09c442fa15429f1422097..639acc5a30b2bc34bc1c311c719f729be3d91315 100644
--- a/media/filters/source_buffer_stream.cc
+++ b/media/filters/source_buffer_stream.cc
@@ -30,6 +30,9 @@ enum {
   // important for debugging splice generation.
   kMaxSpliceGenerationWarningLogs = 50,
   kMaxSpliceGenerationSuccessLogs = 20,
+
+  // Limit the number of MEDIA_LOG() logs for track buffer time gaps.
+  kMaxTrackBufferGapWarningLogs = 20,
 };
 
 // Helper method that returns true if |ranges| is sorted in increasing order,
@@ -134,6 +137,7 @@ SourceBufferStream::SourceBufferStream(const AudioDecoderConfig& audio_config,
       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),
@@ -147,7 +151,8 @@ SourceBufferStream::SourceBufferStream(const AudioDecoderConfig& audio_config,
       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);
 }
@@ -162,6 +167,7 @@ SourceBufferStream::SourceBufferStream(const VideoDecoderConfig& video_config,
       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),
@@ -175,7 +181,8 @@ SourceBufferStream::SourceBufferStream(const VideoDecoderConfig& video_config,
       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);
 }
@@ -191,6 +198,7 @@ SourceBufferStream::SourceBufferStream(const TextTrackConfig& text_config,
       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),
@@ -204,7 +212,8 @@ SourceBufferStream::SourceBufferStream(const TextTrackConfig& text_config,
       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()) {
@@ -533,6 +542,7 @@ void SourceBufferStream::ResetSeekState() {
   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;
@@ -1123,6 +1133,7 @@ SourceBufferStream::Status SourceBufferStream::GetNextBufferInternal(
 
   if (!track_buffer_.empty()) {
     DCHECK(!selected_range_);
+    DCHECK(!just_exhausted_track_buffer_);

[wolenetz, 2015/08/08 00:51:35]

I could think of no scenario where we exhaust track_buffer_, then emit the next
buffer somehow from another track_buffer_. This seems like a sane DCHECK to add
(somewhat drive-by, though).

[chcunningham, 2015/08/10 18:02:18]

What if we encounter this sequence:

1. Overlapped append #1 fills TB
2. We read out all frames from TB, and execute lines 1154 - 1156
 -- setting just_exhausted = true 
 -- SetSelectedRangeIfNeede to somewhere in overlapped append #1
3. Overlapped append #2 causes us to push fresh stuff into TB
4. We GetNextBufferInternal ... DCHECK? 

[wolenetz, 2015/08/10 20:14:43]

While I had thought bullet #3 shouldn't put anything into TB if there has been
no GetNextBufferInternal() since previous track buffer exhaustion because a
precondition for putting anything into TB (and leaving it after pruning) is that
only sequences beginning with non-keyframes can begin track_buffers_. However, I
could be wrong (I'll read some code/write a test). I'm also unsure how much
value the DCHECK is really adding, but it could be exposing a scenario that
doesn't log the gap the way we think it should, so I'll investigate instead of
just removing the DCHECK.

[wolenetz, 2015/08/10 21:56:29]

DCHECK was indeed possible. Removed.

     scoped_refptr<StreamParserBuffer>& next_buffer = track_buffer_.front();
 
     // If the next buffer is an audio splice frame, the next effective config id
@@ -1140,8 +1151,10 @@ SourceBufferStream::Status SourceBufferStream::GetNextBufferInternal(
 
     // 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;
   }
@@ -1165,6 +1178,26 @@ SourceBufferStream::Status SourceBufferStream::GetNextBufferInternal(
   }
 
   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;
 }