MSE - Fix crash caused by incorrect GC of GOP with next buffer position

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 712 matching lines @@
       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"
+      DVLOG(3) << __FUNCTION__ << " Removed " << front2 << " 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);
@@ skipping 91 matching lines @@
 
   // This range will save the last GOP appended to |range_for_next_append_|
   // if the buffers surrounding it get deleted during garbage collection.
   SourceBufferRange* new_range_for_append = NULL;
 
   while (!ranges_.empty() && bytes_freed < total_bytes_to_free) {
     SourceBufferRange* current_range = NULL;
     BufferQueue buffers;
     size_t bytes_deleted = 0;
 
     if (reverse_direction) {

[chcunningham, 2016/02/16 21:27:02]

I don't see that there is any check in the reverse_direction case that "The GOP
being deleted must NOT contain the next buffer position." as required by the new
comments in s_b_r.h

I also don't see that media_time is at all used in this case in general. Why
not?

I think documentation for media_time in .h file should better explain what its
implications are for this methods algorithm

[wolenetz, 2016/02/16 22:05:05]

l.848 is that check.
if last append is reached first in reverse (or forward) collection, then
collection stops (l.873, l.879, l.899). If media_time is reached first, l.848
should cover that case already.

IIUC, media_time is most useful to the GC heuristic when pending_seek_ is true.
Otherwise, the First/LastGOPContainsNextBufferPosition() are more meaningful.
The latter regressed and this change seeks to fix. Whether or not media_time in
the !seek_pending_ case is meaningful to the GC heuristic is out of scope of
this CL.

[servolk, 2016/02/16 23:11:24]

media_time is certainly useful for pending seeks, but not only for that! Using
media_time instead of the demuxer read position for the GC algorithms makes
things clearer for apps and keeps our GC compliant to the MSE spec. The demuxer
read position is purely internal thing that is not visible to the Javascript
player/apps (whereas the media_time position is known in Javascript as
HTMLMediaElement::currentTime). So we had bugs in the past where apps would
notice that the current playback position (media_time) had been evicted by the
GC algorithm and would try to re-buffer that media range being unaware that
those buffers have already been consumed by the media pipeline and are no longer
necessary. By using the media_time we'll keep the data that's already been read
from the demuxer slightly longer, but will avoid confusing the apps.

[servolk, 2016/02/16 23:11:24]

The reason why the next buffer position (i.e. demuxer read position) and not the
media_time is used here is because media_time is that the next buffer position
is generally slighly ahead of the media_time. And if I understand this piece of
code correctly (I'm not the original author), I think most of the time during
normal playback the GC in the reverse direction will stop due to reaching the
last appended buffer position (see the check at line 874). We should only ever
hit this in cases when there's a pending seek backwards on the timeline and for
those cases we want to keep a small amount of data to allow the playback to
continue while the seeking is still in progress.

[chcunningham, 2016/02/16 23:36:25]

Sorry missed that check

       current_range = ranges_.back();
       DVLOG(5) << "current_range=" << RangeToString(*current_range);
       if (current_range->LastGOPContainsNextBufferPosition()) {
         DCHECK_EQ(current_range, selected_range_);
         DVLOG(5) << "current_range contains next read position, stopping GC";
         break;
       }
       DVLOG(5) << "Deleting GOP from back: " << RangeToString(*current_range);
       bytes_deleted = current_range->DeleteGOPFromBack(&buffers);
     } else {
       current_range = ranges_.front();
       DVLOG(5) << "current_range=" << RangeToString(*current_range);
-      if (!current_range->FirstGOPEarlierThanMediaTime(media_time)) {
+      if (!current_range->FirstGOPEarlierThanMediaTime(media_time) ||
+          current_range->FirstGOPContainsNextBufferPosition()) {

[wolenetz, 2016/02/13 01:35:07]

This is the core of the fix...

[servolk, 2016/02/16 19:28:38]

Have you been able to figure out exactly how this happens? TBH I don't
understand how that's possible. I think media_time (the current playback
position on the timeline) should be always <= next_buffer_position (the demuxer
read position). So having this additional check here shouldn't change anything,
imho. Perhaps we should also add a dcheck here that media_time <=
next_buffer_position?

[wolenetz, 2016/02/16 20:12:47]

Yes. I've confirmed at least one way this happens via log inspection and a unit
test (see the new unit test in this CL).
tl;dr: have some later buffered range than the current range. Seek to a time
within the duration of the very last frame in the current range, but after the
DTS of that frame. Garbage collect that range from the beginning. BOOM.
This is also why I added the "alternatively..." CR comment in this CL's earlier
patch set 1 at SBR::FirstGOPEarlierThanMediaTime().

[servolk, 2016/02/16 23:11:24]

ok, but this requires seeking to a very precise position (within a duration of
the video frame!) to cause any problems, so I think it's unlikely to be the root
cause of the crashes being investigated, although I agree we can harden things
here as well.

[chcunningham, 2016/02/16 23:36:25]

After chatting f2f we settled on doing the "alternative" fix as well, as we
agree FirstGOPEarlierThanMediaTime is not quite correct if it fails to
considered the duration of the last frame. 

[wolenetz, 2016/02/16 23:37:55]

Acknowledged. Unfortunately, I have been hitting this and only this in my
attempts to repro the crashes using the steps from the internal b/. I've changed
some of SourceBufferRange's DCHECKs to CHECKs temporarily already
(https://codereview.chromium.org/1673293003/), and may do more of the same if we
continue to see crashes in SourceBufferRange after this fix has landed.

I suspect that the repro involves or is exacerbated by apps clamping seeks to
end of buffered ranges (either by interception of seeks or by doing some
explicit remove starting at the seek target time prior to appending data to
satisfy the seek there and invoking the implicit GC). Note that buffered end
time of a range is what is visible to apps, and that is very likely beyond the
last DTS of the last coded frame in the range.

         // We have removed all data up to the GOP that contains current playback
         // position, we can't delete any further.
         DVLOG(5) << "current_range contains playback position, stopping GC";
         break;
       }
-      DVLOG(4) << "Deleting GOP from front: " << RangeToString(*current_range);
+      DVLOG(4) << "Deleting GOP from front: " << RangeToString(*current_range)
+               << ", media_time: " << media_time.InMicroseconds()
+               << ", current_range->HasNextBufferPosition(): "
+               << current_range->HasNextBufferPosition();
       bytes_deleted = current_range->DeleteGOPFromFront(&buffers);
     }
 
     // Check to see if we've just deleted the GOP that was last appended.
     DecodeTimestamp end_timestamp = buffers.back()->GetDecodeTimestamp();
     if (end_timestamp == last_appended_buffer_timestamp_) {
       DCHECK(last_appended_buffer_timestamp_ != kNoDecodeTimestamp());
       DCHECK(!new_range_for_append);
 
       // Create a new range containing these buffers.
@@ skipping 907 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