[Chromecast] Enable some diagnostics of AV sync playback start times.

I am currently seeing ~200ms starting AV sync difference at the
beginning of playback, so add some checks to see if the audio/video
start at the desired time or not.

1. Add AV sync unittests tha check that the video started on time.
2. Add logging to in AvSync that logs the difference between the
   audio/video playback starting time and the actual starting time.

Bug: b/109701656
Test: On device unittests

Change-Id: I2283517953d55f9224a7e3813029e5f5c58a0ebb
Reviewed-on: https://chromium-review.googlesource.com/1111318
Commit-Queue: Mina Almasry <almasrymina@chromium.org>
Reviewed-by: Sergey Volk <servolk@chromium.org>
Cr-Commit-Position: refs/heads/master@{#571351}

chromecast/media/cma/BUILD.gn

@@ -70,6 +70,10 @@ cast_source_set("unittests") {
     "//testing/gtest",
   ]
 
+  if (enable_video_with_mixed_audio) {
+    defines = [ "ENABLE_VIDEO_WITH_MIXED_AUDIO" ]
+  }
+
   data = [
     "//media/test/data/",
   ]

chromecast/media/cma/backend/audio_video_pipeline_device_unittest.cc

@@ -25,6 +25,11 @@
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/time.h"
 #include "chromecast/base/task_runner_impl.h"
+#if defined(ENABLE_VIDEO_WITH_MIXED_AUDIO)
+#include "chromecast/media/cma/backend/audio_decoder_for_mixer.h"  // nogncheck
+#include "chromecast/media/cma/backend/media_pipeline_backend_for_mixer.h"  // nogncheck
+#include "chromecast/media/cma/backend/video_decoder_for_mixer.h"  // nogncheck
+#endif
 #include "chromecast/media/cma/base/decoder_buffer_adapter.h"
 #include "chromecast/media/cma/base/decoder_config_adapter.h"
 #include "chromecast/media/cma/test/frame_segmenter_for_test.h"
@@ -51,10 +56,16 @@ class AudioVideoPipelineDeviceTest;
 namespace {
 
 const base::TimeDelta kMonitorLoopDelay = base::TimeDelta::FromMilliseconds(20);
+#if defined(ENABLE_VIDEO_WITH_MIXED_AUDIO)
+// TODO(almasrymina): enable these tests to work with non-zero starting PTS.
+const int64_t kStartPts = 0;
+#else
 // Call Start() with an initial PTS of 1 second, to test the behaviour if
 // we push buffers with a PTS before the start PTS. In this case the backend
 // should report the PTS as no later than the last pushed buffers.
 const int64_t kStartPts = 1000 * 1000;
+#endif
+
 // Amount that PTS is allowed to progress past the time that Pause() was called.
 const int kPausePtsSlackMs = 75;
 // Number of effects streams to open simultaneously when also playing a
@@ -87,8 +98,9 @@ base::FilePath GetTestDataFilePath(const std::string& name) {
   CHECK(base::PathService::Get(base::DIR_SOURCE_ROOT, &file_path));
 
   file_path = file_path.Append(FILE_PATH_LITERAL("media"))
-      .Append(FILE_PATH_LITERAL("test")).Append(FILE_PATH_LITERAL("data"))
-      .AppendASCII(name);
+                  .Append(FILE_PATH_LITERAL("test"))
+                  .Append(FILE_PATH_LITERAL("data"))
+                  .AppendASCII(name);
   return file_path;
 }
 
@@ -318,6 +330,13 @@ void BufferFeeder::Stop() {
 }
 
 void BufferFeeder::ScheduleConfigTest() {
+#if defined(ENABLE_VIDEO_WITH_MIXED_AUDIO)
+  // On mixer backends, the config test causes the mixer to remove/add the
+  // mixer input, which causes it to return invalid PTS to AV sync. Disable for
+  // now.
+  // TODO(almasrymina): re-enable this. b/110961816.
+  return;
+#endif
   if (expecting_buffer_complete_) {
     test_config_after_next_push_ = true;
   } else {
@@ -806,6 +825,37 @@ void AudioVideoPipelineDeviceTest::MonitorLoop() {
     last_pts_ = pts;
   }
 
+#if defined(ENABLE_VIDEO_WITH_MIXED_AUDIO)
+  // Do AV sync checks.
+  MediaPipelineBackendForMixer* backend_for_mixer =
+      reinterpret_cast<MediaPipelineBackendForMixer*>(backend_.get());
+  DCHECK(backend_for_mixer);
+
+  int64_t playback_start_time =
+      backend_for_mixer->GetPlaybackStartTimeForTesting();
+
+  if (backend_for_mixer->audio_decoder() &&
+      backend_for_mixer->video_decoder() &&
+      backend_for_mixer->MonotonicClockNow() > playback_start_time + 50000) {
+    int64_t vpts = 0;
+    int64_t timestamp = 0;
+    EXPECT_TRUE(
+        backend_for_mixer->video_decoder()->GetCurrentPts(&timestamp, &vpts))
+        << "Getting VPTS failed at current time="
+        << " current time=" << backend_for_mixer->MonotonicClockNow()
+        << " playback should have started at=" << playback_start_time;
+
+    // Check video started at the correct time.
+    EXPECT_LT(abs(timestamp - vpts - playback_start_time), 30000);
+
+    // TODO(almasrymina): we still have ~150ms difference between audio and
+    // video in some playbacks in the beginning of the video. We need to
+    // reduce that.
+    EXPECT_LT(abs(backend_for_mixer->audio_decoder()->GetCurrentPts() - vpts),
+              150000);
+  }
+#endif
+
   if (!pause_pattern_.empty() &&
       pause_pattern_[pause_pattern_idx_].delay >= base::TimeDelta() &&
       media_time >= pause_time_ + pause_pattern_[pause_pattern_idx_].delay) {
@@ -1149,5 +1199,12 @@ TEST_F(AudioVideoPipelineDeviceTest, WebmPlayback_WithEffectsStreams) {
   base::RunLoop().Run();
 }
 
+TEST_F(AudioVideoPipelineDeviceTest, Mp4Playback) {
+  set_sync_type(MediaPipelineDeviceParams::kModeSyncPts);
+  ConfigureForFile("bear.mp4");
+  Start();
+  base::RunLoop().Run();
+}
+
 }  // namespace media
 }  // namespace chromecast

chromecast/media/cma/backend/media_pipeline_backend_for_mixer.cc

@@ -73,21 +73,22 @@ bool MediaPipelineBackendForMixer::Initialize() {
 
 bool MediaPipelineBackendForMixer::Start(int64_t start_pts) {
   DCHECK_EQ(kStateInitialized, state_);
-  int64_t start_playback_timestamp_us = INT64_MIN;
-  if (!IsIgnorePtsMode()) {
-    start_playback_timestamp_us =
+  if (IsIgnorePtsMode()) {
+    start_playback_timestamp_us_ = INT64_MIN;
+  } else {
+    start_playback_timestamp_us_ =
         MonotonicClockNow() + kSyncedPlaybackStartDelayUs;
   }
 
-  if (audio_decoder_ && !audio_decoder_->Start(start_playback_timestamp_us))
+  if (audio_decoder_ && !audio_decoder_->Start(start_playback_timestamp_us_))
     return false;
   if (video_decoder_ && !video_decoder_->Start(start_pts, true))
     return false;
   if (video_decoder_ &&
-      !video_decoder_->SetPts(start_playback_timestamp_us, start_pts))
+      !video_decoder_->SetPts(start_playback_timestamp_us_, start_pts))
     return false;
   if (av_sync_) {
-    av_sync_->NotifyStart(start_playback_timestamp_us);
+    av_sync_->NotifyStart(start_playback_timestamp_us_);
   }
 
   state_ = kStatePlaying;

chromecast/media/cma/backend/media_pipeline_backend_for_mixer.h

@@ -53,6 +53,10 @@ class MediaPipelineBackendForMixer : public MediaPipelineBackend {
   // Gets current time on the same clock as the rendering delay timestamp.
   virtual int64_t MonotonicClockNow() const;
 
+  int64_t GetPlaybackStartTimeForTesting() const {
+    return start_playback_timestamp_us_;
+  }
+
  protected:
   std::unique_ptr<VideoDecoderForMixer> video_decoder_;
   std::unique_ptr<AudioDecoderForMixer> audio_decoder_;
@@ -72,6 +76,7 @@ class MediaPipelineBackendForMixer : public MediaPipelineBackend {
   const MediaPipelineDeviceParams params_;
 
   std::unique_ptr<AvSync> av_sync_;
+  int64_t start_playback_timestamp_us_ = INT64_MIN;
 
   DISALLOW_COPY_AND_ASSIGN(MediaPipelineBackendForMixer);
 };

chromecast/media/cma/backend/video/av_sync_video.cc

@@ -41,7 +41,7 @@ constexpr base::TimeDelta kAvSyncUpkeepInterval =
 #if DCHECK_IS_ON()
 // Time interval between checking playbacks statistics.
 constexpr base::TimeDelta kPlaybackStatisticsCheckInterval =
-    base::TimeDelta::FromSeconds(1);
+    base::TimeDelta::FromSeconds(5);
 #endif
 
 // The amount of time we wait after a correction before we start upkeeping the
@@ -69,7 +69,8 @@ AvSyncVideo::AvSyncVideo(
 }
 
 void AvSyncVideo::UpkeepAvSync() {
-  if (backend_->MonotonicClockNow() < av_sync_start_timestamp_) {
+  if (backend_->MonotonicClockNow() <
+      (playback_start_timestamp_us_ + kAvSyncUpkeepInterval.InMicroseconds())) {
     return;
   }
 
@@ -91,8 +92,9 @@ void AvSyncVideo::UpkeepAvSync() {
   double error = 0.0;
 
   int64_t new_current_vpts = 0;
-  int64_t timestamp = 0;
-  if (!backend_->video_decoder()->GetCurrentPts(&timestamp, &new_current_vpts)) {
+  int64_t new_vpts_timestamp = 0;
+  if (!backend_->video_decoder()->GetCurrentPts(&new_vpts_timestamp,
+                                                &new_current_vpts)) {
     LOG(ERROR) << "Failed to get VPTS.";
     return;
   }
@@ -102,6 +104,13 @@ void AvSyncVideo::UpkeepAvSync() {
     last_vpts_value_recorded_ = new_current_vpts;
   }
 
+  if (!first_video_pts_received_) {
+    LOG(INFO) << "Video starting at difference="
+              << (new_vpts_timestamp - new_current_vpts) -
+                     playback_start_timestamp_us_;
+    first_video_pts_received_ = true;
+  }
+
   // TODO(almasrymina): using GetCurrentPts is vulnerable to pairing it with an
   // outdated 'now' if the thread gets descheduled in between. We currently see
   // extraneous corrections on real hardware and it's probably due to this.
@@ -121,6 +130,14 @@ void AvSyncVideo::UpkeepAvSync() {
                  << " new_current_vpts=" << new_current_vpts;
   } else {
     audio_pts_->AddSample(now, backend_->audio_decoder()->GetCurrentPts(), 1.0);
+
+    if (!first_audio_pts_received_) {
+      LOG(INFO) << "Audio starting at difference="
+                << (backend_->MonotonicClockNow() -
+                    backend_->audio_decoder()->GetCurrentPts()) -
+                       playback_start_timestamp_us_;
+      first_audio_pts_received_ = true;
+    }
   }
 
   if (video_pts_->num_samples() < 10 || audio_pts_->num_samples() < 20) {
@@ -152,11 +169,15 @@ void AvSyncVideo::UpkeepAvSync() {
 
   VLOG(3) << "Pts_monitor."
           << " difference=" << difference / 1000 << " apts_slope=" << apts_slope
-          << " apts_slope=" << apts_slope
+          << " vpts_slope=" << vpts_slope
           << " current_audio_playback_rate_=" << current_audio_playback_rate_
           << " current_vpts=" << new_current_vpts
           << " current_apts=" << backend_->audio_decoder()->GetCurrentPts()
-          << " current_time=" << backend_->MonotonicClockNow();
+          << " current_time=" << backend_->MonotonicClockNow()
+          << " video_start_error="
+          << (new_vpts_timestamp - new_current_vpts -
+              playback_start_timestamp_us_) /
+                 1000;
 
   av_sync_difference_sum_ += difference;
   ++av_sync_difference_count_;
@@ -183,7 +204,7 @@ void AvSyncVideo::SoftCorrection(int64_t now) {
   error_->EstimateY(now, &difference, &error);
 
   if (audio_pts_->num_samples() < 50) {
-    VLOG(4) << "Not enough apts samples=" << video_pts_->num_samples();
+    VLOG(4) << "Not enough apts samples=" << audio_pts_->num_samples();
     return;
   }
 
@@ -314,6 +335,11 @@ void AvSyncVideo::GatherPlaybackStatistics() {
   av_sync_difference_sum_ = 0;
   av_sync_difference_count_ = 0;
 
+  int64_t accurate_vpts = 0;
+  int64_t accurate_vpts_timestamp = 0;
+  backend_->video_decoder()->GetCurrentPts(&accurate_vpts_timestamp,
+                                           &accurate_vpts);
+
   LOG(INFO) << "Playback diagnostics:"
             << " CurrentContentRefreshRate="
             << backend_->video_decoder()->GetCurrentContentRefreshRate()
@@ -322,7 +348,13 @@ void AvSyncVideo::GatherPlaybackStatistics() {
             << " unexpected_dropped_frames=" << unexpected_dropped_frames
             << " unexpected_repeated_frames=" << unexpected_repeated_frames
             << " average_av_sync_difference="
-            << average_av_sync_difference / 1000;
+            << average_av_sync_difference / 1000 << " video_start_error="
+            << accurate_vpts_timestamp - accurate_vpts -
+                   playback_start_timestamp_us_
+            << " audio_start_error_estimate="
+            << backend_->MonotonicClockNow() -
+                   backend_->audio_decoder()->GetCurrentPts() -
+                   playback_start_timestamp_us_;
 
   int64_t current_vpts = 0;
   int64_t current_apts = 0;
@@ -360,14 +392,16 @@ void AvSyncVideo::NotifyStart(int64_t timestamp) {
   number_of_hard_corrections_ = 0;
   in_soft_correction_ = false;
   difference_at_start_of_correction_ = 0;
-  av_sync_start_timestamp_ = timestamp;
+  playback_start_timestamp_us_ = timestamp;
+  first_audio_pts_received_ = false;
+  first_video_pts_received_ = false;
 
   StartAvSync();
 }
 
 void AvSyncVideo::NotifyStop() {
   StopAvSync();
-  av_sync_start_timestamp_ = INT64_MIN;
+  playback_start_timestamp_us_ = INT64_MIN;
 }
 
 void AvSyncVideo::NotifyPause() {

chromecast/media/cma/backend/video/av_sync_video.h

@@ -89,7 +89,10 @@ class AvSyncVideo : public AvSync {
   int64_t number_of_soft_corrections_ = 0;
   int64_t last_vpts_value_recorded_ = 0;
   int64_t last_correction_timestamp_us = INT64_MIN;
-  int64_t av_sync_start_timestamp_ = INT64_MIN;
+  int64_t playback_start_timestamp_us_ = INT64_MIN;
+
+  bool first_audio_pts_received_ = false;
+  bool first_video_pts_received_ = false;
 
   MediaPipelineBackendForMixer* const backend_;
 };