From 59c35e2b2a8d936bcb2035f5118df1cf4bd5a627 Mon Sep 17 00:00:00 2001 From: Mina Almasry Date: Fri, 29 Jun 2018 01:18:51 +0000 Subject: [PATCH] [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 Reviewed-by: Sergey Volk Cr-Commit-Position: refs/heads/master@{#571351} --- chromecast/media/cma/BUILD.gn | 4 ++ .../audio_video_pipeline_device_unittest.cc | 61 ++++++++++++++++++- .../media_pipeline_backend_for_mixer.cc | 13 ++-- .../media_pipeline_backend_for_mixer.h | 5 ++ .../media/cma/backend/video/av_sync_video.cc | 54 +++++++++++++--- .../media/cma/backend/video/av_sync_video.h | 5 +- 6 files changed, 123 insertions(+), 19 deletions(-) diff --git a/chromecast/media/cma/BUILD.gn b/chromecast/media/cma/BUILD.gn index 51e253a8f030d7..4463d48684da52 100644 --- a/chromecast/media/cma/BUILD.gn +++ b/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/", ] diff --git a/chromecast/media/cma/backend/audio_video_pipeline_device_unittest.cc b/chromecast/media/cma/backend/audio_video_pipeline_device_unittest.cc index 337d09951d9724..0ff0dda5947ff6 100644 --- a/chromecast/media/cma/backend/audio_video_pipeline_device_unittest.cc +++ b/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(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(×tamp, &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 diff --git a/chromecast/media/cma/backend/media_pipeline_backend_for_mixer.cc b/chromecast/media/cma/backend/media_pipeline_backend_for_mixer.cc index 886c92b9996fe8..60133e852ac57b 100644 --- a/chromecast/media/cma/backend/media_pipeline_backend_for_mixer.cc +++ b/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; diff --git a/chromecast/media/cma/backend/media_pipeline_backend_for_mixer.h b/chromecast/media/cma/backend/media_pipeline_backend_for_mixer.h index e96e4b39f49f02..18d1b1fce77642 100644 --- a/chromecast/media/cma/backend/media_pipeline_backend_for_mixer.h +++ b/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 video_decoder_; std::unique_ptr audio_decoder_; @@ -72,6 +76,7 @@ class MediaPipelineBackendForMixer : public MediaPipelineBackend { const MediaPipelineDeviceParams params_; std::unique_ptr av_sync_; + int64_t start_playback_timestamp_us_ = INT64_MIN; DISALLOW_COPY_AND_ASSIGN(MediaPipelineBackendForMixer); }; diff --git a/chromecast/media/cma/backend/video/av_sync_video.cc b/chromecast/media/cma/backend/video/av_sync_video.cc index b489eab0a17be4..634770c4828e62 100644 --- a/chromecast/media/cma/backend/video/av_sync_video.cc +++ b/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(×tamp, &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() { diff --git a/chromecast/media/cma/backend/video/av_sync_video.h b/chromecast/media/cma/backend/video/av_sync_video.h index f498b1fa2558b3..c96b31d3988c14 100644 --- a/chromecast/media/cma/backend/video/av_sync_video.h +++ b/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_; };