ZeroHertzAdapterMode: do not dead-reckon repeated frame timestamps.

Timestamps are currently dead-reckoned for repeated frames in
zero-hertz mode. This leads to an ever increasing
totalPacketSendDelay metric in chrome://webrtc-internals which is
bad.

Fix this by tracking the origin timestamp of the first delay and
measuring time's progression since then. A unit test was added
which fails with the previous version.

go/rtc-0hz-present

Bug: chromium:1255737
Change-Id: I8627b91424f9bc56305b1dbd6a4c0624b6b3669d
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/242863
Reviewed-by: Erik Språng <sprang@webrtc.org>
Commit-Queue: Markus Handell <handellm@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#35595}

video/frame_cadence_adapter.cc

@@ -132,13 +132,25 @@ class ZeroHertzAdapterMode : public AdapterMode {
   };
   // The state of a scheduled repeat.
   struct ScheduledRepeat {
-    ScheduledRepeat(Timestamp scheduled, bool idle)
+    ScheduledRepeat(Timestamp origin,
-        : scheduled(scheduled), idle(idle) {}
+                    int64_t origin_timestamp_us,
+                    int64_t origin_ntp_time_ms)
+        : scheduled(origin),
+          idle(false),
+          origin(origin),
+          origin_timestamp_us(origin_timestamp_us),
+          origin_ntp_time_ms(origin_ntp_time_ms) {}
     // The instant when the repeat was scheduled.
     Timestamp scheduled;
     // True if the repeat was scheduled as an idle repeat (long), false
     // otherwise.
     bool idle;
+    // The moment we decided to start repeating.
+    Timestamp origin;
+    // The timestamp_us of the frame when we started repeating.
+    int64_t origin_timestamp_us;
+    // The ntp_times_ms of the frame when we started repeating.
+    int64_t origin_ntp_time_ms;
   };
 
   // Returns true if all spatial layers can be considered to be converged in
@@ -372,7 +384,7 @@ bool ZeroHertzAdapterMode::ProcessKeyFrameRequest() {
   // refinement frames.
   ResetQualityConvergenceInfo();
 
-  // If we're not repeating, or we're repeating with non-idle duration, we will
+  // If we're not repeating, or we're repeating with short duration, we will
   // very soon send out a frame and don't need a refresh frame.
   if (!scheduled_repeat_.has_value() || !scheduled_repeat_->idle) {
     RTC_LOG(LS_INFO) << __func__ << " this " << this
@@ -449,7 +461,14 @@ void ZeroHertzAdapterMode::ProcessOnDelayedCadence() {
 void ZeroHertzAdapterMode::ScheduleRepeat(int frame_id, bool idle_repeat) {
   RTC_DLOG(LS_VERBOSE) << __func__ << " this " << this << " frame_id "
                        << frame_id;
-  scheduled_repeat_.emplace(clock_->CurrentTime(), idle_repeat);
+  Timestamp now = clock_->CurrentTime();
+  if (!scheduled_repeat_.has_value()) {
+    scheduled_repeat_.emplace(now, queued_frames_.front().timestamp_us(),
+                              queued_frames_.front().ntp_time_ms());
+  }
+  scheduled_repeat_->scheduled = now;
+  scheduled_repeat_->idle = idle_repeat;
+
   TimeDelta repeat_delay = RepeatDuration(idle_repeat);
   queue_->PostDelayedTask(
       ToQueuedTask(safety_,
@@ -478,15 +497,20 @@ void ZeroHertzAdapterMode::ProcessRepeatedFrameOnDelayedCadence(int frame_id) {
   empty_update_rect.MakeEmptyUpdate();
   frame.set_update_rect(empty_update_rect);
 
-  // Adjust timestamps of the frame of the repeat, accounting for the delay in
+  // Adjust timestamps of the frame of the repeat, accounting for the actual
-  // scheduling this method.
+  // delay since we started repeating.
+  //
   // NOTE: No need to update the RTP timestamp as the VideoStreamEncoder
   // overwrites it based on its chosen NTP timestamp source.
-  TimeDelta scheduled_delay = RepeatDuration(scheduled_repeat_->idle);
+  TimeDelta total_delay = clock_->CurrentTime() - scheduled_repeat_->origin;
-  if (frame.timestamp_us() > 0)
+  if (frame.timestamp_us() > 0) {
-    frame.set_timestamp_us(frame.timestamp_us() + scheduled_delay.us());
+    frame.set_timestamp_us(scheduled_repeat_->origin_timestamp_us +
-  if (frame.ntp_time_ms())
+                           total_delay.us());
-    frame.set_ntp_time_ms(frame.ntp_time_ms() + scheduled_delay.ms());
+  }
+  if (frame.ntp_time_ms()) {
+    frame.set_ntp_time_ms(scheduled_repeat_->origin_ntp_time_ms +
+                          total_delay.ms());
+  }
   SendFrameNow(frame);
 
   // Schedule another repeat.
@@ -495,7 +519,10 @@ void ZeroHertzAdapterMode::ProcessRepeatedFrameOnDelayedCadence(int frame_id) {
 
 // RTC_RUN_ON(&sequence_checker_)
 void ZeroHertzAdapterMode::SendFrameNow(const VideoFrame& frame) const {
-  RTC_DLOG(LS_VERBOSE) << __func__ << " this " << this;
+  RTC_DLOG(LS_VERBOSE) << __func__ << " this " << this << " timestamp "
+                       << frame.timestamp() << " timestamp_us "
+                       << frame.timestamp_us() << " ntp_time_ms "
+                       << frame.ntp_time_ms();
   // TODO(crbug.com/1255737): figure out if frames_scheduled_for_processing
   // makes sense to compute in this implementation.
   callback_->OnFrame(/*post_time=*/clock_->CurrentTime(),

video/frame_cadence_adapter_unittest.cc

@@ -13,17 +13,20 @@
 #include <utility>
 #include <vector>
 
+#include "api/task_queue/default_task_queue_factory.h"
 #include "api/task_queue/task_queue_base.h"
 #include "api/task_queue/task_queue_factory.h"
 #include "api/units/timestamp.h"
 #include "api/video/nv12_buffer.h"
 #include "api/video/video_frame.h"
+#include "rtc_base/event.h"
 #include "rtc_base/rate_statistics.h"
 #include "rtc_base/ref_counted_object.h"
 #include "rtc_base/task_utils/to_queued_task.h"
 #include "rtc_base/time_utils.h"
 #include "system_wrappers/include/metrics.h"
 #include "system_wrappers/include/ntp_time.h"
+#include "system_wrappers/include/sleep.h"
 #include "test/field_trial.h"
 #include "test/gmock.h"
 #include "test/gtest.h"
@@ -879,5 +882,61 @@ TEST_F(FrameCadenceAdapterMetricsTest, RecordsMinLtMaxConstraintIfSetOnFrame) {
       ElementsAre(Pair(60 * 4.0 + 5.0 - 1, 1)));
 }
 
+TEST(FrameCadenceAdapterRealTimeTest, TimestampsDoNotDrift) {
+  // This regression test must be performed in realtime because of limitations
+  // in GlobalSimulatedTimeController.
+  //
+  // We sleep for a long while in OnFrame when a repeat was scheduled which
+  // should reflect in accordingly increased ntp_time_ms() and timestamp_us() in
+  // the repeated frames.
+  auto factory = CreateDefaultTaskQueueFactory();
+  auto queue =
+      factory->CreateTaskQueue("test", TaskQueueFactory::Priority::NORMAL);
+  ZeroHertzFieldTrialEnabler enabler;
+  MockCallback callback;
+  Clock* clock = Clock::GetRealTimeClock();
+  std::unique_ptr<FrameCadenceAdapterInterface> adapter;
+  int frame_counter = 0;
+  int64_t original_ntp_time_ms;
+  int64_t original_timestamp_us;
+  rtc::Event event;
+  queue->PostTask(ToQueuedTask([&] {
+    adapter = CreateAdapter(clock);
+    adapter->Initialize(&callback);
+    adapter->SetZeroHertzModeEnabled(
+        FrameCadenceAdapterInterface::ZeroHertzModeParams{});
+    adapter->OnConstraintsChanged(VideoTrackSourceConstraints{0, 30});
+    auto frame = CreateFrame();
+    original_ntp_time_ms = clock->CurrentNtpInMilliseconds();
+    frame.set_ntp_time_ms(original_ntp_time_ms);
+    original_timestamp_us = clock->CurrentTime().us();
+    frame.set_timestamp_us(original_timestamp_us);
+    constexpr int kSleepMs = rtc::kNumMillisecsPerSec / 2;
+    EXPECT_CALL(callback, OnFrame)
+        .WillRepeatedly(
+            Invoke([&](Timestamp, int, const VideoFrame& incoming_frame) {
+              ++frame_counter;
+              // Avoid the first OnFrame and sleep on the second.
+              if (frame_counter == 2) {
+                SleepMs(kSleepMs);
+              } else if (frame_counter == 3) {
+                EXPECT_GE(incoming_frame.ntp_time_ms(),
+                          original_ntp_time_ms + kSleepMs);
+                EXPECT_GE(incoming_frame.timestamp_us(),
+                          original_timestamp_us + kSleepMs);
+                event.Set();
+              }
+            }));
+    adapter->OnFrame(frame);
+  }));
+  event.Wait(rtc::Event::kForever);
+  rtc::Event finalized;
+  queue->PostTask(ToQueuedTask([&] {
+    adapter = nullptr;
+    finalized.Set();
+  }));
+  finalized.Wait(rtc::Event::kForever);
+}
+
 }  // namespace
 }  // namespace webrtc