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}
diff --git a/webrtc/base/BUILD.gn b/webrtc/base/BUILD.gn
index bc6cb38..4c344fd 100644
--- a/webrtc/base/BUILD.gn
+++ b/webrtc/base/BUILD.gn
@@ -133,6 +133,7 @@
"md5digest.cc",
"md5digest.h",
"mod_ops.h",
+ "onetimeevent.h",
"optional.h",
"platform_file.cc",
"platform_file.h",
diff --git a/webrtc/base/base.gyp b/webrtc/base/base.gyp
index a5f0f7b..52f2ffe6 100644
--- a/webrtc/base/base.gyp
+++ b/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',
diff --git a/webrtc/base/base_tests.gyp b/webrtc/base/base_tests.gyp
index caef35c..ec38933 100644
--- a/webrtc/base/base_tests.gyp
+++ b/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',
diff --git a/webrtc/base/onetimeevent.h b/webrtc/base/onetimeevent.h
new file mode 100644
index 0000000..9708b4b
--- /dev/null
+++ b/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_
diff --git a/webrtc/base/onetimeevent_unittest.cc b/webrtc/base/onetimeevent_unittest.cc
new file mode 100644
index 0000000..4ebc139
--- /dev/null
+++ b/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
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc b/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc
index 7a3b6fd..9de65ab 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc
+++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc
@@ -194,6 +194,10 @@
rtp_header->type.Audio.numEnergy);
}
+ if (first_packet_received_()) {
+ LOG(LS_INFO) << "Received first audio RTP packet";
+ }
+
return ParseAudioCodecSpecific(rtp_header,
payload,
payload_length,
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h b/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h
index b68febb..f10613b 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h
+++ b/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 @@
uint8_t num_energy_;
uint8_t current_remote_energy_[kRtpCsrcSize];
+
+ ThreadUnsafeOneTimeEvent first_packet_received_;
};
} // namespace webrtc
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc b/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc
index 406acc2..72fb1b2 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc
+++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc
@@ -70,6 +70,10 @@
: -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));
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h b/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h
index 56f761a..7500232 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h
+++ b/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 @@
const PayloadUnion& specific_payload) const override;
void SetPacketOverHead(uint16_t packet_over_head);
+
+ private:
+ OneTimeEvent first_packet_received_;
};
} // namespace webrtc
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc b/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc
index 804294a..c85a197 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc
+++ b/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 @@
memcpy(dataBuffer + rtpHeaderLength, payloadData, payloadSize);
}
}
+
{
CriticalSectionScoped cs(_sendAudioCritsect.get());
_lastPayloadType = payloadType;
@@ -348,10 +350,14 @@
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
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h b/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h
index 25c5e4d..2ba10d2 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h
+++ b/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 @@
// 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
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc b/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc
index 32ba26f..87c975d 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc
+++ b/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc
@@ -232,6 +232,7 @@
StorageType storage;
bool fec_enabled;
+ bool first_frame = first_frame_sent_();
{
CriticalSectionScoped cs(crit_.get());
FecProtectionParams* fec_params =
@@ -260,6 +261,7 @@
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 @@
&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 @@
_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(
diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.h b/webrtc/modules/rtp_rtcp/source/rtp_sender_video.h
index dc1088a..3ea9168 100644
--- a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.h
+++ b/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 @@
Bitrate _fecOverheadRate;
// Bitrate used for video payload and RTP headers
Bitrate _videoBitrate;
+ OneTimeEvent first_frame_sent_;
};
} // namespace webrtc
diff --git a/webrtc/modules/video_coding/jitter_buffer.cc b/webrtc/modules/video_coding/jitter_buffer.cc
index f048b0a..4e012f6 100644
--- a/webrtc/modules/video_coding/jitter_buffer.cc
+++ b/webrtc/modules/video_coding/jitter_buffer.cc
@@ -1282,9 +1282,13 @@
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_);
}
diff --git a/webrtc/modules/video_coding/video_coding_impl.h b/webrtc/modules/video_coding/video_coding_impl.h
index f5f9b00..581eb4e 100644
--- a/webrtc/modules/video_coding/video_coding_impl.h
+++ b/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 @@
VCMProcessTimer _retransmissionTimer;
VCMProcessTimer _keyRequestTimer;
QpParser qp_parser_;
+ ThreadUnsafeOneTimeEvent first_frame_received_;
};
} // namespace vcm
diff --git a/webrtc/modules/video_coding/video_receiver.cc b/webrtc/modules/video_coding/video_receiver.cc
index 5aadcf9..136f7d7 100644
--- a/webrtc/modules/video_coding/video_receiver.cc
+++ b/webrtc/modules/video_coding/video_receiver.cc
@@ -323,6 +323,13 @@
}
}
#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;
