[Chromecast] Improve AV sync at playback start

A number of changes to improve AV sync at playback start:

- AvSync now will not perform corrections if it measures a slope that is
way off from what it expects. There are a number of reasons this could
happen:
  - Samples measured right after resuming playback may be from the
  paused state, which messes with the measured slope. This is especially
  important given our current interaction with the
  BufferingController...
  - Some vendor video decoder implementations will play video at an
  accelerated rate if they are not able to start playback in time, to
  'catch up' to the required value, and then resume normally. We need to
  ignore this behavior in AvSync.

- Modify the initialization of AvSync a bit to treat Start/Stop similar
to Pause/Resume. From the prespective of AvSync these should be
identical calls, and should maybe be combined to one in the future.
Also, due to the interaction with BufferingController, Start is actually
Start + Pause + Resume, so we need to treat Resume as we do for Start,
because the start of playback is actually the first Resume.

- For AvSync to compare the slope to an expected case, it needs to know
the current rate of playback, so add code from MediaPipelineBackend to
notify AvSync of playback rate changes.
  - As a bonus, the playback rate change is handled a bit better now.
  It's not perfect, but this is the first time I'm testing it as it
  seems no app supports it.

- Add ability for linear regression to dump its samples. This is very
useful for debugging unexpected slope calculations. This was very useful
to root cause the issue.

Bug: b/110481225
Test: Manual

Change-Id: I28ffa83c633446f2441ff5dfb8d5674b5e149ea5
Reviewed-on: https://chromium-review.googlesource.com/1132518Reviewed-by: Sergey Volk <servolk@chromium.org>
Reviewed-by: Kenneth MacKay <kmackay@chromium.org>
Commit-Queue: Mina Almasry <almasrymina@chromium.org>
Cr-Commit-Position: refs/heads/master@{#575130}

chromecast/base/statistics/weighted_moving_linear_regression.cc

@@ -33,13 +33,13 @@ void WeightedMovingLinearRegression::AddSample(int64_t x,
 
   UpdateSet(x, y, weight);
   Sample sample = {x, y, weight};
-  samples_.push(sample);
+  samples_.push_back(sample);
 
   // Remove old samples.
   while (x - samples_.front().x > max_x_range_) {
     const Sample& old_sample = samples_.front();
     UpdateSet(old_sample.x, old_sample.y, -old_sample.weight);
-    samples_.pop();
+    samples_.pop_front();
   }
   DCHECK(!samples_.empty());
 
@@ -96,4 +96,11 @@ void WeightedMovingLinearRegression::UpdateSet(int64_t x,
   covariance_ += weight * (x - x_mean_.weighted_mean()) * (y - old_y_mean);
 }
 
+void WeightedMovingLinearRegression::DumpSamples() const {
+  for (auto sample : samples_) {
+    LOG(INFO) << "x,y,weight: " << sample.x << ", " << sample.y
+              << sample.weight;
+  }
+}
+
 }  // namespace chromecast

chromecast/base/statistics/weighted_moving_linear_regression.h

@@ -46,6 +46,9 @@ class WeightedMovingLinearRegression {
   // case |slope| and |error| are not modified. Returns true otherwise.
   bool EstimateSlope(double* slope, double* error) const;
 
+  // Dumps samples currently in the linear regression.
+  void DumpSamples() const;
+
  private:
   struct Sample {
     int64_t x;
@@ -61,7 +64,7 @@ class WeightedMovingLinearRegression {
   WeightedMean x_mean_;
   WeightedMean y_mean_;
   double covariance_;
-  std::queue<Sample> samples_;
+  std::deque<Sample> samples_;
 
   double slope_;
   double slope_variance_;

chromecast/media/cma/backend/av_sync.h

@@ -41,20 +41,21 @@ class AvSync {
   // at. AvSync will typically start upkeeping AV sync after this is called.
   virtual void NotifyStart(int64_t timestamp, int64_t pts) = 0;
 
-  // Notify that the audio playback has been stopped. AvSync will typically stop
-  // upkeeping AV sync after this call. The AV sync code is *not* responsible
-  // for stopping the video.
+  // Notify that the playback has been stopped. AvSync will typically stop
+  // upkeeping AV sync after this call.
   virtual void NotifyStop() = 0;
 
-  // Notify that the audio playback has been paused. AvSync will typically stop
-  // upkeeping AV sync until the audio playback is resumed again. The AV sync
-  // code is *not* responsible for pausing the video.
+  // Notify that the playback has been paused. AvSync will typically stop
+  // upkeeping AV sync until the playback is resumed again.
   virtual void NotifyPause() = 0;
 
-  // Notify that the audio playback has been resumed. AvSync will typically
-  // start upkeeping AV sync again after this is called. The AV sync code is
-  // *not* responsible for resuming the video.
+  // Notify that the playback has been resumed. AvSync will typically
+  // start upkeeping AV sync again after this is called.
   virtual void NotifyResume() = 0;
+
+  // Notify that the video playback rate has been changed to |rate|. AvSync will
+  // typically match the audio playback rate to that.
+  virtual void NotifyPlaybackRateChange(float rate) = 0;
 };
 
 }  // namespace media

chromecast/media/cma/backend/av_sync_dummy.cc

@@ -18,6 +18,7 @@ class AvSyncDummy : public AvSync {
   void NotifyStop() override;
   void NotifyPause() override;
   void NotifyResume() override;
+  void NotifyPlaybackRateChange(float rate) override;
 };
 
 std::unique_ptr<AvSync> AvSync::Create(
@@ -36,5 +37,7 @@ void AvSyncDummy::NotifyPause() {}
 
 void AvSyncDummy::NotifyResume() {}
 
+void AvSyncDummy::NotifyPlaybackRateChange(float rate) {}
+
 }  // namespace media
 }  // namespace chromecast

chromecast/media/cma/backend/media_pipeline_backend_for_mixer.cc

@@ -141,16 +141,14 @@ bool MediaPipelineBackendForMixer::Resume() {
 bool MediaPipelineBackendForMixer::SetPlaybackRate(float rate) {
   LOG(INFO) << __func__ << " rate=" << rate;
 
-  // TODO(almasrymina); instead of depending on the AV sync code to figure out
-  // that the playback rate has changed, we should notify it that we changed
-  // the playback rate and have it take that into account immediately.
-  // b/110230181.
-  //
   // If av_sync_ is available, only set the playback rate of the video master,
   // and let av_sync_ handle syncing the audio to the video.
   if (av_sync_) {
     DCHECK(video_decoder_);
-    return video_decoder_->SetPlaybackRate(rate);
+    if (!video_decoder_->SetPlaybackRate(rate))
+      return false;
+    av_sync_->NotifyPlaybackRateChange(rate);
+    return true;
   }
 
   // If there is no av_sync_, then we must manually set the playback rate of

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

@@ -37,15 +37,19 @@ const int kLinearRegressionDataLifetimeUs = 5000000;
 constexpr base::TimeDelta kAvSyncUpkeepInterval =
     base::TimeDelta::FromMilliseconds(10);
 
-#if DCHECK_IS_ON()
 // Time interval between checking playbacks statistics.
 constexpr base::TimeDelta kPlaybackStatisticsCheckInterval =
     base::TimeDelta::FromSeconds(5);
-#endif
 
 // The amount of time we wait after a correction before we start upkeeping the
 // AV sync.
 const int kMinimumWaitAfterCorrectionUs = 200000;
+
+// This is the threshold for which we consider the rate of playback variation
+// to be valid. If we measure a rate of playback variation worse than this, we
+// consider the linear regression measurement invalid, we flush the linear
+// regression and let AvSync collect samples all over again.
+const double kExpectedSlopeVariance = 0.1;
 }  // namespace
 
 std::unique_ptr<AvSync> AvSync::Create(
@@ -135,9 +139,9 @@ void AvSyncVideo::UpkeepAvSync() {
     return;
   }
 
-  int64_t current_vpts;
-  double vpts_slope;
-  double apts_slope;
+  int64_t current_vpts = 0;
+  double vpts_slope = 0.0;
+  double apts_slope = 0.0;
   if (!video_pts_->EstimateY(now, &current_vpts, &error) ||
       !audio_pts_->EstimateY(now, &current_apts, &error) ||
       !video_pts_->EstimateSlope(&vpts_slope, &error) ||
@@ -146,6 +150,22 @@ void AvSyncVideo::UpkeepAvSync() {
     return;
   }
 
+  if (abs(vpts_slope - current_video_playback_rate_) > kExpectedSlopeVariance) {
+    LOG(ERROR) << "Calculated bad vpts_slope=" << vpts_slope
+               << ". Expected value close to=" << current_video_playback_rate_
+               << ". Flushing...";
+    FlushVideoPts();
+    return;
+  }
+
+  if (abs(apts_slope - current_audio_playback_rate_) > kExpectedSlopeVariance) {
+    LOG(ERROR) << "Calculated bad apts_slope=" << apts_slope
+               << ". Expected value close to=" << current_audio_playback_rate_
+               << ". Flushing...";
+    FlushAudioPts();
+    return;
+  }
+
   error_->AddSample(now, current_apts - current_vpts, 1.0);
 
   if (error_->num_samples() < 5) {
@@ -185,6 +205,20 @@ void AvSyncVideo::UpkeepAvSync() {
   }
 }
 
+void AvSyncVideo::FlushAudioPts() {
+  audio_pts_.reset(
+      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
+  error_.reset(
+      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
+}
+
+void AvSyncVideo::FlushVideoPts() {
+  video_pts_.reset(
+      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
+  error_.reset(
+      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
+}
+
 void AvSyncVideo::SoftCorrection(int64_t now,
                                  int64_t current_vpts,
                                  int64_t current_apts,
@@ -364,26 +398,12 @@ void AvSyncVideo::GatherPlaybackStatistics() {
   number_of_hard_corrections_ = 0;
 }
 
-void AvSyncVideo::StopAvSync() {
-  audio_pts_.reset(
-      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
-  video_pts_.reset(
-      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
-  error_.reset(
-      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
-  upkeep_av_sync_timer_.Stop();
-  playback_statistics_timer_.Stop();
-}
-
 void AvSyncVideo::NotifyStart(int64_t timestamp, int64_t pts) {
-  number_of_soft_corrections_ = 0;
-  number_of_hard_corrections_ = 0;
-  in_soft_correction_ = false;
-  difference_at_start_of_correction_ = 0;
   playback_start_timestamp_us_ = timestamp;
   playback_start_pts_us_ = pts;
-  first_audio_pts_received_ = false;
-  first_video_pts_received_ = false;
+  LOG(INFO) << __func__
+            << " playback_start_timestamp_us_=" << playback_start_timestamp_us_
+            << " playback_start_pts_us_=" << playback_start_pts_us_;
 
   StartAvSync();
 }
@@ -399,19 +419,52 @@ void AvSyncVideo::NotifyPause() {
 }
 
 void AvSyncVideo::NotifyResume() {
+  playback_start_timestamp_us_ = backend_->MonotonicClockNow();
+  LOG(INFO) << __func__
+            << " playback_start_timestamp_us_=" << playback_start_timestamp_us_;
   StartAvSync();
 }
 
+void AvSyncVideo::NotifyPlaybackRateChange(float rate) {
+  current_audio_playback_rate_ =
+      backend_->audio_decoder()->SetPlaybackRate(rate);
+
+  current_video_playback_rate_ = rate;
+
+  in_soft_correction_ = false;
+  difference_at_start_of_correction_ = 0;
+
+  FlushAudioPts();
+  FlushVideoPts();
+}
+
 void AvSyncVideo::StartAvSync() {
+  audio_pts_.reset(
+      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
+  video_pts_.reset(
+      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
+  error_.reset(
+      new WeightedMovingLinearRegression(kLinearRegressionDataLifetimeUs));
+
+  number_of_soft_corrections_ = 0;
+  number_of_hard_corrections_ = 0;
+  in_soft_correction_ = false;
+  difference_at_start_of_correction_ = 0;
+  first_audio_pts_received_ = false;
+  first_video_pts_received_ = false;
+
   upkeep_av_sync_timer_.Start(FROM_HERE, kAvSyncUpkeepInterval, this,
                               &AvSyncVideo::UpkeepAvSync);
-#if DCHECK_IS_ON()
   // TODO(almasrymina): if this logic turns out to be useful for metrics
   // recording, keep it and remove this TODO. Otherwise remove it.
   playback_statistics_timer_.Start(FROM_HERE, kPlaybackStatisticsCheckInterval,
                                    this,
                                    &AvSyncVideo::GatherPlaybackStatistics);
-#endif
+}
+
+void AvSyncVideo::StopAvSync() {
+  upkeep_av_sync_timer_.Stop();
+  playback_statistics_timer_.Stop();
 }
 
 AvSyncVideo::~AvSyncVideo() = default;

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

@@ -33,6 +33,7 @@ class AvSyncVideo : public AvSync {
   void NotifyStop() override;
   void NotifyPause() override;
   void NotifyResume() override;
+  void NotifyPlaybackRateChange(float rate) override;
 
   class Delegate {
    public:
@@ -58,6 +59,8 @@ class AvSyncVideo : public AvSync {
   void StartAvSync();
   void StopAvSync();
   void GatherPlaybackStatistics();
+  void FlushAudioPts();
+  void FlushVideoPts();
 
   void SoftCorrection(int64_t now,
                       int64_t current_vpts,
@@ -91,6 +94,7 @@ class AvSyncVideo : public AvSync {
   std::unique_ptr<WeightedMovingLinearRegression> video_pts_;
   std::unique_ptr<WeightedMovingLinearRegression> error_;
   double current_audio_playback_rate_ = 1.0;
+  double current_video_playback_rate_ = 1.0;
 
   int64_t last_gather_timestamp_us_ = 0;
   int64_t last_repeated_frames_ = 0;