Fixes issue with non-paced audio send time in dynamic pacer.

Non-paced audio should be sent "immediately", but in several places that
was determined by looking at the current time - which can lead to
inconsistencies.
E.g. if a packet is enqueued and ProcessPackets() is called 1ms later,
the pacer should see NextSendTime() as 1ms ago, so that buffer levels
are cleared at the right pace.

Bug: webrtc:10809
Change-Id: I04a169f3df3e28a5c8ef7fa8a042b9c482c307ce
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/172845
Reviewed-by: Ilya Nikolaevskiy <ilnik@webrtc.org>
Commit-Queue: Erik Språng <sprang@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31002}

modules/pacing/pacing_controller.cc

@@ -345,8 +345,14 @@ Timestamp PacingController::NextSendTime() const {
   // In dynamic mode, figure out when the next packet should be sent,
   // given the current conditions.
 
-  if (!pace_audio_ && packet_queue_.NextPacketIsAudio()) {
-    return now;
+  if (!pace_audio_) {
+    // Not pacing audio, if leading packet is audio its target send
+    // time is the time at which it was enqueued.
+    absl::optional<Timestamp> audio_enqueue_time =
+        packet_queue_.LeadingAudioPacketEnqueueTime();
+    if (audio_enqueue_time.has_value()) {
+      return *audio_enqueue_time;
+    }
   }
 
   if (Congested() || packet_counter_ == 0) {
@@ -559,6 +565,8 @@ void PacingController::ProcessPackets() {
     }
   }
 
+  last_process_time_ = std::max(last_process_time_, previous_process_time);
+
   if (is_probing) {
     probing_send_failure_ = data_sent == DataSize::Zero();
     if (!probing_send_failure_) {
@@ -613,7 +621,8 @@ std::unique_ptr<RtpPacketToSend> PacingController::GetPendingPacket(
   // First, check if there is any reason _not_ to send the next queued packet.
 
   // Unpaced audio packets and probes are exempted from send checks.
-  bool unpaced_audio_packet = !pace_audio_ && packet_queue_.NextPacketIsAudio();
+  bool unpaced_audio_packet =
+      !pace_audio_ && packet_queue_.LeadingAudioPacketEnqueueTime().has_value();
   bool is_probe = pacing_info.probe_cluster_id != PacedPacketInfo::kNotAProbe;
   if (!unpaced_audio_packet && !is_probe) {
     if (Congested()) {

modules/pacing/pacing_controller_unittest.cc

@@ -1717,24 +1717,24 @@ TEST_P(PacingControllerTest, TaskLate) {
   pacer_->ProcessPackets();
 
   Timestamp next_send_time = pacer_->NextSendTime();
+  // Determine time between packets (ca 62ms)
   const TimeDelta time_between_packets = next_send_time - clock_.CurrentTime();
 
   // Simulate a late process call, executed just before we allow sending the
   // fourth packet.
-  clock_.AdvanceTime((time_between_packets * 3) -
-                     (PacingController::kMinSleepTime + TimeDelta::Millis(1)));
+  const TimeDelta kOffset = TimeDelta::Millis(1);
+  clock_.AdvanceTime((time_between_packets * 3) - kOffset);
 
   EXPECT_CALL(callback_, SendPacket).Times(2);
   pacer_->ProcessPackets();
 
-  // Check that next scheduled send time is within sleep-time + 1ms.
+  // Check that next scheduled send time is in ca 1ms.
   next_send_time = pacer_->NextSendTime();
-  EXPECT_LE(next_send_time - clock_.CurrentTime(),
-            PacingController::kMinSleepTime + TimeDelta::Millis(1));
+  const TimeDelta time_left = next_send_time - clock_.CurrentTime();
+  EXPECT_EQ(time_left.RoundTo(TimeDelta::Millis(1)), kOffset);
 
-  // Advance to within error margin for execution.
-  clock_.AdvanceTime(TimeDelta::Millis(1));
-  EXPECT_CALL(callback_, SendPacket).Times(1);
+  clock_.AdvanceTime(time_left);
+  EXPECT_CALL(callback_, SendPacket);
   pacer_->ProcessPackets();
 }
 
@@ -1795,7 +1795,8 @@ TEST_P(PacingControllerTest, AudioNotPacedEvenWhenAccountedFor) {
   pacer_->ProcessPackets();
 }
 
-TEST_P(PacingControllerTest, PaddingAndAudioAfterVideoDisabled) {
+TEST_P(PacingControllerTest,
+       PaddingResumesAfterSaturationEvenWithConcurrentAudio) {
   const uint32_t kSsrc = 12345;
   const DataRate kPacingDataRate = DataRate::KilobitsPerSec(125);
   const DataRate kPaddingDataRate = DataRate::KilobitsPerSec(100);
@@ -1884,6 +1885,42 @@ TEST_P(PacingControllerTest, PaddingAndAudioAfterVideoDisabled) {
   }
 }
 
+TEST_P(PacingControllerTest, AccountsForAudioEnqueuTime) {
+  if (PeriodicProcess()) {
+    // This test applies only when NOT using interval budget.
+    return;
+  }
+
+  const uint32_t kSsrc = 12345;
+  const DataRate kPacingDataRate = DataRate::KilobitsPerSec(125);
+  const DataRate kPaddingDataRate = DataRate::Zero();
+  const DataSize kPacketSize = DataSize::Bytes(130);
+  const TimeDelta kPacketPacingTime = kPacketSize / kPacingDataRate;
+
+  uint32_t sequnce_number = 1;
+  // Audio not paced, but still accounted for in budget.
+  pacer_->SetAccountForAudioPackets(true);
+  pacer_->SetPacingRates(kPacingDataRate, kPaddingDataRate);
+
+  // Enqueue two audio packets, advance clock to where one packet
+  // should have drained the buffer already, has they been sent
+  // immediately.
+  SendAndExpectPacket(RtpPacketMediaType::kAudio, kSsrc, sequnce_number++,
+                      clock_.TimeInMilliseconds(), kPacketSize.bytes());
+  SendAndExpectPacket(RtpPacketMediaType::kAudio, kSsrc, sequnce_number++,
+                      clock_.TimeInMilliseconds(), kPacketSize.bytes());
+  clock_.AdvanceTime(kPacketPacingTime);
+  // Now process and make sure both packets were sent.
+  pacer_->ProcessPackets();
+  ::testing::Mock::VerifyAndClearExpectations(&callback_);
+
+  // Add a video packet. I can't be sent until debt from audio
+  // packets have been drained.
+  Send(RtpPacketMediaType::kVideo, kSsrc + 1, sequnce_number++,
+       clock_.TimeInMilliseconds(), kPacketSize.bytes());
+  EXPECT_EQ(pacer_->NextSendTime() - clock_.CurrentTime(), kPacketPacingTime);
+}
+
 INSTANTIATE_TEST_SUITE_P(
     WithAndWithoutIntervalBudget,
     PacingControllerTest,

modules/pacing/round_robin_packet_queue.cc

@@ -233,19 +233,25 @@ DataSize RoundRobinPacketQueue::Size() const {
   return size_;
 }
 
-bool RoundRobinPacketQueue::NextPacketIsAudio() const {
+absl::optional<Timestamp> RoundRobinPacketQueue::LeadingAudioPacketEnqueueTime()
+    const {
   if (single_packet_queue_.has_value()) {
-    return single_packet_queue_->Type() == RtpPacketMediaType::kAudio;
+    if (single_packet_queue_->Type() == RtpPacketMediaType::kAudio) {
+      return single_packet_queue_->EnqueueTime();
+    }
+    return absl::nullopt;
   }
 
   if (stream_priorities_.empty()) {
-    return false;
+    return absl::nullopt;
   }
   uint32_t ssrc = stream_priorities_.begin()->second;
 
-  auto stream_info_it = streams_.find(ssrc);
-  return stream_info_it->second.packet_queue.top().Type() ==
-         RtpPacketMediaType::kAudio;
+  const auto& top_packet = streams_.find(ssrc)->second.packet_queue.top();
+  if (top_packet.Type() == RtpPacketMediaType::kAudio) {
+    return top_packet.EnqueueTime();
+  }
+  return absl::nullopt;
 }
 
 Timestamp RoundRobinPacketQueue::OldestEnqueueTime() const {

modules/pacing/round_robin_packet_queue.h

@@ -46,7 +46,11 @@ class RoundRobinPacketQueue {
   bool Empty() const;
   size_t SizeInPackets() const;
   DataSize Size() const;
-  bool NextPacketIsAudio() const;
+  // If the next packet, that would be returned by Pop() if called
+  // now, is an audio packet this method returns the enqueue time
+  // of that packet. If queue is empty or top packet is not audio,
+  // returns nullopt.
+  absl::optional<Timestamp> LeadingAudioPacketEnqueueTime() const;
 
   Timestamp OldestEnqueueTime() const;
   TimeDelta AverageQueueTime() const;