Fix seeking back in the new MSE GC algorithm

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 16 matching lines @@
 // 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;
 
+// Limit the number of MEDIA_LOG() logs for MSE GC algorithm warnings.
+const int kMaxGarbageCollectAlgorithWarningLogs = 50;

[wolenetz, 2015/09/21 20:14:39]

nit: 50 is probably too high. In general, GC failure should be allowed for, so
we don't want to allow repeated such failures to exhaust the media internals
event cache.

so, s/50/20/ please.

[servolk, 2015/09/21 21:09:57]

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 565 matching lines @@
 }
 
 bool SourceBufferStream::GarbageCollectIfNeeded(DecodeTimestamp media_time,
                                                 size_t newDataSize) {
   DCHECK(media_time != kNoDecodeTimestamp());
   // Compute size of |ranges_|.
   size_t ranges_size = GetBufferedSize();
 
   // Sanity and overflow checks
   if ((newDataSize > memory_limit_) ||
-      (ranges_size + newDataSize < ranges_size))
+      (ranges_size + newDataSize < ranges_size)) {
+    LIMITED_MEDIA_LOG(DEBUG, media_log_, num_garbage_collect_algorithm_logs_,
+                      kMaxGarbageCollectAlgorithWarningLogs)
+        << "GarbageCollectIfNeeded failed: memory_limit_=" << memory_limit_

[wolenetz, 2015/09/21 20:14:39]

nit: since this is going to chrome://media-internals, let's help developers out
by letting them know at least the type of the stream (audio, video, ...) in the
log message, as well as a little more plainly state the problem. Something like

"New [audio,video,text] append of size [x] bytes exceeds buffering capacity of
[y] bytes. Previously buffered size was [z] bytes." 

[servolk, 2015/09/21 21:09:57]

Done.

+        << " ranges_size=" << ranges_size << " newDataSize=" << newDataSize;
     return false;
+  }
 
   // Return if we're under or at the memory limit.
   if (ranges_size + newDataSize <= memory_limit_)
     return true;
 
   size_t bytes_to_free = ranges_size + newDataSize - memory_limit_;
 
+  // If there is a pending seek, then we should allow GC to remove data more
+  // aggressively for the upcoming append to allow seeking to proceed.
+  bool seek_pending = IsSeekPending();

[wolenetz, 2015/09/21 20:14:39]

IIUC, IsSeekPending() isn't really what we want: it allows for edge cases
related to EOS to filter the |seek_pending_| state. Also, "seek_pending" looks
too much like "seek_pending_" but has different meaning.
Finally, IIUC, Blink always unmarks EOS prior to reaching this GC code path, so
|seek_pending_| should be exactly what we want to use here.
So, please use |seek_pending_| instead of a local, and also add a
DCHECK(!end_of_stream_); here (perhaps with a clarifying comment why...) 

[servolk, 2015/09/21 21:09:57]

Done.

+
   DVLOG(2) << __FUNCTION__ << " " << GetStreamTypeName() << ": Before GC"
            << " media_time=" << media_time.InSecondsF()
            << " ranges_=" << RangesToString(ranges_)
+           << " seek_pending=" << seek_pending
            << " ranges_size=" << ranges_size
            << " newDataSize=" << newDataSize
            << " memory_limit_=" << memory_limit_
            << " last_appended_buffer_timestamp_="
            << last_appended_buffer_timestamp_.InSecondsF();
 
   size_t bytes_freed = 0;
 
   // If last appended buffer position was earlier than the current playback time
   // then try deleting data between last append and current media_time.
   if (last_appended_buffer_timestamp_ != kNoDecodeTimestamp() &&
       last_appended_buffer_timestamp_ < media_time) {
     size_t between = FreeBuffersAfterLastAppended(bytes_to_free, media_time);
     DVLOG(3) << __FUNCTION__ << " FreeBuffersAfterLastAppended "
              << " released " << between << " bytes"
              << " ranges_=" << RangesToString(ranges_);
     bytes_freed += between;
 
-    // If the last append happened before the current playback position
-    // |media_time|, then JS player is probably preparing to seek back and we
-    // should try to preserve all most recently appended data (which is in
-    // range_for_next_append_) from being removed by GC (see crbug.com/440173)
+    // Some players start appending data at the new seek target position before
+    // actually initiating the seek operation (i.e. they try to improve seek
+    // performance by prebuffering some data at the seek target position and
+    // initiating seek once enough data is pre-buffered. In those cases we'll
+    // see that data is being appended at some new position, but there is no
+    // pending seek reported yet. In this situation we need to try preserving
+    // the most recently appended data, i.e. data belonging to the same buffered
+    // range as the most recent append.
     if (range_for_next_append_ != ranges_.end()) {
       DCHECK((*range_for_next_append_)->GetStartTimestamp() <= media_time);
       media_time = (*range_for_next_append_)->GetStartTimestamp();
     }
   }
 
+  // If there is an unsatisfied pending seek, we can safely remove all data that
+  // is earlier than seek target, then remove from the back until we reach the
+  // most recently appended GOP and then remove from the front if we still don't
+  // have enough space for the upcoming append.
+  if (bytes_freed < bytes_to_free && seek_pending) {
+    DCHECK(!ranges_.empty());
+    // All data earlier than the seek target |media_time| can be removed safely
+    size_t front = FreeBuffers(bytes_to_free - bytes_freed, media_time, false);
+    DVLOG(3) << __FUNCTION__ << " Removed " << front << " bytes from the"
+             << " front. ranges_=" << RangesToString(ranges_);
+    bytes_freed += front;
+
+    // If removing data earlier than |media_time| didn't free up enough space,
+    // then try deleting from the back until we reach most recently appended GOP
+    if (bytes_freed < bytes_to_free) {
+      size_t back = FreeBuffers(bytes_to_free - bytes_freed, media_time, true);
+      DVLOG(3) << __FUNCTION__ << " Removed " << back << " bytes from the back"
+               << " ranges_=" << RangesToString(ranges_);
+      bytes_freed += back;
+    }
+
+    // If even that wasn't enough, then try greedily deleting from the front,
+    // that should allow us to remove as much data as necessary to succeed.
+    if (bytes_freed < bytes_to_free) {
+      size_t front2 = FreeBuffers(bytes_to_free - bytes_freed,
+                                  ranges_.back()->GetEndTimestamp(), false);
+      DVLOG(3) << __FUNCTION__ << " Removed " << front << " bytes from the"
+               << " front. ranges_=" << RangesToString(ranges_);
+      bytes_freed += front2;
+    }
+    DCHECK(bytes_freed >= bytes_to_free);
+  }
+
   // Try removing data from the front of the SourceBuffer up to |media_time|
   // position.
   if (bytes_freed < bytes_to_free) {
     size_t front = FreeBuffers(bytes_to_free - bytes_freed, media_time, false);
-    DVLOG(3) << __FUNCTION__ << " Removed " << front << " bytes from the front"
-             << " ranges_=" << RangesToString(ranges_);
+    DVLOG(3) << __FUNCTION__ << " Removed " << front << " bytes from the"
+             << " front. ranges_=" << RangesToString(ranges_);
     bytes_freed += front;
   }
 
   // Try removing data from the back of the SourceBuffer, until we reach the
   // most recent append position.
   if (bytes_freed < bytes_to_free) {
     size_t back = FreeBuffers(bytes_to_free - bytes_freed, media_time, true);
-    DVLOG(3) << __FUNCTION__ << " Removed " << back << " bytes from the back"
+    DVLOG(3) << __FUNCTION__ << " Removed " << back << " bytes from the back."
              << " ranges_=" << RangesToString(ranges_);
     bytes_freed += back;
   }
 
   DVLOG(2) << __FUNCTION__ << " " << GetStreamTypeName() << ": After GC"
            << " bytes_to_free=" << bytes_to_free
            << " bytes_freed=" << bytes_freed
            << " ranges_=" << RangesToString(ranges_);
 
   return bytes_freed >= bytes_to_free;

[wolenetz, 2015/09/21 20:14:39]

nit: I recommend adding another LIMITED_MEDIA_LOG(DEBUG...) here, capped by a
different counter (also with cap, maybe of just 5), for when bytes_freed <
bytes_to_free.

[servolk, 2015/09/21 21:09:57]

Actually I think in this case we should use (D)VLOG instead of
LIMITED_MEDIA_LOG. First of all this shouldn't happen very often in properly
written apps and if it does happen many times (e.g. during a very long media
playback) we want to see all instances where this has occured and now just the
first few ones. Also just seeing this in the media log is not that useful
without seeing the rest of the context (how much data was buffered before, what
exactly the GC algorithm attempted to do) which is currenty logged via DVLOG. So
using MEDIA_LOG here is probably not that helpful, please let me know if you
disagree.

[wolenetz, 2015/09/21 21:38:28]

Acknowledged. Except in the iteration of the stream append loop, quota exceeded
exception is also given to the app synchronously on an append's failure to evict
enough to stay under the limit, so we have quite a bit of state already
available to the developer. So existing DVLOG is ok for now. I'm strongly
considering expanding upon the decode error enumeration in the HTMLMediaElement
API so that more granular, *and*, standardized error codes for things like this
can be exposed. Of course, that's outside the scope of this CL :)

 }
 
 size_t SourceBufferStream::FreeBuffersAfterLastAppended(
     size_t total_bytes_to_free, DecodeTimestamp media_time) {
   DVLOG(4) << __FUNCTION__ << " last_appended_buffer_timestamp_="
             << last_appended_buffer_timestamp_.InSecondsF()
             << " media_time=" << media_time.InSecondsF();
 
   DecodeTimestamp remove_range_start = last_appended_buffer_timestamp_;
   if (last_appended_buffer_is_keyframe_)
@@ skipping 1035 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