Replace first_packet_sent_ms_ in Call.

Instead of using the time on the first callback to Call::OnSentPacket, use the time when the first packet is sent from the pacer (to make sure this packet corresponds to an audio/video RTP packet).

BUG=webrtc:6244

Review-Url: https://codereview.webrtc.org/2825333002
Cr-Commit-Position: refs/heads/master@{#17777}

webrtc/call/call.cc

@@ -216,7 +216,8 @@ class Call : public webrtc::Call,
                                                   const PacketTime& packet_time)
       SHARED_LOCKS_REQUIRED(receive_crit_);
 
-  void UpdateSendHistograms() EXCLUSIVE_LOCKS_REQUIRED(&bitrate_crit_);
+  void UpdateSendHistograms(int64_t first_sent_packet_ms)
+      EXCLUSIVE_LOCKS_REQUIRED(&bitrate_crit_);
   void UpdateReceiveHistograms();
   void UpdateHistograms();
   void UpdateAggregateNetworkState();
@@ -290,7 +291,6 @@ class Call : public webrtc::Call,
   // The following members are only accessed (exclusively) from one thread and
   // from the destructor, and therefore doesn't need any explicit
   // synchronization.
-  int64_t first_packet_sent_ms_;
   RateCounter received_bytes_per_second_counter_;
   RateCounter received_audio_bytes_per_second_counter_;
   RateCounter received_video_bytes_per_second_counter_;
@@ -355,7 +355,6 @@ Call::Call(const Call::Config& config,
       receive_crit_(RWLockWrapper::CreateRWLock()),
       send_crit_(RWLockWrapper::CreateRWLock()),
       event_log_(config.event_log),
-      first_packet_sent_ms_(-1),
       received_bytes_per_second_counter_(clock_, nullptr, true),
       received_audio_bytes_per_second_counter_(clock_, nullptr, true),
       received_video_bytes_per_second_counter_(clock_, nullptr, true),
@@ -422,11 +421,13 @@ Call::~Call() {
   call_stats_->DeregisterStatsObserver(&receive_side_cc_);
   call_stats_->DeregisterStatsObserver(transport_send_->send_side_cc());
 
+  int64_t first_sent_packet_ms =
+      transport_send_->send_side_cc()->GetFirstPacketTimeMs();
   // Only update histograms after process threads have been shut down, so that
   // they won't try to concurrently update stats.
   {
     rtc::CritScope lock(&bitrate_crit_);
-    UpdateSendHistograms();
+    UpdateSendHistograms(first_sent_packet_ms);
   }
   UpdateReceiveHistograms();
   UpdateHistograms();
@@ -463,11 +464,11 @@ void Call::UpdateHistograms() {
       (clock_->TimeInMilliseconds() - start_ms_) / 1000);
 }
 
-void Call::UpdateSendHistograms() {
-  if (first_packet_sent_ms_ == -1)
+void Call::UpdateSendHistograms(int64_t first_sent_packet_ms) {
+  if (first_sent_packet_ms == -1)
     return;
   int64_t elapsed_sec =
-      (clock_->TimeInMilliseconds() - first_packet_sent_ms_) / 1000;
+      (clock_->TimeInMilliseconds() - first_sent_packet_ms) / 1000;
   if (elapsed_sec < metrics::kMinRunTimeInSeconds)
     return;
   const int kMinRequiredPeriodicSamples = 5;
@@ -1047,8 +1048,6 @@ void Call::UpdateAggregateNetworkState() {
 }
 
 void Call::OnSentPacket(const rtc::SentPacket& sent_packet) {
-  if (first_packet_sent_ms_ == -1)
-    first_packet_sent_ms_ = clock_->TimeInMilliseconds();
   video_send_delay_stats_->OnSentPacket(sent_packet.packet_id,
                                         clock_->TimeInMilliseconds());
   transport_send_->send_side_cc()->OnSentPacket(sent_packet);

webrtc/modules/congestion_controller/include/send_side_congestion_controller.h

@@ -88,6 +88,7 @@ class SendSideCongestionController : public CallStatsObserver,
 
   virtual BitrateController* GetBitrateController() const;
   virtual int64_t GetPacerQueuingDelayMs() const;
+  virtual int64_t GetFirstPacketTimeMs() const;
   // TODO(nisse): Delete this accessor function. The pacer should be
   // internal to the congestion controller.
   virtual PacedSender* pacer() { return pacer_.get(); }

webrtc/modules/congestion_controller/send_side_congestion_controller.cc

@@ -177,6 +177,10 @@ int64_t SendSideCongestionController::GetPacerQueuingDelayMs() const {
   return IsNetworkDown() ? 0 : pacer_->QueueInMs();
 }
 
+int64_t SendSideCongestionController::GetFirstPacketTimeMs() const {
+  return pacer_->FirstSentPacketTimeMs();
+}
+
 void SendSideCongestionController::SignalNetworkState(NetworkState state) {
   LOG(LS_INFO) << "SignalNetworkState "
                << (state == kNetworkUp ? "Up" : "Down");

webrtc/modules/pacing/paced_sender.cc

@@ -262,6 +262,7 @@ PacedSender::PacedSender(const Clock* clock,
       max_padding_bitrate_kbps_(0u),
       pacing_bitrate_kbps_(0),
       time_last_update_us_(clock->TimeInMicroseconds()),
+      first_sent_packet_ms_(-1),
       packets_(new paced_sender::PacketQueue(clock)),
       packet_counter_(0) {
   UpdateBudgetWithElapsedTime(kMinPacketLimitMs);
@@ -368,6 +369,11 @@ size_t PacedSender::QueueSizePackets() const {
   return packets_->SizeInPackets();
 }
 
+int64_t PacedSender::FirstSentPacketTimeMs() const {
+  rtc::CritScope cs(&critsect_);
+  return first_sent_packet_ms_;
+}
+
 int64_t PacedSender::QueueInMs() const {
   rtc::CritScope cs(&critsect_);
 
@@ -442,6 +448,8 @@ void PacedSender::Process() {
 
     if (SendPacket(packet, pacing_info)) {
       // Send succeeded, remove it from the queue.
+      if (first_sent_packet_ms_ == -1)
+        first_sent_packet_ms_ = clock_->TimeInMilliseconds();
       bytes_sent += packet.bytes;
       packets_->FinalizePop(packet);
       if (is_probing && bytes_sent > recommended_probe_size)

webrtc/modules/pacing/paced_sender.h

@@ -119,6 +119,10 @@ class PacedSender : public Module, public RtpPacketSender {
 
   virtual size_t QueueSizePackets() const;
 
+  // Returns the time when the first packet was sent, or -1 if no packet is
+  // sent.
+  virtual int64_t FirstSentPacketTimeMs() const;
+
   // Returns the number of milliseconds it will take to send the current
   // packets in the queue, given the current size and bitrate, ignoring prio.
   virtual int64_t ExpectedQueueTimeMs() const;
@@ -184,6 +188,7 @@ class PacedSender : public Module, public RtpPacketSender {
   uint32_t pacing_bitrate_kbps_ GUARDED_BY(critsect_);
 
   int64_t time_last_update_us_ GUARDED_BY(critsect_);
+  int64_t first_sent_packet_ms_ GUARDED_BY(critsect_);
 
   std::unique_ptr<paced_sender::PacketQueue> packets_ GUARDED_BY(critsect_);
   uint64_t packet_counter_;

webrtc/modules/pacing/paced_sender_unittest.cc

@@ -136,6 +136,25 @@ class PacedSenderTest : public ::testing::Test {
   std::unique_ptr<PacedSender> send_bucket_;
 };
 
+TEST_F(PacedSenderTest, FirstSentPacketTimeIsSet) {
+  uint16_t sequence_number = 1234;
+  const uint32_t kSsrc = 12345;
+  const size_t kSizeBytes = 250;
+  const size_t kPacketToSend = 3;
+  const int64_t kStartMs = clock_.TimeInMilliseconds();
+
+  // No packet sent.
+  EXPECT_EQ(-1, send_bucket_->FirstSentPacketTimeMs());
+
+  for (size_t i = 0; i < kPacketToSend; ++i) {
+    SendAndExpectPacket(PacedSender::kNormalPriority, kSsrc, sequence_number++,
+                        clock_.TimeInMilliseconds(), kSizeBytes, false);
+    send_bucket_->Process();
+    clock_.AdvanceTimeMilliseconds(send_bucket_->TimeUntilNextProcess());
+  }
+  EXPECT_EQ(kStartMs, send_bucket_->FirstSentPacketTimeMs());
+}
+
 TEST_F(PacedSenderTest, QueuePacket) {
   uint32_t ssrc = 12345;
   uint16_t sequence_number = 1234;