diff --git a/logging/BUILD.gn b/logging/BUILD.gn index cb22af4a07..d06578d4e3 100644 --- a/logging/BUILD.gn +++ b/logging/BUILD.gn @@ -280,6 +280,7 @@ if (rtc_enable_protobuf) { "../api:libjingle_peerconnection_api", "../call:video_stream_api", "../modules/audio_coding:audio_network_adaptor", + "../modules/congestion_controller:transport_feedback", "../modules/remote_bitrate_estimator:remote_bitrate_estimator", "../modules/rtp_rtcp", "../modules/rtp_rtcp:rtp_rtcp_format", diff --git a/logging/rtc_event_log/DEPS b/logging/rtc_event_log/DEPS index d09e30eace..a3c19ba690 100644 --- a/logging/rtc_event_log/DEPS +++ b/logging/rtc_event_log/DEPS @@ -1,6 +1,7 @@ include_rules = [ "+call", "+modules/audio_coding/audio_network_adaptor", + "+modules/congestion_controller", "+modules/remote_bitrate_estimator/include", "+modules/rtp_rtcp", ] diff --git a/logging/rtc_event_log/rtc_event_log_parser_new.cc b/logging/rtc_event_log/rtc_event_log_parser_new.cc index 4a75dc35fa..ab1ce82a35 100644 --- a/logging/rtc_event_log/rtc_event_log_parser_new.cc +++ b/logging/rtc_event_log/rtc_event_log_parser_new.cc @@ -25,6 +25,7 @@ #include "api/rtpparameters.h" #include "logging/rtc_event_log/rtc_event_log.h" #include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h" +#include "modules/congestion_controller/transport_feedback_adapter.h" #include "modules/remote_bitrate_estimator/include/bwe_defines.h" #include "modules/rtp_rtcp/include/rtp_rtcp_defines.h" #include "modules/rtp_rtcp/source/byte_io.h" @@ -245,6 +246,23 @@ void GetHeaderExtensions(std::vector* header_extensions, } } +void SortPacketFeedbackVectorWithLoss(std::vector* vec) { + class LossHandlingPacketFeedbackComparator { + public: + inline bool operator()(const PacketFeedback& lhs, + const PacketFeedback& rhs) { + if (lhs.arrival_time_ms != PacketFeedback::kNotReceived && + rhs.arrival_time_ms != PacketFeedback::kNotReceived && + lhs.arrival_time_ms != rhs.arrival_time_ms) + return lhs.arrival_time_ms < rhs.arrival_time_ms; + if (lhs.send_time_ms != rhs.send_time_ms) + return lhs.send_time_ms < rhs.send_time_ms; + return lhs.sequence_number < rhs.sequence_number; + } + }; + std::sort(vec->begin(), vec->end(), LossHandlingPacketFeedbackComparator()); +} + } // namespace LoggedRtcpPacket::LoggedRtcpPacket(uint64_t timestamp_us, @@ -1370,4 +1388,74 @@ ParsedRtcEventLogNew::MediaType ParsedRtcEventLogNew::GetMediaType( return MediaType::ANY; } +const std::vector GetNetworkTrace( + const ParsedRtcEventLogNew& parsed_log) { + using RtpPacketType = LoggedRtpPacketOutgoing; + using TransportFeedbackType = LoggedRtcpPacketTransportFeedback; + + std::multimap outgoing_rtp; + for (const auto& stream : parsed_log.outgoing_rtp_packets_by_ssrc()) { + for (const RtpPacketType& rtp_packet : stream.outgoing_packets) + outgoing_rtp.insert( + std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet)); + } + + const std::vector& incoming_rtcp = + parsed_log.transport_feedbacks(kIncomingPacket); + + SimulatedClock clock(0); + TransportFeedbackAdapter feedback_adapter(&clock); + + auto rtp_iterator = outgoing_rtp.begin(); + auto rtcp_iterator = incoming_rtcp.begin(); + + auto NextRtpTime = [&]() { + if (rtp_iterator != outgoing_rtp.end()) + return static_cast(rtp_iterator->first); + return std::numeric_limits::max(); + }; + + auto NextRtcpTime = [&]() { + if (rtcp_iterator != incoming_rtcp.end()) + return static_cast(rtcp_iterator->log_time_us()); + return std::numeric_limits::max(); + }; + + int64_t time_us = std::min(NextRtpTime(), NextRtcpTime()); + + std::vector rtp_rtcp_matched; + while (time_us != std::numeric_limits::max()) { + clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds()); + if (clock.TimeInMicroseconds() >= NextRtcpTime()) { + RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime()); + feedback_adapter.OnTransportFeedback(rtcp_iterator->transport_feedback); + std::vector feedback = + feedback_adapter.GetTransportFeedbackVector(); + SortPacketFeedbackVectorWithLoss(&feedback); + for (const PacketFeedback& packet : feedback) { + rtp_rtcp_matched.emplace_back( + clock.TimeInMilliseconds(), packet.send_time_ms, + packet.arrival_time_ms, packet.payload_size); + } + ++rtcp_iterator; + } + if (clock.TimeInMicroseconds() >= NextRtpTime()) { + RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime()); + const RtpPacketType& rtp_packet = *rtp_iterator->second; + if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) { + feedback_adapter.AddPacket( + rtp_packet.rtp.header.ssrc, + rtp_packet.rtp.header.extension.transportSequenceNumber, + rtp_packet.rtp.total_length, PacedPacketInfo()); + feedback_adapter.OnSentPacket( + rtp_packet.rtp.header.extension.transportSequenceNumber, + rtp_packet.rtp.log_time_ms()); + } + ++rtp_iterator; + } + time_us = std::min(NextRtpTime(), NextRtcpTime()); + } + return rtp_rtcp_matched; +} + } // namespace webrtc diff --git a/logging/rtc_event_log/rtc_event_log_parser_new.h b/logging/rtc_event_log/rtc_event_log_parser_new.h index 8f7cc8fdcf..5ab0c15b92 100644 --- a/logging/rtc_event_log/rtc_event_log_parser_new.h +++ b/logging/rtc_event_log/rtc_event_log_parser_new.h @@ -985,6 +985,21 @@ class ParsedRtcEventLogNew { outgoing_rtp_extensions_maps_; }; +struct MatchedSendArrivalTimes { + MatchedSendArrivalTimes(int64_t fb, int64_t tx, int64_t rx, int64_t ps) + : feedback_arrival_time_ms(fb), + send_time_ms(tx), + arrival_time_ms(rx), + payload_size(ps) {} + + int64_t feedback_arrival_time_ms; + int64_t send_time_ms; // PacketFeedback::kNoSendTime for late feedback. + int64_t arrival_time_ms; // PacketFeedback::kNotReceived for lost packets. + int64_t payload_size; +}; +const std::vector GetNetworkTrace( + const ParsedRtcEventLogNew& parsed_log); + } // namespace webrtc #endif // LOGGING_RTC_EVENT_LOG_RTC_EVENT_LOG_PARSER_NEW_H_ diff --git a/rtc_tools/event_log_visualizer/analyzer.cc b/rtc_tools/event_log_visualizer/analyzer.cc index c9187ca70c..a05598163b 100644 --- a/rtc_tools/event_log_visualizer/analyzer.cc +++ b/rtc_tools/event_log_visualizer/analyzer.cc @@ -1276,83 +1276,27 @@ void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) { } void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) { - using RtpPacketType = LoggedRtpPacketOutgoing; - using TransportFeedbackType = LoggedRtcpPacketTransportFeedback; - - // TODO(terelius): This could be provided by the parser. - std::multimap outgoing_rtp; - for (const auto& stream : parsed_log_.outgoing_rtp_packets_by_ssrc()) { - for (const RtpPacketType& rtp_packet : stream.outgoing_packets) - outgoing_rtp.insert( - std::make_pair(rtp_packet.rtp.log_time_us(), &rtp_packet)); - } - - const std::vector& incoming_rtcp = - parsed_log_.transport_feedbacks(kIncomingPacket); - - SimulatedClock clock(0); - TransportFeedbackAdapter feedback_adapter(&clock); - TimeSeries late_feedback_series("Late feedback results.", LineStyle::kNone, PointStyle::kHighlight); TimeSeries time_series("Network Delay Change", LineStyle::kLine, PointStyle::kHighlight); int64_t estimated_base_delay_ms = std::numeric_limits::max(); - auto rtp_iterator = outgoing_rtp.begin(); - auto rtcp_iterator = incoming_rtcp.begin(); - - auto NextRtpTime = [&]() { - if (rtp_iterator != outgoing_rtp.end()) - return static_cast(rtp_iterator->first); - return std::numeric_limits::max(); - }; - - auto NextRtcpTime = [&]() { - if (rtcp_iterator != incoming_rtcp.end()) - return static_cast(rtcp_iterator->log_time_us()); - return std::numeric_limits::max(); - }; - - int64_t time_us = std::min(NextRtpTime(), NextRtcpTime()); int64_t prev_y = 0; - while (time_us != std::numeric_limits::max()) { - clock.AdvanceTimeMicroseconds(time_us - clock.TimeInMicroseconds()); - if (clock.TimeInMicroseconds() >= NextRtcpTime()) { - RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime()); - feedback_adapter.OnTransportFeedback(rtcp_iterator->transport_feedback); - std::vector feedback = - feedback_adapter.GetTransportFeedbackVector(); - SortPacketFeedbackVector(&feedback); - for (const PacketFeedback& packet : feedback) { - float x = ToCallTimeSec(clock.TimeInMicroseconds()); - if (packet.send_time_ms == PacketFeedback::kNoSendTime) { - late_feedback_series.points.emplace_back(x, prev_y); - continue; - } - int64_t y = packet.arrival_time_ms - packet.send_time_ms; - prev_y = y; - estimated_base_delay_ms = std::min(y, estimated_base_delay_ms); - time_series.points.emplace_back(x, y); - } - ++rtcp_iterator; + for (auto packet : GetNetworkTrace(parsed_log_)) { + if (packet.arrival_time_ms == PacketFeedback::kNotReceived) + continue; + float x = ToCallTimeSec(1000 * packet.feedback_arrival_time_ms); + if (packet.send_time_ms == PacketFeedback::kNoSendTime) { + late_feedback_series.points.emplace_back(x, prev_y); + continue; } - if (clock.TimeInMicroseconds() >= NextRtpTime()) { - RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime()); - const RtpPacketType& rtp_packet = *rtp_iterator->second; - if (rtp_packet.rtp.header.extension.hasTransportSequenceNumber) { - feedback_adapter.AddPacket( - rtp_packet.rtp.header.ssrc, - rtp_packet.rtp.header.extension.transportSequenceNumber, - rtp_packet.rtp.total_length, PacedPacketInfo()); - feedback_adapter.OnSentPacket( - rtp_packet.rtp.header.extension.transportSequenceNumber, - rtp_packet.rtp.log_time_us() / 1000); - } - ++rtp_iterator; - } - time_us = std::min(NextRtpTime(), NextRtcpTime()); + int64_t y = packet.arrival_time_ms - packet.send_time_ms; + prev_y = y; + estimated_base_delay_ms = std::min(y, estimated_base_delay_ms); + time_series.points.emplace_back(x, y); } + // We assume that the base network delay (w/o queues) is the min delay // observed during the call. for (TimeSeriesPoint& point : time_series.points)