Add trace of enqueued and sent RTP packets

This is useful in debugging the latency from a packet
is enqueued until it's sent.

Bug: webrtc:11617
Change-Id: Ic2f194334a2e178de221df3a0838481035bb3505
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/176231
Reviewed-by: Erik Språng <sprang@webrtc.org>
Commit-Queue: Johannes Kron <kron@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31381}
diff --git a/modules/pacing/paced_sender.cc b/modules/pacing/paced_sender.cc
index 88effe4..a0e7676 100644
--- a/modules/pacing/paced_sender.cc
+++ b/modules/pacing/paced_sender.cc
@@ -22,6 +22,7 @@
 #include "rtc_base/location.h"
 #include "rtc_base/logging.h"
 #include "rtc_base/time_utils.h"
+#include "rtc_base/trace_event.h"
 #include "system_wrappers/include/clock.h"
 
 namespace webrtc {
@@ -114,8 +115,15 @@
 void PacedSender::EnqueuePackets(
     std::vector<std::unique_ptr<RtpPacketToSend>> packets) {
   {
+    TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("webrtc"),
+                 "PacedSender::EnqueuePackets");
     rtc::CritScope cs(&critsect_);
     for (auto& packet : packets) {
+      TRACE_EVENT2(TRACE_DISABLED_BY_DEFAULT("webrtc"),
+                   "PacedSender::EnqueuePackets::Loop", "sequence_number",
+                   packet->SequenceNumber(), "rtp_timestamp",
+                   packet->Timestamp());
+
       pacing_controller_.EnqueuePacket(std::move(packet));
     }
   }
diff --git a/modules/pacing/packet_router.cc b/modules/pacing/packet_router.cc
index e9e8d4b..02befc9 100644
--- a/modules/pacing/packet_router.cc
+++ b/modules/pacing/packet_router.cc
@@ -24,6 +24,7 @@
 #include "rtc_base/checks.h"
 #include "rtc_base/logging.h"
 #include "rtc_base/time_utils.h"
+#include "rtc_base/trace_event.h"
 
 namespace webrtc {
 namespace {
@@ -136,6 +137,10 @@
 
 void PacketRouter::SendPacket(std::unique_ptr<RtpPacketToSend> packet,
                               const PacedPacketInfo& cluster_info) {
+  TRACE_EVENT2(TRACE_DISABLED_BY_DEFAULT("webrtc"), "PacketRouter::SendPacket",
+               "sequence_number", packet->SequenceNumber(), "rtp_timestamp",
+               packet->Timestamp());
+
   rtc::CritScope cs(&modules_crit_);
   // With the new pacer code path, transport sequence numbers are only set here,
   // on the pacer thread. Therefore we don't need atomics/synchronization.
@@ -168,6 +173,9 @@
 
 std::vector<std::unique_ptr<RtpPacketToSend>> PacketRouter::GeneratePadding(
     DataSize size) {
+  TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("webrtc"),
+               "PacketRouter::GeneratePadding", "bytes", size.bytes());
+
   rtc::CritScope cs(&modules_crit_);
   // First try on the last rtp module to have sent media. This increases the
   // the chance that any payload based padding will be useful as it will be
@@ -179,22 +187,28 @@
   if (last_send_module_ != nullptr &&
       last_send_module_->SupportsRtxPayloadPadding()) {
     padding_packets = last_send_module_->GeneratePadding(size.bytes());
-    if (!padding_packets.empty()) {
-      return padding_packets;
+  }
+
+  if (padding_packets.empty()) {
+    // Iterate over all modules send module. Video modules will be at the front
+    // and so will be prioritized. This is important since audio packets may not
+    // be taken into account by the bandwidth estimator, e.g. in FF.
+    for (RtpRtcp* rtp_module : send_modules_list_) {
+      if (rtp_module->SupportsPadding()) {
+        padding_packets = rtp_module->GeneratePadding(size.bytes());
+        if (!padding_packets.empty()) {
+          last_send_module_ = rtp_module;
+          break;
+        }
+      }
     }
   }
 
-  // Iterate over all modules send module. Video modules will be at the front
-  // and so will be prioritized. This is important since audio packets may not
-  // be taken into account by the bandwidth estimator, e.g. in FF.
-  for (RtpRtcp* rtp_module : send_modules_list_) {
-    if (rtp_module->SupportsPadding()) {
-      padding_packets = rtp_module->GeneratePadding(size.bytes());
-      if (!padding_packets.empty()) {
-        last_send_module_ = rtp_module;
-        break;
-      }
-    }
+  for (auto& packet : padding_packets) {
+    TRACE_EVENT2(TRACE_DISABLED_BY_DEFAULT("webrtc"),
+                 "PacketRouter::GeneratePadding::Loop", "sequence_number",
+                 packet->SequenceNumber(), "rtp_timestamp",
+                 packet->Timestamp());
   }
 
   return padding_packets;
diff --git a/modules/pacing/task_queue_paced_sender.cc b/modules/pacing/task_queue_paced_sender.cc
index 41eebea..d058e03 100644
--- a/modules/pacing/task_queue_paced_sender.cc
+++ b/modules/pacing/task_queue_paced_sender.cc
@@ -17,6 +17,7 @@
 #include "rtc_base/event.h"
 #include "rtc_base/logging.h"
 #include "rtc_base/task_utils/to_queued_task.h"
+#include "rtc_base/trace_event.h"
 
 namespace webrtc {
 namespace {
@@ -121,6 +122,15 @@
 
 void TaskQueuePacedSender::EnqueuePackets(
     std::vector<std::unique_ptr<RtpPacketToSend>> packets) {
+  TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("webrtc"),
+               "TaskQueuePacedSender::EnqueuePackets");
+  for (auto& packet : packets) {
+    TRACE_EVENT2(TRACE_DISABLED_BY_DEFAULT("webrtc"),
+                 "TaskQueuePacedSender::EnqueuePackets::Loop",
+                 "sequence_number", packet->SequenceNumber(), "rtp_timestamp",
+                 packet->Timestamp());
+  }
+
   task_queue_.PostTask([this, packets_ = std::move(packets)]() mutable {
     RTC_DCHECK_RUN_ON(&task_queue_);
     for (auto& packet : packets_) {