[Stats] Update totalPacketSendDelay to only cover time in pacer queue.

This metric was always supposed to be the spec's answer to
googBucketDelay, and is defined as "The total number of seconds that
packets have spent buffered locally before being transmitted onto the
network." But our implementation measured the time between capture and
send, including encode time. This is incorrect and yields a much larger
value than expected.

This CL updated the metric to do what the spec says. Implementation-wise
we measure the time between pushing and popping each packet from the
queue (in modules/pacing/prioritized_packet_queue.cc).

The spec says to increment the delay counter at the same time as we
increment the packet counter in order for the app to be able to do
"delta totalPacketSendDelay / delta packetSent". For this reason,
`total_packet_delay` is added to RtpPacketCounter. (Previously, the
two counters were incremented on different threads and observers.)

Running Google Meet on a good network, I could observe a 2-3 ms average
send delay per packet with this implementation compared to 20-30 ms
with the old implementation. See b/137014977#comment170 for comparison
with googBucketDelay which is a little bit different by design -
totalPacketSendDelay is clearly better than googBucketDelay.

Since none of this depend on the media kind, we can wire up this metric
for audio as well in a follow-up:
https://webrtc-review.googlesource.com/c/src/+/280523

Bug: webrtc:14593
Change-Id: If8fcd82fee74030d0923ee5df2c2aea2264600d4
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/280443
Reviewed-by: Erik Språng <[email protected]>
Commit-Queue: Henrik Boström <[email protected]>
Cr-Commit-Position: refs/heads/main@{#38480}

Author: henbos

call/video_send_stream.h

@@ -77,9 +77,10 @@ class VideoSendStream {
     // TODO(holmer): Move bitrate_bps out to the webrtc::Call layer.
     int total_bitrate_bps = 0;
     int retransmit_bitrate_bps = 0;
+    // `avg_delay_ms` and `max_delay_ms` are only used in tests. Consider
+    // deleting.
     int avg_delay_ms = 0;
     int max_delay_ms = 0;
-    uint64_t total_packet_send_delay_ms = 0;
     StreamDataCounters rtp_stats;
     RtcpPacketTypeCounter rtcp_packet_type_counts;
     // A snapshot of the most recent Report Block with additional data of

media/base/media_channel.h

@@ -595,7 +595,8 @@ struct VideoSenderInfo : public MediaSenderInfo {
   uint64_t total_encode_time_ms = 0;
   // https://w3c.github.io/webrtc-stats/#dom-rtcoutboundrtpstreamstats-totalencodedbytestarget
   uint64_t total_encoded_bytes_target = 0;
-  uint64_t total_packet_send_delay_ms = 0;
+  // https://w3c.github.io/webrtc-stats/#dom-rtcoutboundrtpstreamstats-totalpacketsenddelay
+  webrtc::TimeDelta total_packet_send_delay = webrtc::TimeDelta::Zero();
   bool has_entered_low_resolution = false;
   absl::optional<uint64_t> qp_sum;
   webrtc::VideoContentType content_type = webrtc::VideoContentType::UNSPECIFIED;

media/engine/webrtc_video_engine.cc

@@ -2674,7 +2674,8 @@ WebRtcVideoChannel::WebRtcVideoSendStream::GetPerLayerVideoSenderInfos(
         stream_stats.rtp_stats.transmitted.header_bytes +
         stream_stats.rtp_stats.transmitted.padding_bytes;
     info.packets_sent = stream_stats.rtp_stats.transmitted.packets;
-    info.total_packet_send_delay_ms += stream_stats.total_packet_send_delay_ms;
+    info.total_packet_send_delay +=
+        stream_stats.rtp_stats.transmitted.total_packet_delay;
     info.send_frame_width = stream_stats.width;
     info.send_frame_height = stream_stats.height;
     info.key_frames_encoded = stream_stats.frame_counts.key_frames;
@@ -2728,7 +2729,7 @@ WebRtcVideoChannel::WebRtcVideoSendStream::GetAggregatedVideoSenderInfo(
     info.header_and_padding_bytes_sent +=
         infos[i].header_and_padding_bytes_sent;
     info.packets_sent += infos[i].packets_sent;
-    info.total_packet_send_delay_ms += infos[i].total_packet_send_delay_ms;
+    info.total_packet_send_delay += infos[i].total_packet_send_delay;
     info.retransmitted_bytes_sent += infos[i].retransmitted_bytes_sent;
     info.retransmitted_packets_sent += infos[i].retransmitted_packets_sent;
     info.packets_lost += infos[i].packets_lost;

media/engine/webrtc_video_engine_unittest.cc

@@ -5567,7 +5567,7 @@ TEST_F(WebRtcVideoChannelTest, GetAggregatedStatsReportWithoutSubStreams) {
   EXPECT_EQ(sender.total_encoded_bytes_target,
             stats.total_encoded_bytes_target);
   // Comes from substream only.
-  EXPECT_EQ(sender.total_packet_send_delay_ms, 0u);
+  EXPECT_EQ(sender.total_packet_send_delay, webrtc::TimeDelta::Zero());
   EXPECT_EQ(sender.qp_sum, absl::nullopt);
 
   EXPECT_EQ(sender.has_entered_low_resolution,
@@ -5594,7 +5594,8 @@ TEST_F(WebRtcVideoChannelTest, GetAggregatedStatsReportForSubStreams) {
   substream.retransmit_bitrate_bps = 6;
   substream.avg_delay_ms = 7;
   substream.max_delay_ms = 8;
-  substream.total_packet_send_delay_ms = 9;
+  substream.rtp_stats.transmitted.total_packet_delay =
+      webrtc::TimeDelta::Millis(9);
   substream.rtp_stats.transmitted.header_bytes = 10;
   substream.rtp_stats.transmitted.padding_bytes = 11;
   substream.rtp_stats.retransmitted.payload_bytes = 12;
@@ -5640,6 +5641,8 @@ TEST_F(WebRtcVideoChannelTest, GetAggregatedStatsReportForSubStreams) {
             static_cast<int>(2 * substream.rtp_stats.transmitted.packets));
   EXPECT_EQ(sender.retransmitted_packets_sent,
             2u * substream.rtp_stats.retransmitted.packets);
+  EXPECT_EQ(sender.total_packet_send_delay,
+            2 * substream.rtp_stats.transmitted.total_packet_delay);
   EXPECT_EQ(sender.packets_lost,
             2 * substream.report_block_data->report_block().packets_lost);
   EXPECT_EQ(sender.fraction_lost,
@@ -5689,8 +5692,6 @@ TEST_F(WebRtcVideoChannelTest, GetAggregatedStatsReportForSubStreams) {
   EXPECT_EQ(sender.total_encode_time_ms, 2u * substream.total_encode_time_ms);
   EXPECT_EQ(sender.total_encoded_bytes_target,
             2u * substream.total_encoded_bytes_target);
-  EXPECT_EQ(sender.total_packet_send_delay_ms,
-            2u * substream.total_packet_send_delay_ms);
   EXPECT_EQ(sender.has_entered_low_resolution,
             stats.has_entered_low_resolution);
   EXPECT_EQ(sender.qp_sum, 2u * *substream.qp_sum);
@@ -5716,7 +5717,8 @@ TEST_F(WebRtcVideoChannelTest, GetPerLayerStatsReportForSubStreams) {
   substream.retransmit_bitrate_bps = 6;
   substream.avg_delay_ms = 7;
   substream.max_delay_ms = 8;
-  substream.total_packet_send_delay_ms = 9;
+  substream.rtp_stats.transmitted.total_packet_delay =
+      webrtc::TimeDelta::Millis(9);
   substream.rtp_stats.transmitted.header_bytes = 10;
   substream.rtp_stats.transmitted.padding_bytes = 11;
   substream.rtp_stats.retransmitted.payload_bytes = 12;
@@ -5760,6 +5762,8 @@ TEST_F(WebRtcVideoChannelTest, GetPerLayerStatsReportForSubStreams) {
             substream.rtp_stats.retransmitted.payload_bytes);
   EXPECT_EQ(sender.packets_sent,
             static_cast<int>(substream.rtp_stats.transmitted.packets));
+  EXPECT_EQ(sender.total_packet_send_delay,
+            substream.rtp_stats.transmitted.total_packet_delay);
   EXPECT_EQ(sender.retransmitted_packets_sent,
             substream.rtp_stats.retransmitted.packets);
   EXPECT_EQ(sender.packets_lost,
@@ -5810,8 +5814,6 @@ TEST_F(WebRtcVideoChannelTest, GetPerLayerStatsReportForSubStreams) {
   EXPECT_EQ(sender.total_encode_time_ms, substream.total_encode_time_ms);
   EXPECT_EQ(sender.total_encoded_bytes_target,
             substream.total_encoded_bytes_target);
-  EXPECT_EQ(sender.total_packet_send_delay_ms,
-            substream.total_packet_send_delay_ms);
   EXPECT_EQ(sender.has_entered_low_resolution,
             stats.has_entered_low_resolution);
   EXPECT_EQ(sender.qp_sum, *substream.qp_sum);

modules/pacing/prioritized_packet_queue.cc

@@ -180,6 +180,13 @@ std::unique_ptr<RtpPacketToSend> PrioritizedPacketQueue::Pop() {
       last_update_time_ - packet.enqueue_time - pause_time_sum_;
   queue_time_sum_ -= time_in_non_paused_state;
 
+  // Set the time spent in the send queue, which is the per-packet equivalent of
+  // totalPacketSendDelay. The notion of being paused is an implementation
+  // detail that we do not want to expose, so it makes sense to report the
+  // metric excluding the pause time. This also avoids spikes in the metric.
+  // https://w3c.github.io/webrtc-stats/#dom-rtcoutboundrtpstreamstats-totalpacketsenddelay
+  packet.packet->set_time_in_send_queue(time_in_non_paused_state);
+
   RTC_DCHECK(size_packets_ > 0 || queue_time_sum_ == TimeDelta::Zero());
 
   RTC_CHECK(packet.enqueue_time_iterator != enqueue_times_.end());

modules/rtp_rtcp/include/rtp_rtcp_defines.cc

@@ -17,6 +17,7 @@
 #include "absl/algorithm/container.h"
 #include "api/array_view.h"
 #include "modules/rtp_rtcp/source/rtp_packet.h"
+#include "modules/rtp_rtcp/source/rtp_packet_to_send.h"
 
 namespace webrtc {
 
@@ -52,11 +53,23 @@ RtpPacketCounter::RtpPacketCounter(const RtpPacket& packet)
       padding_bytes(packet.padding_size()),
       packets(1) {}
 
+RtpPacketCounter::RtpPacketCounter(const RtpPacketToSend& packet_to_send)
+    : RtpPacketCounter(static_cast<const RtpPacket&>(packet_to_send)) {
+  total_packet_delay =
+      packet_to_send.time_in_send_queue().value_or(TimeDelta::Zero());
+}
+
 void RtpPacketCounter::AddPacket(const RtpPacket& packet) {
   ++packets;
   header_bytes += packet.headers_size();
   padding_bytes += packet.padding_size();
   payload_bytes += packet.payload_size();
 }
 
+void RtpPacketCounter::AddPacket(const RtpPacketToSend& packet_to_send) {
+  AddPacket(static_cast<const RtpPacket&>(packet_to_send));
+  total_packet_delay +=
+      packet_to_send.time_in_send_queue().value_or(TimeDelta::Zero());
+}
+
 }  // namespace webrtc

modules/rtp_rtcp/include/rtp_rtcp_defines.h

@@ -312,12 +312,14 @@ struct RtpPacketCounter {
       : header_bytes(0), payload_bytes(0), padding_bytes(0), packets(0) {}
 
   explicit RtpPacketCounter(const RtpPacket& packet);
+  explicit RtpPacketCounter(const RtpPacketToSend& packet_to_send);
 
   void Add(const RtpPacketCounter& other) {
     header_bytes += other.header_bytes;
     payload_bytes += other.payload_bytes;
     padding_bytes += other.padding_bytes;
     packets += other.packets;
+    total_packet_delay += other.total_packet_delay;
   }
 
   void Subtract(const RtpPacketCounter& other) {
@@ -329,16 +331,20 @@ struct RtpPacketCounter {
     padding_bytes -= other.padding_bytes;
     RTC_DCHECK_GE(packets, other.packets);
     packets -= other.packets;
+    RTC_DCHECK_GE(total_packet_delay, other.total_packet_delay);
+    total_packet_delay -= other.total_packet_delay;
   }
 
   bool operator==(const RtpPacketCounter& other) const {
     return header_bytes == other.header_bytes &&
            payload_bytes == other.payload_bytes &&
-           padding_bytes == other.padding_bytes && packets == other.packets;
+           padding_bytes == other.padding_bytes && packets == other.packets &&
+           total_packet_delay == other.total_packet_delay;
   }
 
   // Not inlined, since use of RtpPacket would result in circular includes.
   void AddPacket(const RtpPacket& packet);
+  void AddPacket(const RtpPacketToSend& packet_to_send);
 
   size_t TotalBytes() const {
     return header_bytes + payload_bytes + padding_bytes;
@@ -348,6 +354,9 @@ struct RtpPacketCounter {
   size_t payload_bytes;  // Payload bytes, excluding RTP headers and padding.
   size_t padding_bytes;  // Number of padding bytes.
   uint32_t packets;      // Number of packets.
+  // The total delay of all `packets`. For RtpPacketToSend packets, this is
+  // `time_in_send_queue()`. For receive packets, this is zero.
+  webrtc::TimeDelta total_packet_delay = webrtc::TimeDelta::Zero();
 };
 
 // Data usage statistics for a (rtp) stream.
@@ -470,7 +479,6 @@ class SendSideDelayObserver {
   virtual ~SendSideDelayObserver() {}
   virtual void SendSideDelayUpdated(int avg_delay_ms,
                                     int max_delay_ms,
-                                    uint64_t total_delay_ms,
                                     uint32_t ssrc) = 0;
 };
 

modules/rtp_rtcp/source/deprecated/deprecated_rtp_sender_egress.cc

@@ -90,7 +90,6 @@ DEPRECATED_RtpSenderEgress::DEPRECATED_RtpSenderEgress(
       timestamp_offset_(0),
       max_delay_it_(send_delays_.end()),
       sum_delays_ms_(0),
-      total_packet_send_delay_ms_(0),
       send_rates_(kNumMediaTypes,
                   {kBitrateStatisticsWindowMs, RateStatistics::kBpsScale}),
       rtp_sequence_number_map_(need_rtp_packet_infos_
@@ -341,7 +340,6 @@ void DEPRECATED_RtpSenderEgress::UpdateDelayStatistics(int64_t capture_time_ms,
 
   int avg_delay_ms = 0;
   int max_delay_ms = 0;
-  uint64_t total_packet_send_delay_ms = 0;
   {
     MutexLock lock(&lock_);
     // Compute the max and average of the recent capture-to-send delays.
@@ -392,8 +390,6 @@ void DEPRECATED_RtpSenderEgress::UpdateDelayStatistics(int64_t capture_time_ms,
       max_delay_it_ = it;
     }
     sum_delays_ms_ += new_send_delay;
-    total_packet_send_delay_ms_ += new_send_delay;
-    total_packet_send_delay_ms = total_packet_send_delay_ms_;
 
     size_t num_delays = send_delays_.size();
     RTC_DCHECK(max_delay_it_ != send_delays_.end());
@@ -405,8 +401,8 @@ void DEPRECATED_RtpSenderEgress::UpdateDelayStatistics(int64_t capture_time_ms,
     avg_delay_ms =
         rtc::dchecked_cast<int>((sum_delays_ms_ + num_delays / 2) / num_delays);
   }
-  send_side_delay_observer_->SendSideDelayUpdated(
-      avg_delay_ms, max_delay_ms, total_packet_send_delay_ms, ssrc);
+  send_side_delay_observer_->SendSideDelayUpdated(avg_delay_ms, max_delay_ms,
+                                                  ssrc);
 }
 
 void DEPRECATED_RtpSenderEgress::RecomputeMaxSendDelay() {

modules/rtp_rtcp/source/deprecated/deprecated_rtp_sender_egress.h

@@ -133,7 +133,6 @@ class DEPRECATED_RtpSenderEgress {
   SendDelayMap::const_iterator max_delay_it_ RTC_GUARDED_BY(lock_);
   // The sum of delays over a kSendSideDelayWindowMs sliding window.
   int64_t sum_delays_ms_ RTC_GUARDED_BY(lock_);
-  uint64_t total_packet_send_delay_ms_ RTC_GUARDED_BY(lock_);
   StreamDataCounters rtp_stats_ RTC_GUARDED_BY(lock_);
   StreamDataCounters rtx_rtp_stats_ RTC_GUARDED_BY(lock_);
   // One element per value in RtpPacketMediaType, with index matching value.

modules/rtp_rtcp/source/rtp_packet_to_send.h

@@ -19,6 +19,7 @@
 #include "api/array_view.h"
 #include "api/ref_counted_base.h"
 #include "api/scoped_refptr.h"
+#include "api/units/time_delta.h"
 #include "api/units/timestamp.h"
 #include "api/video/video_timing.h"
 #include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
@@ -120,6 +121,15 @@ class RtpPacketToSend : public RtpPacket {
   void set_is_red(bool is_red) { is_red_ = is_red; }
   bool is_red() const { return is_red_; }
 
+  // The amount of time spent in the send queue, used for totalPacketSendDelay.
+  // https://w3c.github.io/webrtc-stats/#dom-rtcoutboundrtpstreamstats-totalpacketsenddelay
+  void set_time_in_send_queue(TimeDelta time_in_send_queue) {
+    time_in_send_queue_ = time_in_send_queue;
+  }
+  absl::optional<TimeDelta> time_in_send_queue() const {
+    return time_in_send_queue_;
+  }
+
  private:
   webrtc::Timestamp capture_time_ = webrtc::Timestamp::Zero();
   absl::optional<RtpPacketMediaType> packet_type_;
@@ -130,6 +140,7 @@ class RtpPacketToSend : public RtpPacket {
   bool is_key_frame_ = false;
   bool fec_protect_packet_ = false;
   bool is_red_ = false;
+  absl::optional<TimeDelta> time_in_send_queue_;
 };
 
 }  // namespace webrtc