MSE: Detect and MEDIA_LOG one kind of problematic GOP structure

If a random access point doesn't have the earliest presentation time of
other frames that depend on it (eg, other frames in later decode time up
until the next random access point), the MSE spec was not designed to
support processing and buffering it well. With the change to managing
and reporting buffered ranges by PTS intervals instead of DTS intervals,
this could impact interop. This change detects this general case and
logs once per track to chrome://media-internals. Later changes might
include telemetry collection to assist removing or fixing support for
at least SAP Type 2 in the MSE ISOBMFF bytestream spec.

To verify the new log is emitted by the new test, this change also
upgrades FrameProcessorTest's |media_log_| to a StrictMock<MockMediaLog>
and includes new strict verification of logs emitted during
FrameProcessorTests.

See also related spec issue https://github.com/w3c/media-source/issues/187

BUG=739931,718641

Change-Id: I361177dee6a5c70edf17bdbde2f3ea643977e6ec
Reviewed-on: https://chromium-review.googlesource.com/563017
Commit-Queue: Chrome Cunningham <chcunningham@chromium.org>
Reviewed-by: Chrome Cunningham <chcunningham@chromium.org>
Cr-Commit-Position: refs/heads/master@{#485125}

media/base/test_helpers.h

@@ -171,10 +171,36 @@ MATCHER(MuxedSequenceModeWarning, "") {
                          "SourceBuffer with multiple tracks");
 }
 
+MATCHER_P2(NonkeyframePrecedesGopStartWarning,
+           keyframe_time_string,
+           nonkeyframe_time_string,
+           "") {
+  return CONTAINS_STRING(
+      arg,
+      "Warning: presentation time of most recently processed random access "
+      "point (" +
+          std::string(keyframe_time_string) +
+          " s) is later than the presentation time of a non-keyframe (" +
+          nonkeyframe_time_string +
+          " s) that depends on it. This type of random access point is not "
+          "well supported by MSE; buffered range reporting may be less "
+          "precise.");
+}
+
 MATCHER(StreamParsingFailed, "") {
   return CONTAINS_STRING(arg, "Append: stream parsing failed.");
 }
 
+MATCHER(ParsedBuffersNotInDTSSequence, "") {
+  return CONTAINS_STRING(arg, "Parsed buffers not in DTS sequence");
+}
+
+MATCHER(ParsedDTSGreaterThanPTS, "") {
+  return CONTAINS_STRING(arg, "Parsed ") &&
+         CONTAINS_STRING(arg, "frame has DTS ") &&
+         CONTAINS_STRING(arg, ", which is after the frame's PTS");
+}
+
 MATCHER_P(FoundStream, stream_type_string, "") {
   return CONTAINS_STRING(
              arg, "found_" + std::string(stream_type_string) + "_stream") &&
@@ -203,6 +229,12 @@ MATCHER_P2(UnexpectedTrack, track_type, id, "") {
                                   " track track_id=" + id);
 }
 
+MATCHER_P2(FrameTypeMismatchesTrackType, frame_type, track_type, "") {
+  return CONTAINS_STRING(arg, std::string("Frame type ") + frame_type +
+                                  " doesn't match track buffer type " +
+                                  track_type);
+}
+
 MATCHER_P2(SkippingSpliceAtOrBefore,
            new_microseconds,
            existing_microseconds,

media/filters/frame_processor.cc

@@ -18,6 +18,7 @@ namespace media {
 const int kMaxDroppedPrerollWarnings = 10;
 const int kMaxDtsBeyondPtsWarnings = 10;
 const int kMaxMuxedSequenceModeWarnings = 1;
+const int kMaxNumNonkeyframePrecedesGopStartWarnings = 1;
 
 // Helper class to capture per-track details needed by a frame processor. Some
 // of this information may be duplicated in the short-term in the associated
@@ -26,7 +27,7 @@ const int kMaxMuxedSequenceModeWarnings = 1;
 // http://www.w3.org/TR/media-source/#track-buffers.
 class MseTrackBuffer {
  public:
-  explicit MseTrackBuffer(ChunkDemuxerStream* stream);
+  MseTrackBuffer(ChunkDemuxerStream* stream, MediaLog* media_log);
   ~MseTrackBuffer();
 
   // Get/set |last_decode_timestamp_|.
@@ -104,6 +105,14 @@ class MseTrackBuffer {
   // also FrameProcessor::ProcessFrame().
   DecodeTimestamp last_processed_decode_timestamp_;
 
+  // This is used to understand if the stream parser is producing random access
+  // points that are not SAP Type 1, whose support is likely going to be
+  // deprecated from MSE API pending real-world usage data. This is kNoTimestamp
+  // if no frames have been enqueued ever or since the last
+  // NotifyStartOfCodedFrameGroup() or Reset(). Otherwise, this is the most
+  // recently enqueued keyframe's presentation timestamp.
+  base::TimeDelta last_keyframe_presentation_timestamp_;
+
   // The coded frame duration of the last coded frame appended in the current
   // coded frame group. Initially kNoTimestamp, meaning "unset".
   base::TimeDelta last_frame_duration_;
@@ -128,16 +137,24 @@ class MseTrackBuffer {
   // clears it.
   StreamParser::BufferQueue processed_frames_;
 
+  // MediaLog for reporting messages and properties to debug content and engine.
+  MediaLog* media_log_;
+
+  // Counter that limits spam to |media_log_| for MseTrackBuffer warnings.
+  int num_nonkeyframe_precedes_gop_start_warnings_ = 0;
+
   DISALLOW_COPY_AND_ASSIGN(MseTrackBuffer);
 };
 
-MseTrackBuffer::MseTrackBuffer(ChunkDemuxerStream* stream)
+MseTrackBuffer::MseTrackBuffer(ChunkDemuxerStream* stream, MediaLog* media_log)
     : last_decode_timestamp_(kNoDecodeTimestamp()),
       last_processed_decode_timestamp_(DecodeTimestamp()),
+      last_keyframe_presentation_timestamp_(kNoTimestamp),
       last_frame_duration_(kNoTimestamp),
       highest_presentation_timestamp_(kNoTimestamp),
       needs_random_access_point_(true),
-      stream_(stream) {
+      stream_(stream),
+      media_log_(media_log) {
   DCHECK(stream_);
 }
 
@@ -152,6 +169,7 @@ void MseTrackBuffer::Reset() {
   last_frame_duration_ = kNoTimestamp;
   highest_presentation_timestamp_ = kNoTimestamp;
   needs_random_access_point_ = true;
+  last_keyframe_presentation_timestamp_ = kNoTimestamp;
 }
 
 void MseTrackBuffer::SetHighestPresentationTimestampIfIncreased(
@@ -164,6 +182,28 @@ void MseTrackBuffer::SetHighestPresentationTimestampIfIncreased(
 
 void MseTrackBuffer::EnqueueProcessedFrame(
     const scoped_refptr<StreamParserBuffer>& frame) {
+  if (frame->is_key_frame()) {
+    last_keyframe_presentation_timestamp_ = frame->timestamp();
+  } else {
+    DCHECK(last_keyframe_presentation_timestamp_ != kNoTimestamp);
+    // This is just one case of potentially problematic GOP structures, though
+    // others are more clearly disallowed in at least some of the MSE bytestream
+    // specs, especially ISOBMFF.
+    if (frame->timestamp() < last_keyframe_presentation_timestamp_) {
+      LIMITED_MEDIA_LOG(DEBUG, media_log_,
+                        num_nonkeyframe_precedes_gop_start_warnings_,
+                        kMaxNumNonkeyframePrecedesGopStartWarnings)
+          << "Warning: presentation time of most recently processed random "
+             "access point ("
+          << last_keyframe_presentation_timestamp_
+          << ") is later than the presentation time of a non-keyframe ("
+          << frame->timestamp()
+          << ") that depends on it. This type of random access point is not "
+             "well supported by MSE; buffered range reporting may be less "
+             "precise.";
+    }
+  }
+
   last_processed_decode_timestamp_ = frame->GetDecodeTimestamp();
   processed_frames_.push_back(frame);
 }
@@ -182,6 +222,7 @@ bool MseTrackBuffer::FlushProcessedFrames() {
 }
 
 void MseTrackBuffer::NotifyStartOfCodedFrameGroup(DecodeTimestamp start_time) {
+  last_keyframe_presentation_timestamp_ = kNoTimestamp;
   last_processed_decode_timestamp_ = start_time;
   stream_->OnStartOfCodedFrameGroup(start_time);
 }
@@ -294,7 +335,7 @@ bool FrameProcessor::AddTrack(StreamParser::TrackId id,
     return false;
   }
 
-  track_buffers_[id] = base::MakeUnique<MseTrackBuffer>(stream);
+  track_buffers_[id] = base::MakeUnique<MseTrackBuffer>(stream, media_log_);
   return true;
 }
 

media/filters/frame_processor_unittest.cc

@@ -20,6 +20,7 @@
 #include "media/base/media_log.h"
 #include "media/base/media_util.h"
 #include "media/base/mock_filters.h"
+#include "media/base/mock_media_log.h"
 #include "media/base/test_helpers.h"
 #include "media/base/timestamp_constants.h"
 #include "media/filters/chunk_demuxer.h"
@@ -263,7 +264,7 @@ class FrameProcessorTest : public testing::TestWithParam<bool> {
   }
 
   base::MessageLoop message_loop_;
-  MediaLog media_log_;
+  StrictMock<MockMediaLog> media_log_;
   StrictMock<FrameProcessorTestCallbackHelper> callbacks_;
 
   std::unique_ptr<FrameProcessor> frame_processor_;
@@ -336,6 +337,7 @@ TEST_F(FrameProcessorTest, WrongTypeInAppendedBuffer) {
   const auto& audio_buffers =
       StringToBufferQueue("0K", audio_id_, DemuxerStream::VIDEO);
   buffer_queue_map.insert(std::make_pair(audio_id_, audio_buffers));
+  EXPECT_MEDIA_LOG(FrameTypeMismatchesTrackType("video", "1"));
   ASSERT_FALSE(
       frame_processor_->ProcessFrames(buffer_queue_map, append_window_start_,
                                       append_window_end_, &timestamp_offset_));
@@ -352,6 +354,7 @@ TEST_F(FrameProcessorTest, NonMonotonicallyIncreasingTimestampInOneCall) {
   const auto& audio_buffers =
       StringToBufferQueue("10K 0K", audio_id_, DemuxerStream::AUDIO);
   buffer_queue_map.insert(std::make_pair(audio_id_, audio_buffers));
+  EXPECT_MEDIA_LOG(ParsedBuffersNotInDTSSequence());
   ASSERT_FALSE(
       frame_processor_->ProcessFrames(buffer_queue_map, append_window_start_,
                                       append_window_end_, &timestamp_offset_));
@@ -536,8 +539,10 @@ TEST_P(FrameProcessorTest, AudioVideo_SequentialProcessFrames) {
   //   (a0,a10,a20,a30,a40);(v0,v10,v20,v30)
   InSequence s;
   AddTestTracks(HAS_AUDIO | HAS_VIDEO);
-  if (GetParam())
+  if (GetParam()) {
     frame_processor_->SetSequenceMode(true);
+    EXPECT_MEDIA_LOG(MuxedSequenceModeWarning());
+  }
 
   EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_ * 3));
   ProcessFrames("0K 10K", "0K 10 20");
@@ -568,6 +573,7 @@ TEST_P(FrameProcessorTest, AudioVideo_Discontinuity) {
   bool using_sequence_mode = GetParam();
   if (using_sequence_mode) {
     frame_processor_->SetSequenceMode(true);
+    EXPECT_MEDIA_LOG(MuxedSequenceModeWarning());
     EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_ * 7));
   } else {
     EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_ * 6));
@@ -603,6 +609,8 @@ TEST_P(FrameProcessorTest, AudioVideo_Discontinuity_TimestampOffset) {
   AddTestTracks(HAS_AUDIO | HAS_VIDEO);
   bool using_sequence_mode = GetParam();
   frame_processor_->SetSequenceMode(using_sequence_mode);
+  if (using_sequence_mode)
+    EXPECT_MEDIA_LOG(MuxedSequenceModeWarning());
 
   // Start a coded frame group at time 100ms. Note the jagged start still uses
   // the coded frame group's start time as the range start for both streams.
@@ -722,6 +730,7 @@ TEST_P(FrameProcessorTest, AudioVideo_OutOfSequence_After_Discontinuity) {
     // applied to frames beginning at the first frame after the discontinuity
     // caused by the video append at 160K, below.
     SetTimestampOffset(frame_duration_ * 10);
+    EXPECT_MEDIA_LOG(MuxedSequenceModeWarning());
   }
   EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_ * 14));
   ProcessFrames("100K 110K 120K", "110K 120K 130K");
@@ -906,6 +915,8 @@ TEST_P(FrameProcessorTest,
   InSequence s;
   AddTestTracks(HAS_AUDIO);
   bool using_sequence_mode = GetParam();
+
+  EXPECT_MEDIA_LOG(ParsedDTSGreaterThanPTS()).Times(2);
   if (using_sequence_mode) {
     frame_processor_->SetSequenceMode(true);
     EXPECT_CALL(callbacks_, PossibleDurationIncrease(
@@ -941,9 +952,12 @@ TEST_P(FrameProcessorTest, PartialAppendWindowFilterNoNewMediaSegment) {
   // partial front trim, to prevent incorrect introduction of a discontinuity
   // and potentially a non-keyframe video frame to be processed next after the
   // discontinuity.
+  bool using_sequence_mode = GetParam();
   InSequence s;
   AddTestTracks(HAS_AUDIO | HAS_VIDEO);
-  frame_processor_->SetSequenceMode(GetParam());
+  frame_processor_->SetSequenceMode(using_sequence_mode);
+  if (using_sequence_mode)
+    EXPECT_MEDIA_LOG(MuxedSequenceModeWarning());
   EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_));
   ProcessFrames("", "0K");
   EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_));
@@ -1027,6 +1041,45 @@ TEST_P(FrameProcessorTest, PartialAppendWindowZeroDurationPreroll) {
             last_read_parser_buffer->preroll_buffer()->duration());
 }
 
+TEST_P(FrameProcessorTest,
+       OOOKeyframePrecededByDependantNonKeyframeShouldWarn) {
+  bool is_sequence_mode = GetParam();
+  InSequence s;
+  AddTestTracks(HAS_VIDEO);
+  frame_processor_->SetSequenceMode(is_sequence_mode);
+
+  if (is_sequence_mode) {
+    // Allow room in the timeline for the last video append (40|70, below) in
+    // this test to remain within default append window [0, +Infinity]. Moving
+    // the sequence mode appends to begin at time 50ms, the same time as the
+    // first append, below, also results in identical expectation checks for
+    // buffered ranges and buffer reads for both segments and sequence modes.
+    SetTimestampOffset(frame_duration_ * 5);
+  }
+
+  EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_ * 7));
+  ProcessFrames("", "50K 60");
+
+  CheckExpectedRangesByTimestamp(video_.get(), "{ [50,70) }");
+
+  EXPECT_MEDIA_LOG(ParsedDTSGreaterThanPTS());
+  EXPECT_MEDIA_LOG(NonkeyframePrecedesGopStartWarning("0.05", "0.04"));
+  EXPECT_CALL(callbacks_, PossibleDurationIncrease(frame_duration_ * 7));
+  ProcessFrames("", "40|70");  // PTS=40, DTS=70
+
+  // Verify DTS-based range is increased.
+  // TODO(wolenetz): Update this expectation to be { [50,70] } when switching to
+  // managing and reporting buffered ranges by PTS intervals instead of DTS
+  // intervals. This reflects the expectation that PTS start is not "pulled
+  // backward" for the new frame at PTS=40 because current spec text doesn't
+  // support SAP Type 2; it has no steps in the coded frame processing algorithm
+  // that would do that "pulling backward". See https://crbug.com/718641 and
+  // https://github.com/w3c/media-source/issues/187.
+  CheckExpectedRangesByTimestamp(video_.get(), "{ [50,80) }");
+  seek(video_.get(), base::TimeDelta());
+  CheckReadsThenReadStalls(video_.get(), "50 60 40");
+}
+
 INSTANTIATE_TEST_CASE_P(SequenceMode, FrameProcessorTest, Values(true));
 INSTANTIATE_TEST_CASE_P(SegmentsMode, FrameProcessorTest, Values(false));