diff --git a/webrtc/modules/audio_coding/main/source/audio_coding_module_impl.cc b/webrtc/modules/audio_coding/main/source/audio_coding_module_impl.cc index 27cce93bca..f8e966d584 100644 --- a/webrtc/modules/audio_coding/main/source/audio_coding_module_impl.cc +++ b/webrtc/modules/audio_coding/main/source/audio_coding_module_impl.cc @@ -22,6 +22,7 @@ #include "webrtc/system_wrappers/interface/critical_section_wrapper.h" #include "webrtc/system_wrappers/interface/rw_lock_wrapper.h" #include "webrtc/system_wrappers/interface/trace.h" +#include "webrtc/system_wrappers/interface/trace_event.h" namespace webrtc { @@ -2231,6 +2232,8 @@ AudioPlayoutMode AudioCodingModuleImpl::PlayoutMode() const { // Automatic resample to the requested frequency. WebRtc_Word32 AudioCodingModuleImpl::PlayoutData10Ms( WebRtc_Word32 desired_freq_hz, AudioFrame* audio_frame) { + TRACE_EVENT0("webrtc_voe", "ACM::PlayoutData10Ms"); + bool stereo_mode; if (GetSilence(desired_freq_hz, audio_frame)) diff --git a/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc b/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc index 5d598e03ab..9fdb1ec8d4 100644 --- a/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc +++ b/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc @@ -18,11 +18,49 @@ #include "modules/rtp_rtcp/source/rtp_rtcp_impl.h" #include "system_wrappers/interface/critical_section_wrapper.h" #include "system_wrappers/interface/trace.h" +#include "system_wrappers/interface/trace_event.h" namespace webrtc { using RTCPUtility::RTCPCnameInformation; +NACKStringBuilder::NACKStringBuilder() : + _stream(""), _count(0), _consecutive(false) +{ + // Empty. +} + +void NACKStringBuilder::PushNACK(WebRtc_UWord16 nack) +{ + if (_count == 0) + { + _stream << nack; + } else if (nack == _prevNack + 1) + { + _consecutive = true; + } else + { + if (_consecutive) + { + _stream << "-" << _prevNack; + _consecutive = false; + } + _stream << "," << nack; + } + _count++; + _prevNack = nack; +} + +std::string NACKStringBuilder::GetResult() +{ + if (_consecutive) + { + _stream << "-" << _prevNack; + _consecutive = false; + } + return _stream.str(); +} + RTCPSender::RTCPSender(const WebRtc_Word32 id, const bool audio, Clock* clock, @@ -79,7 +117,10 @@ RTCPSender::RTCPSender(const WebRtc_Word32 id, _appData(NULL), _appLength(0), _xrSendVoIPMetric(false), - _xrVoIPMetric() + _xrVoIPMetric(), + _nackCount(0), + _pliCount(0), + _fullIntraRequestCount(0) { memset(_CNAME, 0, sizeof(_CNAME)); memset(_lastSendReport, 0, sizeof(_lastSendReport)); @@ -151,6 +192,11 @@ RTCPSender::Init() memset(_CNAME, 0, sizeof(_CNAME)); memset(_lastSendReport, 0, sizeof(_lastSendReport)); memset(_lastRTCPTime, 0, sizeof(_lastRTCPTime)); + + _nackCount = 0; + _pliCount = 0; + _fullIntraRequestCount = 0; + return 0; } @@ -1065,6 +1111,7 @@ RTCPSender::BuildREMB(WebRtc_UWord8* rtcpbuffer, WebRtc_UWord32& pos) ModuleRTPUtility::AssignUWord32ToBuffer(rtcpbuffer+pos, _rembSSRC[i]); pos += 4; } + TRACE_COUNTER1("webrtc_rtcp", "Remb", _rembBitrate); return 0; } @@ -1294,7 +1341,8 @@ WebRtc_Word32 RTCPSender::BuildNACK(WebRtc_UWord8* rtcpbuffer, WebRtc_UWord32& pos, const WebRtc_Word32 nackSize, - const WebRtc_UWord16* nackList) + const WebRtc_UWord16* nackList, + std::string* nackString) { // sanity if(pos + 16 >= IP_PACKET_SIZE) @@ -1324,12 +1372,14 @@ RTCPSender::BuildNACK(WebRtc_UWord8* rtcpbuffer, // add the list int i = 0; int numOfNackFields = 0; + NACKStringBuilder stringBuilder; while (nackSize > i && numOfNackFields < kRtcpMaxNackFields) { WebRtc_UWord16 nack = nackList[i]; // put dow our sequence number ModuleRTPUtility::AssignUWord16ToBuffer(rtcpbuffer+pos, nack); pos += 2; + stringBuilder.PushNACK(nack); i++; numOfNackFields++; @@ -1372,6 +1422,7 @@ RTCPSender::BuildNACK(WebRtc_UWord8* rtcpbuffer, assert(!(shift > 15) && !(shift < 0)); bitmask += (1<< shift); + stringBuilder.PushNACK(nackList[i]); i++; if(nackSize > i) { @@ -1403,6 +1454,7 @@ RTCPSender::BuildNACK(WebRtc_UWord8* rtcpbuffer, } } rtcpbuffer[nackSizePos]=(WebRtc_UWord8)(2+numOfNackFields); + *nackString = stringBuilder.GetResult(); return 0; } @@ -1784,6 +1836,9 @@ RTCPSender::SendRTCP(const WebRtc_UWord32 packetTypeFlags, { break; // out of buffer } + TRACE_EVENT_INSTANT1("webrtc_rtcp", "SendRTCP", "type", "pli"); + _pliCount++; + TRACE_COUNTER1("webrtc_rtcp", "PLI Count", _pliCount); } if(rtcpPacketTypeFlags & kRtcpFir) { @@ -1796,6 +1851,9 @@ RTCPSender::SendRTCP(const WebRtc_UWord32 packetTypeFlags, { break; // out of buffer } + TRACE_EVENT_INSTANT1("webrtc_rtcp", "SendRTCP", "type", "fir"); + _fullIntraRequestCount++; + TRACE_COUNTER1("webrtc_rtcp", "FIR Count", _fullIntraRequestCount); } if(rtcpPacketTypeFlags & kRtcpSli) { @@ -1837,6 +1895,8 @@ RTCPSender::SendRTCP(const WebRtc_UWord32 packetTypeFlags, { break; // out of buffer } + TRACE_EVENT_INSTANT2("webrtc_rtcp", "SendRTCP", "type", "remb", + "bitrate", _rembBitrate); } if(rtcpPacketTypeFlags & kRtcpBye) { @@ -1888,7 +1948,9 @@ RTCPSender::SendRTCP(const WebRtc_UWord32 packetTypeFlags, } if(rtcpPacketTypeFlags & kRtcpNack) { - buildVal = BuildNACK(rtcpbuffer, pos, nackSize, nackList); + std::string nackString; + buildVal = BuildNACK(rtcpbuffer, pos, nackSize, nackList, + &nackString); if(buildVal == -1) { return -1; // error @@ -1897,6 +1959,10 @@ RTCPSender::SendRTCP(const WebRtc_UWord32 packetTypeFlags, { break; // out of buffer } + TRACE_EVENT_INSTANT2("webrtc_rtcp", "SendRTCP", "type", "nack", + "list", TRACE_STR_COPY(nackString.c_str())); + _nackCount++; + TRACE_COUNTER1("webrtc_rtcp", "Nacks", _nackCount); } if(rtcpPacketTypeFlags & kRtcpXrVoipMetric) { diff --git a/webrtc/modules/rtp_rtcp/source/rtcp_sender.h b/webrtc/modules/rtp_rtcp/source/rtcp_sender.h index 2844975db3..5ca6a01829 100644 --- a/webrtc/modules/rtp_rtcp/source/rtcp_sender.h +++ b/webrtc/modules/rtp_rtcp/source/rtcp_sender.h @@ -12,6 +12,8 @@ #define WEBRTC_MODULES_RTP_RTCP_SOURCE_RTCP_SENDER_H_ #include +#include +#include #include "typedefs.h" #include "rtcp_utility.h" @@ -26,6 +28,20 @@ namespace webrtc { class ModuleRtpRtcpImpl; +class NACKStringBuilder +{ +public: + NACKStringBuilder(); + void PushNACK(WebRtc_UWord16 nack); + std::string GetResult(); + +private: + std::ostringstream _stream; + int _count; + WebRtc_UWord16 _prevNack; + bool _consecutive; +}; + class RTCPSender { public: @@ -181,7 +197,8 @@ private: WebRtc_Word32 BuildNACK(WebRtc_UWord8* rtcpbuffer, WebRtc_UWord32& pos, const WebRtc_Word32 nackSize, - const WebRtc_UWord16* nackList); + const WebRtc_UWord16* nackList, + std::string* nackString); private: WebRtc_Word32 _id; @@ -249,6 +266,11 @@ private: // XR VoIP metric bool _xrSendVoIPMetric; RTCPVoIPMetric _xrVoIPMetric; + + // Counters + WebRtc_UWord32 _nackCount; + WebRtc_UWord32 _pliCount; + WebRtc_UWord32 _fullIntraRequestCount; }; } // namespace webrtc diff --git a/webrtc/modules/rtp_rtcp/source/rtcp_sender_unittest.cc b/webrtc/modules/rtp_rtcp/source/rtcp_sender_unittest.cc index 6f8f2c6de4..23951303eb 100644 --- a/webrtc/modules/rtp_rtcp/source/rtcp_sender_unittest.cc +++ b/webrtc/modules/rtp_rtcp/source/rtcp_sender_unittest.cc @@ -26,6 +26,161 @@ namespace webrtc { +TEST(NACKStringBuilderTest, TestCase1) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(7); + builder.PushNACK(9); + builder.PushNACK(10); + builder.PushNACK(11); + builder.PushNACK(12); + builder.PushNACK(15); + builder.PushNACK(18); + builder.PushNACK(19); + EXPECT_EQ(std::string("5,7,9-12,15,18-19"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase2) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(6); + builder.PushNACK(7); + builder.PushNACK(9); + builder.PushNACK(10); + builder.PushNACK(11); + builder.PushNACK(12); + builder.PushNACK(15); + builder.PushNACK(18); + builder.PushNACK(19); + EXPECT_EQ(std::string("5-7,9-12,15,18-19"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase3) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(7); + builder.PushNACK(9); + builder.PushNACK(10); + builder.PushNACK(11); + builder.PushNACK(12); + builder.PushNACK(15); + builder.PushNACK(18); + builder.PushNACK(19); + builder.PushNACK(21); + EXPECT_EQ(std::string("5,7,9-12,15,18-19,21"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase4) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(7); + builder.PushNACK(8); + builder.PushNACK(9); + builder.PushNACK(10); + builder.PushNACK(11); + builder.PushNACK(12); + builder.PushNACK(15); + builder.PushNACK(18); + builder.PushNACK(19); + EXPECT_EQ(std::string("5,7-12,15,18-19"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase5) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(7); + builder.PushNACK(9); + builder.PushNACK(10); + builder.PushNACK(11); + builder.PushNACK(12); + builder.PushNACK(15); + builder.PushNACK(16); + builder.PushNACK(18); + builder.PushNACK(19); + EXPECT_EQ(std::string("5,7,9-12,15-16,18-19"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase6) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(7); + builder.PushNACK(9); + builder.PushNACK(10); + builder.PushNACK(11); + builder.PushNACK(12); + builder.PushNACK(15); + builder.PushNACK(16); + builder.PushNACK(17); + builder.PushNACK(18); + builder.PushNACK(19); + EXPECT_EQ(std::string("5,7,9-12,15-19"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase7) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(6); + builder.PushNACK(7); + builder.PushNACK(8); + builder.PushNACK(11); + builder.PushNACK(12); + builder.PushNACK(13); + builder.PushNACK(14); + builder.PushNACK(15); + EXPECT_EQ(std::string("5-8,11-15"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase8) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(7); + builder.PushNACK(9); + builder.PushNACK(11); + builder.PushNACK(15); + builder.PushNACK(17); + builder.PushNACK(19); + EXPECT_EQ(std::string("5,7,9,11,15,17,19"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase9) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(6); + builder.PushNACK(7); + builder.PushNACK(8); + builder.PushNACK(9); + builder.PushNACK(10); + builder.PushNACK(11); + builder.PushNACK(12); + EXPECT_EQ(std::string("5-12"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase10) { + NACKStringBuilder builder; + builder.PushNACK(5); + EXPECT_EQ(std::string("5"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase11) { + NACKStringBuilder builder; + EXPECT_EQ(std::string(""), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase12) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(6); + EXPECT_EQ(std::string("5-6"), builder.GetResult()); +} + +TEST(NACKStringBuilderTest, TestCase13) { + NACKStringBuilder builder; + builder.PushNACK(5); + builder.PushNACK(6); + builder.PushNACK(9); + EXPECT_EQ(std::string("5-6,9"), builder.GetResult()); +} + void CreateRtpPacket(const bool marker_bit, const WebRtc_UWord8 payload, const WebRtc_UWord16 seq_num, const WebRtc_UWord32 timestamp, const WebRtc_UWord32 ssrc, WebRtc_UWord8* array, diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc b/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc index 851eaeb0e9..eb34673f42 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc @@ -21,6 +21,7 @@ #include "webrtc/modules/rtp_rtcp/source/rtp_rtcp_impl.h" #include "webrtc/system_wrappers/interface/critical_section_wrapper.h" #include "webrtc/system_wrappers/interface/trace.h" +#include "webrtc/system_wrappers/interface/trace_event.h" namespace webrtc { @@ -1140,6 +1141,8 @@ void RTPReceiver::ProcessBitrate() { CriticalSectionScoped cs(critical_section_rtp_receiver_); Bitrate::Process(); + TRACE_COUNTER1("webrtc_rtp", "Received Bitrate", BitrateLast()); + TRACE_COUNTER1("webrtc_rtp", "Received Packet Rate", PacketRate()); } } // 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 1ae0a7dd3f..55894ebd03 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc @@ -17,6 +17,7 @@ #include "webrtc/system_wrappers/interface/critical_section_wrapper.h" #include "webrtc/system_wrappers/interface/trace.h" +#include "webrtc/system_wrappers/interface/trace_event.h" namespace webrtc { RTPReceiverAudio::RTPReceiverAudio(const WebRtc_Word32 id, @@ -190,6 +191,9 @@ WebRtc_Word32 RTPReceiverAudio::ParseRtpPacket( const WebRtc_UWord16 packet_length, const WebRtc_Word64 timestamp_ms, const bool is_first_packet) { + TRACE_EVENT_INSTANT2("webrtc_rtp", "RTPReceiverAudio::ParseRtpPacket", + "seqnum", rtp_header->header.sequenceNumber, + "timestamp", rtp_header->header.timestamp); const WebRtc_UWord8* payload_data = ModuleRTPUtility::GetPayloadData(rtp_header, packet); diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc b/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc index 1a0c1e7430..09180d8b79 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc @@ -22,6 +22,7 @@ #include "webrtc/modules/rtp_rtcp/source/rtp_utility.h" #include "webrtc/system_wrappers/interface/critical_section_wrapper.h" #include "webrtc/system_wrappers/interface/trace.h" +#include "webrtc/system_wrappers/interface/trace_event.h" namespace webrtc { WebRtc_UWord32 BitRateBPS(WebRtc_UWord16 x) { @@ -74,6 +75,9 @@ WebRtc_Word32 RTPReceiverVideo::ParseRtpPacket( const WebRtc_UWord16 packet_length, const WebRtc_Word64 timestamp_ms, const bool is_first_packet) { + TRACE_EVENT_INSTANT2("webrtc_rtp", "RTPReceiverVideo::ParseRtpPacket", + "seqnum", rtp_header->header.sequenceNumber, + "timestamp", rtp_header->header.timestamp); const WebRtc_UWord8* payload_data = ModuleRTPUtility::GetPayloadData(rtp_header, packet); const WebRtc_UWord16 payload_data_length = diff --git a/webrtc/modules/video_coding/main/source/generic_decoder.cc b/webrtc/modules/video_coding/main/source/generic_decoder.cc index fd90c684a5..7f7805438d 100644 --- a/webrtc/modules/video_coding/main/source/generic_decoder.cc +++ b/webrtc/modules/video_coding/main/source/generic_decoder.cc @@ -10,6 +10,7 @@ #include "video_coding.h" #include "trace.h" +#include "trace_event.h" #include "generic_decoder.h" #include "internal_defines.h" #include "webrtc/system_wrappers/interface/clock.h" @@ -63,6 +64,9 @@ int32_t VCMDecodedFrameCallback::Decoded(I420VideoFrame& decodedImage) _frame.SwapFrame(&decodedImage); _frame.set_render_time_ms(frameInfo->renderTimeMs); int32_t callbackReturn = _receiveCallback->FrameToRender(_frame); + TRACE_EVENT_INSTANT2("webrtc_vie", "VCMDecodedFrameCallback::Decoded", + "timestamp", decodedImage.timestamp(), + "render_time_ms", decodedImage.render_time_ms()); if (callbackReturn < 0) { WEBRTC_TRACE(webrtc::kTraceDebug, @@ -166,6 +170,9 @@ int32_t VCMGenericDecoder::Decode(const VCMEncodedFrame& frame, _nextFrameInfoIdx = (_nextFrameInfoIdx + 1) % kDecoderFrameMemoryLength; + TRACE_EVENT2("webrtc_vie", "VCMGenericDecoder::Decode", + "timestamp", frame.TimeStamp(), + "render_time_ms", frame.RenderTimeMs()); int32_t ret = _decoder.Decode(frame.EncodedImage(), frame.MissingFrame(), frame.FragmentationHeader(), diff --git a/webrtc/modules/video_coding/main/source/jitter_buffer.cc b/webrtc/modules/video_coding/main/source/jitter_buffer.cc index a1727257ef..53ff5400b9 100644 --- a/webrtc/modules/video_coding/main/source/jitter_buffer.cc +++ b/webrtc/modules/video_coding/main/source/jitter_buffer.cc @@ -24,6 +24,7 @@ #include "webrtc/system_wrappers/interface/event_wrapper.h" #include "webrtc/system_wrappers/interface/logging.h" #include "webrtc/system_wrappers/interface/trace.h" +#include "webrtc/system_wrappers/interface/trace_event.h" namespace webrtc { @@ -214,6 +215,7 @@ void VCMJitterBuffer::Stop() { running_ = false; last_decoded_state_.Reset(); frame_list_.clear(); + TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", "type", "Stop"); for (int i = 0; i < kMaxNumberOfFrames; i++) { if (frame_buffers_[i] != NULL) { static_cast(frame_buffers_[i])->SetState(kStateFree); @@ -238,6 +240,7 @@ void VCMJitterBuffer::Flush() { CriticalSectionScoped cs(crit_sect_); // Erase all frames from the sorted list and set their state to free. frame_list_.clear(); + TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", "type", "Flush"); for (int i = 0; i < max_number_of_frames_; i++) { ReleaseFrameIfNotDecoding(frame_buffers_[i]); } @@ -258,6 +261,7 @@ void VCMJitterBuffer::Flush() { WEBRTC_TRACE(webrtc::kTraceDebug, webrtc::kTraceVideoCoding, VCMId(vcm_id_, receiver_id_), "JB(0x%x): Jitter buffer: flush", this); + TRACE_EVENT_INSTANT0("webrtc_vie", "VCMJitterBuffer::Flush"); } // Get received key and delta frames @@ -336,6 +340,8 @@ void VCMJitterBuffer::IncomingRateStatistics(unsigned int* framerate, bitrate = 0; incoming_bit_rate_ = 0; } + TRACE_COUNTER1("webrtc_vie", "IncomingFrameRate", incoming_frame_rate_); + TRACE_COUNTER1("webrtc_vie", "IncomingBitRate", incoming_bit_rate_); } // Wait for the first packet in the next frame to arrive. @@ -488,6 +494,10 @@ VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding( VCMFrameBuffer* oldest_frame = *it; it = frame_list_.erase(it); + if (frame_list_.empty()) { + TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + "type", "GetCompleteFrameForDecoding"); + } // Update jitter estimate. const bool retransmitted = (oldest_frame->GetNackCount() > 0); @@ -512,6 +522,10 @@ VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding( crit_sect_->Leave(); + TRACE_EVENT_INSTANT2("webrtc_vie", + "VCMJitterBuffer::GetCompleteFrameForDecoding", + "timestamp", oldest_frame->TimeStamp(), + "render_time_ms", oldest_frame->RenderTimeMs()); return oldest_frame; } @@ -557,6 +571,10 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() { waiting_for_completion_.timestamp = oldest_frame->TimeStamp(); } frame_list_.erase(frame_list_.begin()); + if (frame_list_.empty()) { + TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + "type", "GetFrameForDecoding"); + } // Look for previous frame loss VerifyAndSetPreviousFrameLost(oldest_frame); @@ -579,6 +597,10 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() { last_decoded_state_.SetState(oldest_frame); DropPacketsFromNackList(last_decoded_state_.sequence_num()); + TRACE_EVENT_INSTANT2("webrtc_vie", + "VCMJitterBuffer::GetFrameForDecoding", + "timestamp", oldest_frame->TimeStamp(), + "render_time_ms", oldest_frame->RenderTimeMs()); return oldest_frame; } @@ -605,6 +627,10 @@ int VCMJitterBuffer::GetFrame(const VCMPacket& packet, if (packet.sizeBytes > 0) { num_discarded_packets_++; num_consecutive_old_packets_++; + TRACE_EVENT_INSTANT2("webrtc_vie", "OldPacketDropped", + "seqnum", packet.seqNum, + "timestamp", packet.timestamp); + TRACE_COUNTER1("webrtc_vie", "DroppedOldPackets", num_discarded_packets_); } // Update last decoded sequence number if the packet arrived late and // belongs to a frame with a timestamp equal to the last decoded @@ -999,6 +1025,10 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() { UpdateJitterEstimate(*oldest_frame, false); } it = frame_list_.erase(it); + if (frame_list_.empty()) { + TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + "type", "GetFrameForDecodingNACK"); + } // Look for previous frame loss. VerifyAndSetPreviousFrameLost(oldest_frame); @@ -1019,6 +1049,10 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() { last_decoded_state_.SetState(oldest_frame); DropPacketsFromNackList(last_decoded_state_.sequence_num()); + TRACE_EVENT_INSTANT2("webrtc_vie", + "VCMJitterBuffer::GetFrameForDecodingNACK", + "timestamp", oldest_frame->TimeStamp(), + "render_time_ms", oldest_frame->RenderTimeMs()); return oldest_frame; } @@ -1035,6 +1069,8 @@ VCMFrameBuffer* VCMJitterBuffer::GetEmptyFrame() { return NULL; } + TRACE_EVENT_INSTANT0("webrtc_vie", "VCMJitterBuffer::GetEmptyFrame"); + crit_sect_->Enter(); for (int i = 0; i < max_number_of_frames_; ++i) { @@ -1058,6 +1094,8 @@ VCMFrameBuffer* VCMJitterBuffer::GetEmptyFrame() { VCMId(vcm_id_, receiver_id_), "JB(0x%x) FB(0x%x): Jitter buffer increased to:%d frames", this, ptr_new_buffer, max_number_of_frames_); + TRACE_EVENT_INSTANT1("webrtc_vie", "JitterBufferIncreased", + "NewSize", max_number_of_frames_); return ptr_new_buffer; } crit_sect_->Leave(); @@ -1078,6 +1116,8 @@ bool VCMJitterBuffer::RecycleFramesUntilKeyFrame() { VCMId(vcm_id_, receiver_id_), "Jitter buffer drop count:%d, low_seq %d", drop_count_, (*it)->GetLowSeqNum()); + TRACE_EVENT_INSTANT0("webrtc_vie", + "VCMJitterBuffer::RecycleFramesUntilKeyFrame"); ReleaseFrameIfNotDecoding(*it); it = frame_list_.erase(it); if (it != frame_list_.end() && (*it)->FrameType() == kVideoFrameKey) { @@ -1087,6 +1127,10 @@ bool VCMJitterBuffer::RecycleFramesUntilKeyFrame() { return true; } } + if (frame_list_.empty()) { + TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + "type", "RecycleFramesUntilKeyFrame"); + } waiting_for_key_frame_ = true; last_decoded_state_.Reset(); // TODO(mikhal): No sync. missing_sequence_numbers_.clear(); @@ -1116,13 +1160,30 @@ VCMFrameBufferEnum VCMJitterBuffer::UpdateFrameState(VCMFrameBuffer* frame) { if (length != 0 && !frame->GetCountedFrame()) { // Ignore ACK frames. incoming_frame_count_++; + TRACE_EVENT_INSTANT1("webrtc_vie", "AddFrameToJitterBuffer", + "timestamp", frame->TimeStamp()); + if (frame->FrameType() == kVideoFrameKey) { + TRACE_EVENT_INSTANT1("webrtc_vie", "AddKeyFrameToJitterBuffer", + "timestamp", frame->TimeStamp()); + } frame->SetCountedFrame(true); + } else { + TRACE_EVENT_INSTANT1("webrtc_vie", + "AddRetransmittedFrameToJitterBuffer", + "timestamp", frame->TimeStamp()); + if (frame->FrameType() == kVideoFrameKey) { + TRACE_EVENT_INSTANT1("webrtc_vie", + "AddRetransmittedKeyFrameToJitterBuffer", + "timestamp", frame->TimeStamp()); + } } // Check if we should drop the frame. A complete frame can arrive too late. if (last_decoded_state_.IsOldFrame(frame)) { // Frame is older than the latest decoded frame, drop it. Will be // released by CleanUpOldFrames later. + TRACE_EVENT_INSTANT1("webrtc_vie", "DropLateFrame", + "timestamp", frame->TimeStamp()); frame->Reset(); frame->SetState(kStateEmpty); WEBRTC_TRACE(webrtc::kTraceDebug, webrtc::kTraceVideoCoding, @@ -1236,11 +1297,18 @@ void VCMJitterBuffer::CleanUpOldOrEmptyFrames() { } if (last_decoded_state_.IsOldFrame(oldest_frame)) { ReleaseFrameIfNotDecoding(frame_list_.front()); + TRACE_EVENT_INSTANT1("webrtc_vie", "OldFrameDropped", + "timestamp", oldest_frame->TimeStamp()); + TRACE_COUNTER1("webrtc_vie", "DroppedLateFrames", drop_count_); frame_list_.erase(frame_list_.begin()); } else { break; } } + if (frame_list_.empty()) { + TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + "type", "CleanUpOldOrEmptyFrames"); + } if (!last_decoded_state_.in_initial_state()) { DropPacketsFromNackList(last_decoded_state_.sequence_num()); } diff --git a/webrtc/video_engine/vie_sync_module.cc b/webrtc/video_engine/vie_sync_module.cc index e973898681..47e89c98d5 100644 --- a/webrtc/video_engine/vie_sync_module.cc +++ b/webrtc/video_engine/vie_sync_module.cc @@ -14,6 +14,7 @@ #include "modules/video_coding/main/interface/video_coding.h" #include "system_wrappers/interface/critical_section_wrapper.h" #include "system_wrappers/interface/trace.h" +#include "system_wrappers/interface/trace_event.h" #include "video_engine/stream_synchronization.h" #include "video_engine/vie_channel.h" #include "voice_engine/include/voe_video_sync.h" @@ -152,6 +153,10 @@ WebRtc_Word32 ViESyncModule::Process() { return 0; } + TRACE_COUNTER1("webrtc_sync", "CurrentVideoDelay", + total_video_delay_target_ms); + TRACE_COUNTER1("webrtc_sync", "CurrentAudioDelay", current_audio_delay_ms); + TRACE_COUNTER1("webrtc_sync", "RelativeDelay", relative_delay_ms); int extra_audio_delay_ms = 0; // Calculate the necessary extra audio delay and desired total video // delay to get the streams in sync. @@ -161,6 +166,10 @@ WebRtc_Word32 ViESyncModule::Process() { &total_video_delay_target_ms)) { return 0; } + + TRACE_COUNTER1("webrtc_sync", "ExtraAudioDelayTarget", extra_audio_delay_ms); + TRACE_COUNTER1("webrtc_sync", "TotalVideoDelayTarget", + total_video_delay_target_ms); if (voe_sync_interface_->SetMinimumPlayoutDelay( voe_channel_id_, extra_audio_delay_ms) == -1) { WEBRTC_TRACE(webrtc::kTraceDebug, webrtc::kTraceVideo, vie_channel_->Id(),