Added log messages for some important call setup events:

- First audio RTP packet sent / received
 - First RTP packet of the first video frame sent / received
 - Last RTP packet of the first video frame sent / received
These timestamps should make it easier to measure how fast the call
becomes established from the user's perspective.

Review URL: https://codereview.webrtc.org/1765443002

Cr-Commit-Position: refs/heads/master@{#12287}

webrtc/base/BUILD.gn

@@ -133,6 +133,7 @@ static_library("rtc_base_approved") {
     "md5digest.cc",
     "md5digest.h",
     "mod_ops.h",
+    "onetimeevent.h",
     "optional.h",
     "platform_file.cc",
     "platform_file.h",

webrtc/base/base.gyp

@@ -105,6 +105,7 @@
         'md5digest.cc',
         'md5digest.h',
         'mod_ops.h',
+        'onetimeevent.h',
         'optional.h',
         'platform_file.cc',
         'platform_file.h',

webrtc/base/base_tests.gyp

@@ -79,6 +79,7 @@
           'multipart_unittest.cc',
           'nat_unittest.cc',
           'network_unittest.cc',
+          'onetimeevent_unittest.cc',
           'optional_unittest.cc',
           'optionsfile_unittest.cc',
           'pathutils_unittest.cc',

webrtc/base/onetimeevent.h

@@ -0,0 +1,62 @@
+/*
+ *  Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#ifndef WEBRTC_BASE_ONETIMEEVENT_H_
+#define WEBRTC_BASE_ONETIMEEVENT_H_
+
+#include "webrtc/base/scoped_ptr.h"
+#include "webrtc/base/criticalsection.h"
+#include "webrtc/typedefs.h"
+
+namespace webrtc {
+// Provides a simple way to perform an operation (such as logging) one
+// time in a certain scope.
+// Example:
+//   OneTimeEvent firstFrame;
+//   ...
+//   if (firstFrame()) {
+//     LOG(LS_INFO) << "This is the first frame".
+//   }
+class OneTimeEvent {
+ public:
+  OneTimeEvent() {}
+  bool operator()() {
+    rtc::CritScope cs(&critsect_);
+    if (happened_) {
+      return false;
+    }
+    happened_ = true;
+    return true;
+  }
+
+ private:
+  bool happened_ = false;
+  rtc::CriticalSection critsect_;
+};
+
+// A non-thread-safe, ligher-weight version of the OneTimeEvent class.
+class ThreadUnsafeOneTimeEvent {
+ public:
+  ThreadUnsafeOneTimeEvent() {}
+  bool operator()() {
+    if (happened_) {
+      return false;
+    }
+    happened_ = true;
+    return true;
+  }
+
+ private:
+  bool happened_ = false;
+};
+
+}  // namespace webrtc
+
+#endif  // WEBRTC_BASE_ONETIMEEVENT_H_

webrtc/base/onetimeevent_unittest.cc

@@ -0,0 +1,33 @@
+/*
+ *  Copyright 2016 The WebRTC Project Authors. All rights reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#include "webrtc/base/gunit.h"
+#include "webrtc/base/onetimeevent.h"
+
+namespace webrtc {
+
+TEST(OneTimeEventTest, ThreadSafe) {
+  OneTimeEvent ot;
+
+  // The one time event is expected to evaluate to true only the first time.
+  EXPECT_TRUE(ot());
+  EXPECT_FALSE(ot());
+  EXPECT_FALSE(ot());
+}
+
+TEST(OneTimeEventTest, ThreadUnsafe) {
+  ThreadUnsafeOneTimeEvent ot;
+
+  EXPECT_TRUE(ot());
+  EXPECT_FALSE(ot());
+  EXPECT_FALSE(ot());
+}
+
+}  // namespace webrtc

webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc

@@ -194,6 +194,10 @@ int32_t RTPReceiverAudio::ParseRtpPacket(WebRtcRTPHeader* rtp_header,
            rtp_header->type.Audio.numEnergy);
   }
 
+  if (first_packet_received_()) {
+    LOG(LS_INFO) << "Received first audio RTP packet";
+  }
+
   return ParseAudioCodecSpecific(rtp_header,
                                  payload,
                                  payload_length,

webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h

@@ -13,6 +13,7 @@
 
 #include <set>
 
+#include "webrtc/base/onetimeevent.h"
 #include "webrtc/base/scoped_ptr.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_receiver.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
@@ -118,6 +119,8 @@ class RTPReceiverAudio : public RTPReceiverStrategy,
 
   uint8_t num_energy_;
   uint8_t current_remote_energy_[kRtpCsrcSize];
+
+  ThreadUnsafeOneTimeEvent first_packet_received_;
 };
 }  // namespace webrtc
 

webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc

@@ -70,6 +70,10 @@ int32_t RTPReceiverVideo::ParseRtpPacket(WebRtcRTPHeader* rtp_header,
                                                                            : -1;
   }
 
+  if (first_packet_received_()) {
+    LOG(LS_INFO) << "Received first video RTP packet";
+  }
+
   // We are not allowed to hold a critical section when calling below functions.
   rtc::scoped_ptr<RtpDepacketizer> depacketizer(
       RtpDepacketizer::Create(rtp_header->type.Video.codec));

webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h

@@ -11,6 +11,7 @@
 #ifndef WEBRTC_MODULES_RTP_RTCP_SOURCE_RTP_RECEIVER_VIDEO_H_
 #define WEBRTC_MODULES_RTP_RTCP_SOURCE_RTP_RECEIVER_VIDEO_H_
 
+#include "webrtc/base/onetimeevent.h"
 #include "webrtc/base/scoped_ptr.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
 #include "webrtc/modules/rtp_rtcp/source/bitrate.h"
@@ -54,6 +55,9 @@ class RTPReceiverVideo : public RTPReceiverStrategy {
       const PayloadUnion& specific_payload) const override;
 
   void SetPacketOverHead(uint16_t packet_over_head);
+
+ private:
+  OneTimeEvent first_packet_received_;
 };
 }  // namespace webrtc
 

webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc

@@ -12,6 +12,7 @@
 
 #include <string.h>
 
+#include "webrtc/base/logging.h"
 #include "webrtc/base/trace_event.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
 #include "webrtc/modules/rtp_rtcp/source/byte_io.h"
@@ -333,6 +334,7 @@ int32_t RTPSenderAudio::SendAudio(FrameType frameType,
       memcpy(dataBuffer + rtpHeaderLength, payloadData, payloadSize);
     }
   }
+
   {
     CriticalSectionScoped cs(_sendAudioCritsect.get());
     _lastPayloadType = payloadType;
@@ -348,10 +350,14 @@ int32_t RTPSenderAudio::SendAudio(FrameType frameType,
   TRACE_EVENT_ASYNC_END2("webrtc", "Audio", captureTimeStamp, "timestamp",
                          _rtpSender->Timestamp(), "seqnum",
                          _rtpSender->SequenceNumber());
-  return _rtpSender->SendToNetwork(dataBuffer, payloadSize, rtpHeaderLength,
-                                   TickTime::MillisecondTimestamp(),
-                                   kAllowRetransmission,
-                                   RtpPacketSender::kHighPriority);
+  int32_t send_result = _rtpSender->SendToNetwork(
+      dataBuffer, payloadSize, rtpHeaderLength,
+      TickTime::MillisecondTimestamp(), kAllowRetransmission,
+      RtpPacketSender::kHighPriority);
+  if (first_packet_sent_()) {
+    LOG(LS_INFO) << "First audio RTP packet sent to pacer";
+  }
+  return send_result;
 }
 
 // Audio level magnitude and voice activity flag are set for each RTP packet

webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h

@@ -12,6 +12,7 @@
 #define WEBRTC_MODULES_RTP_RTCP_SOURCE_RTP_SENDER_AUDIO_H_
 
 #include "webrtc/common_types.h"
+#include "webrtc/base/onetimeevent.h"
 #include "webrtc/modules/rtp_rtcp/source/dtmf_queue.h"
 #include "webrtc/modules/rtp_rtcp/source/rtp_rtcp_config.h"
 #include "webrtc/modules/rtp_rtcp/source/rtp_sender.h"
@@ -100,6 +101,7 @@ class RTPSenderAudio : public DTMFqueue {
   // Audio level indication
   // (https://datatracker.ietf.org/doc/draft-lennox-avt-rtp-audio-level-exthdr/)
   uint8_t _audioLevel_dBov GUARDED_BY(_sendAudioCritsect);
+  OneTimeEvent first_packet_sent_;
 };
 }  // namespace webrtc
 

webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc

@@ -232,6 +232,7 @@ int32_t RTPSenderVideo::SendVideo(const RtpVideoCodecTypes videoType,
 
   StorageType storage;
   bool fec_enabled;
+  bool first_frame = first_frame_sent_();
   {
     CriticalSectionScoped cs(crit_.get());
     FecProtectionParams* fec_params =
@@ -260,6 +261,7 @@ int32_t RTPSenderVideo::SendVideo(const RtpVideoCodecTypes videoType,
 
   packetizer->SetPayloadData(data, payload_bytes_to_send, frag);
 
+  bool first = true;
   bool last = false;
   while (!last) {
     uint8_t dataBuffer[IP_PACKET_SIZE] = {0};
@@ -268,6 +270,7 @@ int32_t RTPSenderVideo::SendVideo(const RtpVideoCodecTypes videoType,
                                 &payload_bytes_in_packet, &last)) {
       return -1;
     }
+
     // Write RTP header.
     // Set marker bit true if this is the last packet in frame.
     _rtpSender.BuildRTPheader(
@@ -309,6 +312,18 @@ int32_t RTPSenderVideo::SendVideo(const RtpVideoCodecTypes videoType,
                       _rtpSender.SequenceNumber(), captureTimeStamp,
                       capture_time_ms, storage);
     }
+
+    if (first_frame) {
+      if (first) {
+        LOG(LS_INFO)
+            << "Sent first RTP packet of the first video frame (pre-pacer)";
+      }
+      if (last) {
+        LOG(LS_INFO)
+            << "Sent last RTP packet of the first video frame (pre-pacer)";
+      }
+    }
+    first = false;
   }
 
   TRACE_EVENT_ASYNC_END1(

webrtc/modules/rtp_rtcp/source/rtp_sender_video.h

@@ -13,6 +13,7 @@
 
 #include <list>
 
+#include "webrtc/base/onetimeevent.h"
 #include "webrtc/base/scoped_ptr.h"
 #include "webrtc/base/thread_annotations.h"
 #include "webrtc/common_types.h"
@@ -116,6 +117,7 @@ class RTPSenderVideo {
   Bitrate _fecOverheadRate;
   // Bitrate used for video payload and RTP headers
   Bitrate _videoBitrate;
+  OneTimeEvent first_frame_sent_;
 };
 }  // namespace webrtc
 

webrtc/modules/video_coding/jitter_buffer.cc

@@ -1282,9 +1282,13 @@ void VCMJitterBuffer::CountFrame(const VCMFrameBuffer& frame) {
   if (frame.IsSessionComplete()) {
     if (frame.FrameType() == kVideoFrameKey) {
       ++receive_statistics_.key_frames;
+      if (receive_statistics_.key_frames == 1) {
+        LOG(LS_INFO) << "Received first complete key frame";
+      }
     } else {
       ++receive_statistics_.delta_frames;
     }
+
     if (stats_callback_ != NULL)
       stats_callback_->OnFrameCountsUpdated(receive_statistics_);
   }

webrtc/modules/video_coding/video_coding_impl.h

@@ -16,6 +16,7 @@
 #include <memory>
 #include <vector>
 
+#include "webrtc/base/onetimeevent.h"
 #include "webrtc/base/thread_annotations.h"
 #include "webrtc/base/thread_checker.h"
 #include "webrtc/modules/video_coding/codec_database.h"
@@ -219,6 +220,7 @@ class VideoReceiver {
   VCMProcessTimer _retransmissionTimer;
   VCMProcessTimer _keyRequestTimer;
   QpParser qp_parser_;
+  ThreadUnsafeOneTimeEvent first_frame_received_;
 };
 
 }  // namespace vcm

webrtc/modules/video_coding/video_receiver.cc

@@ -323,6 +323,13 @@ int32_t VideoReceiver::Decode(uint16_t maxWaitTimeMs) {
     }
   }
 #endif
+
+  if (first_frame_received_()) {
+    LOG(LS_INFO) << "Received first "
+                 << (frame->Complete() ? "complete" : "incomplete")
+                 << " decodable video frame";
+  }
+
   const int32_t ret = Decode(*frame);
   _receiver.ReleaseFrame(frame);
   return ret;