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,
 };
 
 // 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;
@@ skipping 84 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 570 matching lines @@
   pending_buffer_ = NULL;
   return SourceBufferStream::kSuccess;
 }
 
 SourceBufferStream::Status SourceBufferStream::GetNextBufferInternal(
     scoped_refptr<StreamParserBuffer>* out_buffer) {
   CHECK(!config_change_pending_);
 
   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
     // 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();
     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()) {

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

Random out of scope question: I'm just reading the impl of IsEndOfStreamReached
for the first time. Most stuff made sense, except for the last line


return selected_range_ == ranges_.back();


I'm probably missing some detail, but doesn't it seem like that would hit pretty
often? e.g. you only have range, and you've got it selected as you feed buffers
out if it. I'm not seeing a guard that you've actually fed out all the buffers,
and even if there is a guard, how do we know EOS is the right thing to do
instead of kNeedBuffer? Again, I'm probably missing something...

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

I think IsEndOfStreamReached's name is perhaps confusing.
See the header comments. A true retval from it doesn't necessarily mean that
there is no more possible response to GetNextBuffer. It's more like
"IsEndOfStreamRangeReached", though there's also some confusing logic around
seek_pending, which might make its true name something like
"IsEndOfStreamRangeReachedOrIsSeekPendingBeyondEndOfStreamRange".

Patches welcome ;)

(Also, the guard that we've fed out all the buffers in currently selected range
(if any) is in l.1163 of this patch.)

       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