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 8f16bf3af5..54cc6273e2 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 @@ -1304,6 +1304,10 @@ int32_t AudioCodingModuleImpl::RegisterIncomingMessagesCallback( // Add 10MS of raw (PCM) audio data to the encoder. int32_t AudioCodingModuleImpl::Add10MsData( const AudioFrame& audio_frame) { + TRACE_EVENT2("webrtc", "ACM::Add10MsData", + "timestamp", audio_frame.timestamp_, + "samples_per_channel", audio_frame.samples_per_channel_); + if (audio_frame.samples_per_channel_ <= 0) { assert(false); WEBRTC_TRACE(webrtc::kTraceError, webrtc::kTraceAudioCoding, id_, @@ -2232,11 +2236,14 @@ AudioPlayoutMode AudioCodingModuleImpl::PlayoutMode() const { // Automatic resample to the requested frequency. int32_t AudioCodingModuleImpl::PlayoutData10Ms( int32_t desired_freq_hz, AudioFrame* audio_frame) { - TRACE_EVENT0("webrtc_voe", "ACM::PlayoutData10Ms"); + TRACE_EVENT_ASYNC_BEGIN0("webrtc", "ACM::PlayoutData10Ms", 0); bool stereo_mode; - if (GetSilence(desired_freq_hz, audio_frame)) + if (GetSilence(desired_freq_hz, audio_frame)) { + TRACE_EVENT_ASYNC_END1("webrtc", "ACM::PlayoutData10Ms", 0, + "silence", true); return 0; // Silence is generated, return. + } // RecOut always returns 10 ms. if (neteq_.RecOut(audio_frame_) != 0) { @@ -2264,6 +2271,8 @@ int32_t AudioCodingModuleImpl::PlayoutData10Ms( CriticalSectionScoped lock(acm_crit_sect_); if ((receive_freq != desired_freq_hz) && (desired_freq_hz != -1)) { + TRACE_EVENT_ASYNC_END2("webrtc", "ACM::PlayoutData10Ms", 0, + "stereo", stereo_mode, "resample", true); // Resample payload_data. int16_t temp_len = output_resampler_.Resample10Msec( audio_frame_.data_, receive_freq, audio_frame->data_, @@ -2280,6 +2289,8 @@ int32_t AudioCodingModuleImpl::PlayoutData10Ms( // Set the sampling frequency. audio_frame->sample_rate_hz_ = desired_freq_hz; } else { + TRACE_EVENT_ASYNC_END2("webrtc", "ACM::PlayoutData10Ms", 0, + "stereo", stereo_mode, "resample", false); memcpy(audio_frame->data_, audio_frame_.data_, audio_frame_.samples_per_channel_ * audio_frame->num_channels_ * sizeof(int16_t)); diff --git a/webrtc/modules/rtp_rtcp/source/rtcp_receiver.cc b/webrtc/modules/rtp_rtcp/source/rtcp_receiver.cc index d6bf0927f7..ebe61295ed 100644 --- a/webrtc/modules/rtp_rtcp/source/rtcp_receiver.cc +++ b/webrtc/modules/rtp_rtcp/source/rtcp_receiver.cc @@ -14,6 +14,7 @@ #include //assert #include "trace.h" +#include "trace_event.h" #include "critical_section_wrapper.h" #include "rtcp_utility.h" #include "rtp_rtcp_impl.h" @@ -397,8 +398,9 @@ RTCPReceiver::HandleSenderReceiverReport(RTCPUtility::RTCPParserV2& rtcpParser, if (rtcpPacketType == RTCPUtility::kRtcpSrCode) { - WEBRTC_TRACE(kTraceDebug, kTraceRtpRtcp, _id, - "Received SR(%d). SSRC:0x%x, from SSRC:0x%x, to us %d.", _id, _SSRC, remoteSSRC, (_remoteSSRC == remoteSSRC)?1:0); + TRACE_EVENT_INSTANT2("webrtc_rtp", "SR", + "remote_ssrc", remoteSSRC, + "ssrc", _SSRC); if (_remoteSSRC == remoteSSRC) // have I received RTP packets from this party { @@ -427,8 +429,9 @@ RTCPReceiver::HandleSenderReceiverReport(RTCPUtility::RTCPParserV2& rtcpParser, } } else { - WEBRTC_TRACE(kTraceDebug, kTraceRtpRtcp, _id, - "Received RR(%d). SSRC:0x%x, from SSRC:0x%x", _id, _SSRC, remoteSSRC); + TRACE_EVENT_INSTANT2("webrtc_rtp", "RR", + "remote_ssrc", remoteSSRC, + "ssrc", _SSRC); rtcpPacketInformation.rtcpPacketTypeFlags |= kRtcpRr; } @@ -481,6 +484,10 @@ RTCPReceiver::HandleReportBlock(const RTCPUtility::RTCPPacket& rtcpPacket, _lastReceivedRrMs = _clock->TimeInMilliseconds(); const RTCPPacketReportBlockItem& rb = rtcpPacket.ReportBlockItem; + TRACE_COUNTER_ID1("webrtc_rtp", "RRFractionLost", rb.SSRC, rb.FractionLost); + TRACE_COUNTER_ID1("webrtc_rtp", "RRCumulativeNumOfPacketLost", + rb.SSRC, rb.CumulativeNumOfPacketsLost); + TRACE_COUNTER_ID1("webrtc_rtp", "RRJitter", rb.SSRC, rb.Jitter); reportBlock->remoteReceiveBlock.remoteSSRC = remoteSSRC; reportBlock->remoteReceiveBlock.sourceSSRC = rb.SSRC; reportBlock->remoteReceiveBlock.fractionLost = rb.FractionLost; @@ -554,9 +561,7 @@ RTCPReceiver::HandleReportBlock(const RTCPUtility::RTCPPacket& rtcpPacket, reportBlock->numAverageCalcs++; } - WEBRTC_TRACE(kTraceDebug, kTraceRtpRtcp, _id, - " -> Received report block(%d), from SSRC:0x%x, RTT:%d, loss:%d", - _id, remoteSSRC, RTT, rtcpPacket.ReportBlockItem.FractionLost); + TRACE_COUNTER_ID1("webrtc_rtp", "RR_RTT", rb.SSRC, RTT); // rtcpPacketInformation rtcpPacketInformation.AddReportInfo( diff --git a/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc b/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc index ef97f85ac4..5dc571af88 100644 --- a/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc +++ b/webrtc/modules/rtp_rtcp/source/rtcp_sender.cc @@ -1117,7 +1117,7 @@ RTCPSender::BuildREMB(uint8_t* rtcpbuffer, uint32_t& pos) ModuleRTPUtility::AssignUWord32ToBuffer(rtcpbuffer+pos, _rembSSRC[i]); pos += 4; } - TRACE_COUNTER1("webrtc_rtcp", "Remb", _rembBitrate); + TRACE_COUNTER_ID1("webrtc_rtp", "RTCPRembBitrate", _SSRC, _rembBitrate); return 0; } @@ -1842,9 +1842,9 @@ RTCPSender::SendRTCP(const uint32_t packetTypeFlags, { break; // out of buffer } - TRACE_EVENT_INSTANT1("webrtc_rtcp", "SendRTCP", "type", "pli"); + TRACE_EVENT_INSTANT0("webrtc_rtp", "RTCPSender::PLI"); _pliCount++; - TRACE_COUNTER1("webrtc_rtcp", "PLI Count", _pliCount); + TRACE_COUNTER_ID1("webrtc_rtp", "RTCP_PLICount", _SSRC, _pliCount); } if(rtcpPacketTypeFlags & kRtcpFir) { @@ -1857,9 +1857,10 @@ RTCPSender::SendRTCP(const uint32_t packetTypeFlags, { break; // out of buffer } - TRACE_EVENT_INSTANT1("webrtc_rtcp", "SendRTCP", "type", "fir"); + TRACE_EVENT_INSTANT0("webrtc_rtp", "RTCPSender::FIR"); _fullIntraRequestCount++; - TRACE_COUNTER1("webrtc_rtcp", "FIR Count", _fullIntraRequestCount); + TRACE_COUNTER_ID1("webrtc_rtp", "RTCP_FIRCount", _SSRC, + _fullIntraRequestCount); } if(rtcpPacketTypeFlags & kRtcpSli) { @@ -1901,8 +1902,7 @@ RTCPSender::SendRTCP(const uint32_t packetTypeFlags, { break; // out of buffer } - TRACE_EVENT_INSTANT2("webrtc_rtcp", "SendRTCP", "type", "remb", - "bitrate", _rembBitrate); + TRACE_EVENT_INSTANT0("webrtc_rtp", "RTCPSender::REMB"); } if(rtcpPacketTypeFlags & kRtcpBye) { @@ -1965,10 +1965,10 @@ RTCPSender::SendRTCP(const uint32_t packetTypeFlags, { break; // out of buffer } - TRACE_EVENT_INSTANT2("webrtc_rtcp", "SendRTCP", "type", "nack", - "list", TRACE_STR_COPY(nackString.c_str())); + TRACE_EVENT_INSTANT1("webrtc_rtp", "RTCPSender::NACK", + "nacks", TRACE_STR_COPY(nackString.c_str())); _nackCount++; - TRACE_COUNTER1("webrtc_rtcp", "Nacks", _nackCount); + TRACE_COUNTER_ID1("webrtc_rtp", "RTCP_NACKCount", _SSRC, _nackCount); } if(rtcpPacketTypeFlags & kRtcpXrVoipMetric) { diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc b/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc index f18529c0ce..ba2bdba11d 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver.cc @@ -337,6 +337,7 @@ int32_t RTPReceiver::IncomingRTPPacket( WebRtcRTPHeader* rtp_header, const uint8_t* packet, const uint16_t packet_length) { + TRACE_EVENT0("webrtc_rtp", "RTPRecv::Packet"); // The rtp_header argument contains the parsed RTP header. int length = packet_length - rtp_header->header.paddingLength; @@ -1141,8 +1142,10 @@ 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()); + TRACE_COUNTER_ID1("webrtc_rtp", + "RTPReceiverBitrate", ssrc_, BitrateLast()); + TRACE_COUNTER_ID1("webrtc_rtp", + "RTPReceiverPacketRate", ssrc_, 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 ea921ccedf..857fa60280 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.cc @@ -191,10 +191,9 @@ int32_t RTPReceiverAudio::ParseRtpPacket( const uint16_t packet_length, const int64_t timestamp_ms, const bool is_first_packet) { - TRACE_EVENT_INSTANT2("webrtc_rtp", "RTPReceiverAudio::ParseRtpPacket", - "seqnum", rtp_header->header.sequenceNumber, - "timestamp", rtp_header->header.timestamp); - + TRACE_EVENT2("webrtc_rtp", "Audio::ParseRtp", + "seqnum", rtp_header->header.sequenceNumber, + "timestamp", rtp_header->header.timestamp); const uint8_t* payload_data = ModuleRTPUtility::GetPayloadData(rtp_header, packet); const uint16_t payload_data_length = diff --git a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc b/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc index ca6e05b972..bb361dc7ab 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_receiver_video.cc @@ -75,9 +75,9 @@ int32_t RTPReceiverVideo::ParseRtpPacket( const uint16_t packet_length, const int64_t timestamp_ms, const bool is_first_packet) { - TRACE_EVENT_INSTANT2("webrtc_rtp", "RTPReceiverVideo::ParseRtpPacket", - "seqnum", rtp_header->header.sequenceNumber, - "timestamp", rtp_header->header.timestamp); + TRACE_EVENT2("webrtc_rtp", "Video::ParseRtp", + "seqnum", rtp_header->header.sequenceNumber, + "timestamp", rtp_header->header.timestamp); const uint8_t* payload_data = ModuleRTPUtility::GetPayloadData(rtp_header, packet); const uint16_t payload_data_length = diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender.cc b/webrtc/modules/rtp_rtcp/source/rtp_sender.cc index 9c5cfe02ef..0e481c752f 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_sender.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_sender.cc @@ -18,9 +18,27 @@ #include "webrtc/modules/rtp_rtcp/source/rtp_sender_video.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 { +namespace { + +const char* FrameTypeToString(const FrameType frame_type) { + switch (frame_type) { + case kFrameEmpty: return "empty"; + case kAudioFrameSpeech: return "audio_speech"; + case kAudioFrameCN: return "audio_cn"; + case kVideoFrameKey: return "video_key"; + case kVideoFrameDelta: return "video_delta"; + case kVideoFrameGolden: return "video_golden"; + case kVideoFrameAltRef: return "video_altref"; + } + return ""; +} + +} // namespace + RTPSender::RTPSender(const int32_t id, const bool audio, Clock *clock, Transport *transport, RtpAudioFeedback *audio_feedback, PacedSender *paced_sender) @@ -305,6 +323,9 @@ int32_t RTPSender::SendOutgoingData( const uint8_t *payload_data, const uint32_t payload_size, const RTPFragmentationHeader *fragmentation, VideoCodecInformation *codec_info, const RTPVideoTypeHeader *rtp_type_hdr) { + TRACE_EVENT2("webrtc_rtp", "RTPSender::SendOutgoingData", + "timestsamp", capture_timestamp, + "frame_type", FrameTypeToString(frame_type)); { // Drop this packet if we're not sending media packets. CriticalSectionScoped cs(send_critsect_); @@ -448,6 +469,12 @@ int32_t RTPSender::ReSendPacket(uint16_t packet_id, uint32_t min_resend_time) { } int32_t bytes_sent = ReSendToNetwork(buffer_to_send_ptr, length); + ModuleRTPUtility::RTPHeaderParser rtp_parser(data_buffer, length); + WebRtcRTPHeader rtp_header; + rtp_parser.Parse(rtp_header); + TRACE_EVENT_INSTANT2("webrtc_rtp", "RTPSender::ReSendPacket", + "timestamp", rtp_header.header.timestamp, + "seqnum", rtp_header.header.sequenceNumber); if (bytes_sent <= 0) { WEBRTC_TRACE(kTraceWarning, kTraceRtpRtcp, id_, "Transport failed to resend packet_id %u", packet_id); @@ -490,6 +517,8 @@ int RTPSender::SetSelectiveRetransmissions(uint8_t settings) { void RTPSender::OnReceivedNACK( const std::list& nack_sequence_numbers, const uint16_t avg_rtt) { + TRACE_EVENT2("webrtc_rtp", "RTPSender::OnReceivedNACK", + "num_seqnum", nack_sequence_numbers.size(), "avg_rtt", avg_rtt); const int64_t now = clock_->TimeInMilliseconds(); uint32_t bytes_re_sent = 0; @@ -608,6 +637,9 @@ void RTPSender::TimeToSendPacket(uint16_t sequence_number, ModuleRTPUtility::RTPHeaderParser rtp_parser(data_buffer, length); WebRtcRTPHeader rtp_header; rtp_parser.Parse(rtp_header); + TRACE_EVENT_INSTANT2("webrtc_rtp", "RTPSender::TimeToSendPacket", + "timestamp", rtp_header.header.timestamp, + "seqnum", sequence_number); int64_t diff_ms = clock_->TimeInMilliseconds() - capture_time_ms; if (UpdateTransmissionTimeOffset(data_buffer, length, rtp_header, diff_ms)) { diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc b/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc index 8589874885..6e9c93147f 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc @@ -13,6 +13,8 @@ #include //memcpy #include //assert +#include "trace_event.h" + namespace webrtc { RTPSenderAudio::RTPSenderAudio(const int32_t id, Clock* clock, RTPSenderInterface* rtpSender) : @@ -471,6 +473,9 @@ int32_t RTPSenderAudio::SendAudio( } _lastPayloadType = payloadType; } // end critical section + TRACE_EVENT_INSTANT2("webrtc_rtp", "Audio::Send", + "timestamp", captureTimeStamp, + "seqnum", _rtpSender->SequenceNumber()); return _rtpSender->SendToNetwork(dataBuffer, payloadSize, static_cast(rtpHeaderLength), @@ -609,6 +614,10 @@ RTPSenderAudio::SendTelephoneEventPacket(const bool ended, ModuleRTPUtility::AssignUWord16ToBuffer(dtmfbuffer+14, duration); _sendAudioCritsect->Leave(); + TRACE_EVENT_INSTANT2("webrtc_rtp", + "Audio::SendTelephoneEvent", + "timestamp", dtmfTimeStamp, + "seqnum", _rtpSender->SequenceNumber()); retVal = _rtpSender->SendToNetwork(dtmfbuffer, 4, 12, -1, kAllowRetransmission); sendCount--; diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc b/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc index 034b3df344..817dd65944 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc +++ b/webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc @@ -12,6 +12,7 @@ #include "critical_section_wrapper.h" #include "trace.h" +#include "trace_event.h" #include "rtp_utility.h" @@ -111,6 +112,7 @@ int32_t RTPSenderVideo::SendVideoPacket(uint8_t* data_buffer, const uint16_t payload_length, const uint16_t rtp_header_length, + const uint32_t capture_timestamp, int64_t capture_time_ms, StorageType storage, bool protect) { @@ -123,6 +125,9 @@ RTPSenderVideo::SendVideoPacket(uint8_t* data_buffer, payload_length, rtp_header_length, _payloadTypeRED); + TRACE_EVENT_INSTANT2("webrtc_rtp", "Video::PacketRed", + "timestamp", capture_timestamp, + "seqnum", _rtpSender.SequenceNumber()); // Sending the media packet with RED header. int packet_success = _rtpSender.SendToNetwork( red_packet->data(), @@ -157,6 +162,9 @@ RTPSenderVideo::SendVideoPacket(uint8_t* data_buffer, if (_retransmissionSettings & kRetransmitFECPackets) { storage = kAllowRetransmission; } + TRACE_EVENT_INSTANT2("webrtc_rtp", "Video::PacketFec", + "timestamp", capture_timestamp, + "seqnum", _rtpSender.SequenceNumber()); // Sending FEC packet with RED header. int packet_success = _rtpSender.SendToNetwork( red_packet->data(), @@ -177,6 +185,9 @@ RTPSenderVideo::SendVideoPacket(uint8_t* data_buffer, _fecOverheadRate.Update(fec_overhead_sent); return ret; } + TRACE_EVENT_INSTANT2("webrtc_rtp", "Video::PacketNormal", + "timestamp", capture_timestamp, + "seqnum", _rtpSender.SequenceNumber()); int ret = _rtpSender.SendToNetwork(data_buffer, payload_length, rtp_header_length, @@ -203,6 +214,9 @@ RTPSenderVideo::SendRTPIntraRequest() ModuleRTPUtility::AssignUWord32ToBuffer(data+4, _rtpSender.SSRC()); + TRACE_EVENT_INSTANT1("webrtc_rtp", + "Video::IntraRequest", + "seqnum", _rtpSender.SequenceNumber()); return _rtpSender.SendToNetwork(data, 0, length, -1, kDontStore); } @@ -361,7 +375,8 @@ int32_t RTPSenderVideo::SendGeneric(const FrameType frame_type, payload += payload_length; if (SendVideoPacket(buffer, payload_length + 1, rtp_header_length, - capture_time_ms, kAllowRetransmission, true)) { + capture_timestamp, capture_time_ms, + kAllowRetransmission, true)) { return -1; } } @@ -450,7 +465,8 @@ RTPSenderVideo::SendVP8(const FrameType frameType, _rtpSender.BuildRTPheader(dataBuffer, payloadType, last, captureTimeStamp); if (-1 == SendVideoPacket(dataBuffer, payloadBytesInPacket, - rtpHeaderLength, capture_time_ms, storage, protect)) + rtpHeaderLength, captureTimeStamp, + capture_time_ms, storage, protect)) { WEBRTC_TRACE(kTraceError, kTraceRtpRtcp, _id, "RTPSenderVideo::SendVP8 failed to send packet number" @@ -463,6 +479,12 @@ RTPSenderVideo::SendVP8(const FrameType frameType, void RTPSenderVideo::ProcessBitrate() { _videoBitrate.Process(); _fecOverheadRate.Process(); + TRACE_COUNTER_ID1("webrtc_rtp", "VideoSendBitrate", + _rtpSender.SSRC(), + _videoBitrate.BitrateLast()); + TRACE_COUNTER_ID1("webrtc_rtp", "VideoFecOverheadRate", + _rtpSender.SSRC(), + _fecOverheadRate.BitrateLast()); } uint32_t RTPSenderVideo::VideoBitrateSent() const { diff --git a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.h b/webrtc/modules/rtp_rtcp/source/rtp_sender_video.h index e1dc942c4d..ad15d1f8c6 100644 --- a/webrtc/modules/rtp_rtcp/source/rtp_sender_video.h +++ b/webrtc/modules/rtp_rtcp/source/rtp_sender_video.h @@ -92,6 +92,7 @@ protected: virtual int32_t SendVideoPacket(uint8_t* dataBuffer, const uint16_t payloadLength, const uint16_t rtpHeaderLength, + const uint32_t capture_timestamp, int64_t capture_time_ms, StorageType storage, bool protect); diff --git a/webrtc/modules/video_capture/video_capture_impl.cc b/webrtc/modules/video_capture/video_capture_impl.cc index 49762376ba..eb2b4aad26 100644 --- a/webrtc/modules/video_capture/video_capture_impl.cc +++ b/webrtc/modules/video_capture/video_capture_impl.cc @@ -16,6 +16,7 @@ #include "ref_count.h" #include "tick_util.h" #include "trace.h" +#include "trace_event.h" #include "video_capture_config.h" #include @@ -199,6 +200,9 @@ WebRtc_Word32 VideoCaptureImpl::DeliverCapturedFrame(I420VideoFrame& captureFrame.set_render_time_ms(TickTime::MillisecondTimestamp()); } + TRACE_EVENT1("webrtc", "VC::DeliverCapturedFrame", + "capture_time", capture_time); + if (captureFrame.render_time_ms() == last_capture_time_) { // We don't allow the same capture time for two frames, drop this one. return -1; @@ -267,6 +271,8 @@ WebRtc_Word32 VideoCaptureImpl::IncomingFrame( const WebRtc_Word32 width = frameInfo.width; const WebRtc_Word32 height = frameInfo.height; + TRACE_EVENT1("webrtc", "VC::IncomingFrame", "capture_time", captureTime); + if (frameInfo.codecType == kVideoCodecUnknown) { // Not encoded, convert to I420. diff --git a/webrtc/modules/video_coding/codecs/vp8/vp8_impl.cc b/webrtc/modules/video_coding/codecs/vp8/vp8_impl.cc index 9a57e4c5a7..7516d4655a 100644 --- a/webrtc/modules/video_coding/codecs/vp8/vp8_impl.cc +++ b/webrtc/modules/video_coding/codecs/vp8/vp8_impl.cc @@ -331,6 +331,8 @@ uint32_t VP8EncoderImpl::MaxIntraTarget(uint32_t optimalBuffersize) { int VP8EncoderImpl::Encode(const I420VideoFrame& input_image, const CodecSpecificInfo* codec_specific_info, const std::vector* frame_types) { + TRACE_EVENT1("webrtc", "VP8::Encode", "timestamp", input_image.timestamp()); + if (!inited_) { return WEBRTC_VIDEO_CODEC_UNINITIALIZED; } @@ -390,9 +392,6 @@ int VP8EncoderImpl::Encode(const I420VideoFrame& input_image, input_image.timestamp()); } - TRACE_EVENT1("video_coding", "VP8EncoderImpl::Encode", - "input_image_timestamp", input_image.timestamp()); - // TODO(holmer): Ideally the duration should be the timestamp diff of this // frame and the next frame to be encoded, which we don't have. Instead we // would like to use the duration of the previous frame. Unfortunately the diff --git a/webrtc/modules/video_coding/main/source/generic_decoder.cc b/webrtc/modules/video_coding/main/source/generic_decoder.cc index 7f7805438d..1b74d229dc 100644 --- a/webrtc/modules/video_coding/main/source/generic_decoder.cc +++ b/webrtc/modules/video_coding/main/source/generic_decoder.cc @@ -64,9 +64,6 @@ 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, @@ -169,10 +166,6 @@ int32_t VCMGenericDecoder::Decode(const VCMEncodedFrame& frame, "Decoding timestamp %u", frame.TimeStamp()); _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/generic_encoder.cc b/webrtc/modules/video_coding/main/source/generic_encoder.cc index 6c1adfb7b6..fda3df2415 100644 --- a/webrtc/modules/video_coding/main/source/generic_encoder.cc +++ b/webrtc/modules/video_coding/main/source/generic_encoder.cc @@ -12,6 +12,7 @@ #include "generic_encoder.h" #include "media_optimization.h" #include "../../../../engine_configurations.h" +#include "trace_event.h" namespace webrtc { @@ -177,6 +178,8 @@ VCMEncodedFrameCallback::Encoded( const CodecSpecificInfo* codecSpecificInfo, const RTPFragmentationHeader* fragmentationHeader) { + TRACE_EVENT2("webrtc", "VCM::Encoded", "timestamp", encodedImage._timeStamp, + "length", encodedImage._length); FrameType frameType = VCMEncodedFrame::ConvertFrameType(encodedImage._frameType); uint32_t encodedBytes = 0; diff --git a/webrtc/modules/video_coding/main/source/jitter_buffer.cc b/webrtc/modules/video_coding/main/source/jitter_buffer.cc index c01afcc9b1..0953b71837 100644 --- a/webrtc/modules/video_coding/main/source/jitter_buffer.cc +++ b/webrtc/modules/video_coding/main/source/jitter_buffer.cc @@ -215,7 +215,7 @@ void VCMJitterBuffer::Stop() { running_ = false; last_decoded_state_.Reset(); frame_list_.clear(); - TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", "type", "Stop"); + TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied", "type", "Stop"); for (int i = 0; i < kMaxNumberOfFrames; i++) { if (frame_buffers_[i] != NULL) { static_cast(frame_buffers_[i])->SetState(kStateFree); @@ -240,7 +240,8 @@ 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"); + TRACE_EVENT_INSTANT2("webrtc", "JB::FrameListEmptied", "type", "Flush", + "frames", max_number_of_frames_); for (int i = 0; i < max_number_of_frames_; i++) { ReleaseFrameIfNotDecoding(frame_buffers_[i]); } @@ -261,7 +262,6 @@ 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 @@ -340,8 +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_); + TRACE_COUNTER1("webrtc", "JBIncomingFramerate", incoming_frame_rate_); + TRACE_COUNTER1("webrtc", "JBIncomingBitrate", incoming_bit_rate_); } // Wait for the first packet in the next frame to arrive. @@ -433,6 +433,7 @@ bool VCMJitterBuffer::CompleteSequenceWithNextFrame() { // complete frame, |max_wait_time_ms| decided by caller. VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding( uint32_t max_wait_time_ms) { + TRACE_EVENT0("webrtc", "JB::GetCompleteFrame"); if (!running_) { return NULL; } @@ -495,7 +496,7 @@ VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding( VCMFrameBuffer* oldest_frame = *it; it = frame_list_.erase(it); if (frame_list_.empty()) { - TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied", "type", "GetCompleteFrameForDecoding"); } @@ -521,15 +522,11 @@ VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding( DropPacketsFromNackList(last_decoded_state_.sequence_num()); crit_sect_->Leave(); - - TRACE_EVENT_INSTANT2("webrtc_vie", - "VCMJitterBuffer::GetCompleteFrameForDecoding", - "timestamp", oldest_frame->TimeStamp(), - "render_time_ms", oldest_frame->RenderTimeMs()); return oldest_frame; } VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() { + TRACE_EVENT0("webrtc", "JB::GetFrameForDecoding"); CriticalSectionScoped cs(crit_sect_); if (!running_) { return NULL; @@ -572,7 +569,7 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() { } frame_list_.erase(frame_list_.begin()); if (frame_list_.empty()) { - TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied", "type", "GetFrameForDecoding"); } @@ -596,11 +593,6 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() { // We have a frame - update decoded state with frame info. 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; } @@ -627,10 +619,10 @@ int VCMJitterBuffer::GetFrame(const VCMPacket& packet, if (packet.sizeBytes > 0) { num_discarded_packets_++; num_consecutive_old_packets_++; - TRACE_EVENT_INSTANT2("webrtc_vie", "OldPacketDropped", + TRACE_EVENT_INSTANT2("webrtc", "JB::OldPacketDropped", "seqnum", packet.seqNum, "timestamp", packet.timestamp); - TRACE_COUNTER1("webrtc_vie", "DroppedOldPackets", num_discarded_packets_); + TRACE_COUNTER1("webrtc", "JBDroppedOldPackets", 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 @@ -896,6 +888,8 @@ uint16_t* VCMJitterBuffer::GetNackList(uint16_t* nack_list_size, return NULL; } if (TooLargeNackList()) { + TRACE_EVENT_INSTANT1("webrtc", "JB::NackListTooLarge", + "size", missing_sequence_numbers_.size()); *request_key_frame = !HandleTooLargeNackList(); } unsigned int i = 0; @@ -925,6 +919,7 @@ bool VCMJitterBuffer::UpdateNackList(uint16_t sequence_number) { for (uint16_t i = latest_received_sequence_number_ + 1; i < sequence_number; ++i) { missing_sequence_numbers_.insert(missing_sequence_numbers_.end(), i); + TRACE_EVENT_INSTANT1("webrtc", "AddNack", "seqnum", i); } if (TooLargeNackList() && !HandleTooLargeNackList()) { return false; @@ -935,6 +930,7 @@ bool VCMJitterBuffer::UpdateNackList(uint16_t sequence_number) { } } else { missing_sequence_numbers_.erase(sequence_number); + TRACE_EVENT_INSTANT1("webrtc", "RemoveNack", "seqnum", sequence_number); } return true; } @@ -994,6 +990,7 @@ int64_t VCMJitterBuffer::LastDecodedTimestamp() const { } VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() { + TRACE_EVENT0("webrtc", "JB::GetFrameForDecodingNACK"); CleanUpOldOrEmptyFrames(); // First look for a complete continuous frame. // When waiting for nack, wait for a key frame, if a continuous frame cannot @@ -1023,7 +1020,7 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() { } it = frame_list_.erase(it); if (frame_list_.empty()) { - TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied", "type", "GetFrameForDecodingNACK"); } @@ -1045,11 +1042,6 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() { // We have a frame - update decoded state with frame info. 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; } @@ -1066,8 +1058,6 @@ 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) { @@ -1091,8 +1081,7 @@ 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_); + TRACE_COUNTER1("webrtc", "JBMaxFrames", max_number_of_frames_); return ptr_new_buffer; } crit_sect_->Leave(); @@ -1113,8 +1102,7 @@ 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"); + TRACE_EVENT_INSTANT0("webrtc", "JB::RecycleFramesUntilKeyFrame"); ReleaseFrameIfNotDecoding(*it); it = frame_list_.erase(it); if (it != frame_list_.end() && (*it)->FrameType() == kVideoFrameKey) { @@ -1125,7 +1113,7 @@ bool VCMJitterBuffer::RecycleFramesUntilKeyFrame() { } } if (frame_list_.empty()) { - TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied", "type", "RecycleFramesUntilKeyFrame"); } waiting_for_key_frame_ = true; @@ -1154,32 +1142,19 @@ VCMFrameBufferEnum VCMJitterBuffer::UpdateFrameState(VCMFrameBuffer* frame) { this, frame, length, frame->FrameType()); } + bool frame_counted = false; 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()); - } + frame_counted = true; } // 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", + TRACE_EVENT_INSTANT1("webrtc", "JB::DropLateFrame", "timestamp", frame->TimeStamp()); frame->Reset(); frame->SetState(kStateEmpty); @@ -1202,6 +1177,15 @@ VCMFrameBufferEnum VCMJitterBuffer::UpdateFrameState(VCMFrameBuffer* frame) { } num_consecutive_old_frames_ = 0; frame->SetState(kStateComplete); + if (frame->FrameType() == kVideoFrameKey) { + TRACE_EVENT_INSTANT2("webrtc", "JB::AddKeyFrame", + "timestamp", frame->TimeStamp(), + "retransmit", !frame_counted); + } else { + TRACE_EVENT_INSTANT2("webrtc", "JB::AddFrame", + "timestamp", frame->TimeStamp(), + "retransmit", !frame_counted); + } // Update receive statistics. We count all layers, thus when you use layers // adding all key and delta frames might differ from frame count. @@ -1294,16 +1278,16 @@ void VCMJitterBuffer::CleanUpOldOrEmptyFrames() { } if (last_decoded_state_.IsOldFrame(oldest_frame)) { ReleaseFrameIfNotDecoding(frame_list_.front()); - TRACE_EVENT_INSTANT1("webrtc_vie", "OldFrameDropped", + TRACE_EVENT_INSTANT1("webrtc", "JB::OldFrameDropped", "timestamp", oldest_frame->TimeStamp()); - TRACE_COUNTER1("webrtc_vie", "DroppedLateFrames", drop_count_); + TRACE_COUNTER1("webrtc", "JBDroppedLateFrames", drop_count_); frame_list_.erase(frame_list_.begin()); } else { break; } } if (frame_list_.empty()) { - TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", + TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied", "type", "CleanUpOldOrEmptyFrames"); } if (!last_decoded_state_.in_initial_state()) { diff --git a/webrtc/modules/video_coding/main/source/receiver.cc b/webrtc/modules/video_coding/main/source/receiver.cc index 9747244478..68696919db 100644 --- a/webrtc/modules/video_coding/main/source/receiver.cc +++ b/webrtc/modules/video_coding/main/source/receiver.cc @@ -18,6 +18,7 @@ #include "webrtc/modules/video_coding/main/source/media_opt_util.h" #include "webrtc/system_wrappers/interface/clock.h" #include "webrtc/system_wrappers/interface/trace.h" +#include "webrtc/system_wrappers/interface/trace_event.h" namespace webrtc { @@ -173,6 +174,7 @@ VCMEncodedFrame* VCMReceiver::FrameForDecoding( int64_t& next_render_time_ms, bool render_timing, VCMReceiver* dual_receiver) { + TRACE_EVENT0("webrtc", "Recv::FrameForDecoding"); // No need to enter the critical section here since the jitter buffer // is thread-safe. FrameType incoming_frame_type = kVideoFrameDelta; @@ -227,6 +229,8 @@ VCMEncodedFrame* VCMReceiver::FrameForDecoding( uint16_t max_wait_time_ms, int64_t next_render_time_ms, VCMReceiver* dual_receiver) { + TRACE_EVENT1("webrtc", "FrameForDecoding", + "max_wait", max_wait_time_ms); // How long can we wait until we must decode the next frame. uint32_t wait_time_ms = timing_->MaxWaitingTime( next_render_time_ms, clock_->TimeInMilliseconds()); @@ -286,6 +290,7 @@ VCMEncodedFrame* VCMReceiver::FrameForDecoding( VCMEncodedFrame* VCMReceiver::FrameForRendering(uint16_t max_wait_time_ms, int64_t next_render_time_ms, VCMReceiver* dual_receiver) { + TRACE_EVENT0("webrtc", "FrameForRendering"); // How long MUST we wait until we must decode the next frame. This is // different for the case where we have a renderer which can render at a // specified time. Here we must wait as long as possible before giving the diff --git a/webrtc/modules/video_coding/main/source/video_coding_impl.cc b/webrtc/modules/video_coding/main/source/video_coding_impl.cc index a418db8a12..1204fbc316 100644 --- a/webrtc/modules/video_coding/main/source/video_coding_impl.cc +++ b/webrtc/modules/video_coding/main/source/video_coding_impl.cc @@ -17,6 +17,7 @@ #include "trace.h" #include "video_codec_interface.h" #include "webrtc/system_wrappers/interface/clock.h" +#include "webrtc/system_wrappers/interface/trace_event.h" namespace webrtc { @@ -863,6 +864,7 @@ VideoCodingModuleImpl::RegisterPacketRequestCallback( int32_t VideoCodingModuleImpl::Decode(uint16_t maxWaitTimeMs) { + TRACE_EVENT1("webrtc", "VCM::Decode", "max_wait", maxWaitTimeMs); int64_t nextRenderTimeMs; { CriticalSectionScoped cs(_receiveCritSect); @@ -954,6 +956,7 @@ int32_t VideoCodingModuleImpl::RequestSliceLossIndication( const uint64_t pictureID) const { + TRACE_EVENT1("webrtc", "RequestSLI", "picture_id", pictureID); if (_frameTypeCallback != NULL) { const int32_t ret = @@ -980,6 +983,7 @@ VideoCodingModuleImpl::RequestSliceLossIndication( int32_t VideoCodingModuleImpl::RequestKeyFrame() { + TRACE_EVENT0("webrtc", "RequestKeyFrame"); if (_frameTypeCallback != NULL) { const int32_t ret = _frameTypeCallback->RequestKeyFrame(); @@ -1062,6 +1066,9 @@ VideoCodingModuleImpl::DecodeDualFrame(uint16_t maxWaitTimeMs) int32_t VideoCodingModuleImpl::Decode(const VCMEncodedFrame& frame) { + TRACE_EVENT2("webrtc", "Decode", + "timestamp", frame.TimeStamp(), + "type", frame.FrameType()); // Change decoder if payload type has changed const bool renderTimingBefore = _codecDataBase.SupportsRenderScheduling(); _decoder = _codecDataBase.GetDecoder(frame.PayloadType(), @@ -1208,6 +1215,9 @@ VideoCodingModuleImpl::IncomingPacket(const uint8_t* incomingPayload, uint32_t payloadLength, const WebRtcRTPHeader& rtpInfo) { + TRACE_EVENT2("webrtc", "VCM::Packet", + "seqnum", rtpInfo.header.sequenceNumber, + "type", rtpInfo.frameType); if (incomingPayload == NULL) { // The jitter buffer doesn't handle non-zero payload lengths for packets // without payload. diff --git a/webrtc/video_engine/vie_capturer.cc b/webrtc/video_engine/vie_capturer.cc index f9580e95d6..1a283d7c09 100644 --- a/webrtc/video_engine/vie_capturer.cc +++ b/webrtc/video_engine/vie_capturer.cc @@ -20,6 +20,7 @@ #include "system_wrappers/interface/event_wrapper.h" #include "system_wrappers/interface/thread_wrapper.h" #include "system_wrappers/interface/trace.h" +#include "system_wrappers/interface/trace_event.h" #include "video_engine/include/vie_image_process.h" #include "video_engine/vie_defines.h" #include "video_engine/vie_encoder.h" @@ -353,6 +354,10 @@ void ViECapturer::OnIncomingCapturedFrame(const int32_t capture_id, // is slightly off since it's being set when the frame has been received from // the camera, and not when the camera actually captured the frame. video_frame.set_render_time_ms(video_frame.render_time_ms() - FrameDelay()); + + TRACE_EVENT_INSTANT1("webrtc", "VC::OnIncomingCapturedFrame", + "render_time", video_frame.render_time_ms()); + captured_frame_.SwapFrame(&video_frame); capture_event_.Set(); return; @@ -368,6 +373,10 @@ void ViECapturer::OnIncomingCapturedEncodedFrame(const int32_t capture_id, // is slightly off since it's being set when the frame has been received from // the camera, and not when the camera actually captured the frame. video_frame.SetRenderTime(video_frame.RenderTimeMs() - FrameDelay()); + + TRACE_EVENT_INSTANT1("webrtc", "VC::OnIncomingCapturedEncodedFrame", + "render_time", video_frame.RenderTimeMs()); + assert(codec_type != kVideoCodecUnknown); if (encoded_frame_.Length() != 0) { // The last encoded frame has not been sent yet. Need to wait. diff --git a/webrtc/video_engine/vie_encoder.cc b/webrtc/video_engine/vie_encoder.cc index c647d7a851..ccacf8c0d6 100644 --- a/webrtc/video_engine/vie_encoder.cc +++ b/webrtc/video_engine/vie_encoder.cc @@ -23,6 +23,7 @@ #include "system_wrappers/interface/logging.h" #include "system_wrappers/interface/tick_util.h" #include "system_wrappers/interface/trace.h" +#include "system_wrappers/interface/trace_event.h" #include "video_engine/include/vie_codec.h" #include "video_engine/include/vie_image_process.h" #include "video_engine/vie_defines.h" @@ -507,6 +508,9 @@ void ViEEncoder::DeliverFrame(int id, ViEId(engine_id_, channel_id_), "%s: Dropping frame %llu after a key fame", __FUNCTION__, video_frame->timestamp()); + TRACE_EVENT_INSTANT1("webrtc", "VE::EncoderDropFrame", + "timestamp", video_frame->timestamp()); + drop_next_frame_ = false; return; } @@ -517,6 +521,11 @@ void ViEEncoder::DeliverFrame(int id, const uint32_t time_stamp = kMsToRtpTimestamp * static_cast(video_frame->render_time_ms()); + + TRACE_EVENT2("webrtc", "VE::DeliverFrame", + "timestamp", time_stamp, + "render_time", video_frame->render_time_ms()); + video_frame->set_timestamp(time_stamp); { CriticalSectionScoped cs(callback_cs_.get()); @@ -770,6 +779,9 @@ int32_t ViEEncoder::SendData( // Paused, don't send this packet. return 0; } + TRACE_EVENT2("webrtc", "VE::SendData", + "timestamp", time_stamp, + "capture_time_ms", capture_time_ms); if (channels_dropping_delta_frames_ && frame_type == webrtc::kVideoFrameKey) { WEBRTC_TRACE(webrtc::kTraceStream, webrtc::kTraceVideo, diff --git a/webrtc/video_engine/vie_sync_module.cc b/webrtc/video_engine/vie_sync_module.cc index 8cf56c0dc6..fe7a1cabb2 100644 --- a/webrtc/video_engine/vie_sync_module.cc +++ b/webrtc/video_engine/vie_sync_module.cc @@ -153,10 +153,9 @@ int32_t 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); + TRACE_COUNTER1("webrtc", "SyncCurrentVideoDelay", total_video_delay_target_ms); + TRACE_COUNTER1("webrtc", "SyncCurrentAudioDelay", current_audio_delay_ms); + TRACE_COUNTER1("webrtc", "SyncRelativeDelay", 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. @@ -167,8 +166,8 @@ int32_t ViESyncModule::Process() { return 0; } - TRACE_COUNTER1("webrtc_sync", "ExtraAudioDelayTarget", extra_audio_delay_ms); - TRACE_COUNTER1("webrtc_sync", "TotalVideoDelayTarget", + TRACE_COUNTER1("webrtc", "SyncExtraAudioDelayTarget", extra_audio_delay_ms); + TRACE_COUNTER1("webrtc", "SyncTotalVideoDelayTarget", total_video_delay_target_ms); if (voe_sync_interface_->SetMinimumPlayoutDelay( voe_channel_id_, extra_audio_delay_ms) == -1) {