diff --git a/logging/BUILD.gn b/logging/BUILD.gn index bc7b3c0bf5..6b29094e71 100644 --- a/logging/BUILD.gn +++ b/logging/BUILD.gn @@ -291,6 +291,7 @@ if (rtc_enable_protobuf) { rtc_static_library("rtc_event_log_parser") { visibility = [ "*" ] sources = [ + "rtc_event_log/logged_events.cc", "rtc_event_log/logged_events.h", "rtc_event_log/rtc_event_log_parser.cc", "rtc_event_log/rtc_event_log_parser.h", @@ -307,6 +308,9 @@ if (rtc_enable_protobuf) { ":rtc_event_log_proto", ":rtc_stream_config", "../api:libjingle_peerconnection_api", + "../api/units:data_rate", + "../api/units:time_delta", + "../api/units:timestamp", "../call:video_stream_api", "../modules/audio_coding:audio_network_adaptor", "../modules/congestion_controller/rtp:transport_feedback", @@ -317,6 +321,7 @@ if (rtc_enable_protobuf) { "../rtc_base:deprecation", "../rtc_base:protobuf_utils", "../rtc_base:rtc_base_approved", + "../rtc_base:rtc_numerics", "//third_party/abseil-cpp/absl/memory", "//third_party/abseil-cpp/absl/types:optional", ] diff --git a/logging/rtc_event_log/logged_events.cc b/logging/rtc_event_log/logged_events.cc new file mode 100644 index 0000000000..0a4b3dfeba --- /dev/null +++ b/logging/rtc_event_log/logged_events.cc @@ -0,0 +1,36 @@ +/* + * Copyright 2019 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 "logging/rtc_event_log/logged_events.h" + +namespace webrtc { + +LoggedPacketInfo::LoggedPacketInfo(const LoggedRtpPacket& rtp, + LoggedMediaType media_type, + bool rtx, + Timestamp capture_time) + : ssrc(rtp.header.ssrc), + stream_seq_no(rtp.header.sequenceNumber), + size(static_cast(rtp.total_length)), + payload_type(rtp.header.payloadType), + media_type(media_type), + rtx(rtx), + marker_bit(rtp.header.markerBit), + has_transport_seq_no(rtp.header.extension.hasTransportSequenceNumber), + transport_seq_no(static_cast( + has_transport_seq_no ? rtp.header.extension.transportSequenceNumber + : 0)), + // TODO(srte): Use logged sample rate when it is added to the format. + capture_time(capture_time), + log_packet_time(Timestamp::us(rtp.log_time_us())) {} + +LoggedPacketInfo::LoggedPacketInfo(const LoggedPacketInfo&) = default; + +LoggedPacketInfo::~LoggedPacketInfo() {} +} // namespace webrtc diff --git a/logging/rtc_event_log/logged_events.h b/logging/rtc_event_log/logged_events.h index 7ff7e2d09c..414026592d 100644 --- a/logging/rtc_event_log/logged_events.h +++ b/logging/rtc_event_log/logged_events.h @@ -13,7 +13,11 @@ #include #include +#include "absl/types/optional.h" #include "api/rtp_headers.h" +#include "api/units/data_rate.h" +#include "api/units/time_delta.h" +#include "api/units/timestamp.h" #include "logging/rtc_event_log/events/rtc_event_dtls_transport_state.h" #include "logging/rtc_event_log/events/rtc_event_ice_candidate_pair.h" #include "logging/rtc_event_log/events/rtc_event_ice_candidate_pair_config.h" @@ -437,5 +441,71 @@ struct LoggedVideoSendConfig { int64_t timestamp_us; rtclog::StreamConfig config; }; + +struct LoggedRouteChangeEvent { + uint32_t route_id; + int64_t timestamp_us; + uint16_t send_overhead; + uint16_t return_overhead; +}; + +enum class LoggedMediaType : uint8_t { kUnknown, kAudio, kVideo }; + +struct LoggedPacketInfo { + LoggedPacketInfo(const LoggedRtpPacket& rtp, + LoggedMediaType media_type, + bool rtx, + Timestamp capture_time); + LoggedPacketInfo(const LoggedPacketInfo&); + ~LoggedPacketInfo(); + uint32_t ssrc; + uint16_t stream_seq_no; + uint16_t size; + uint16_t overhead = 0; + uint8_t payload_type; + LoggedMediaType media_type = LoggedMediaType::kUnknown; + bool rtx = false; + bool marker_bit = false; + bool has_transport_seq_no = false; + bool last_in_feedback = false; + uint16_t transport_seq_no = 0; + // The RTP header timestamp unwrapped and converted from tick count to seconds + // based timestamp. + Timestamp capture_time; + // The time the packet was logged. This is the receive time for incoming + // packets and send time for outgoing. + Timestamp log_packet_time; + // The receive time that was reported in feedback. For incoming packets this + // corresponds to log_packet_time, but might be measured using another clock. + // PlusInfinity indicates that the packet was lost. + Timestamp reported_recv_time = Timestamp::MinusInfinity(); + // The time feedback message was logged. This is the feedback send time for + // incoming packets and feedback receive time for outgoing. + // PlusInfinity indicates that feedback was expected but not received. + Timestamp log_feedback_time = Timestamp::MinusInfinity(); + // The delay betweeen receiving an RTP packet and sending feedback for + // incoming packets. For outgoing packets we don't know the feedback send + // time, and this is instead calculated as the difference in reported receive + // time between this packet and the last packet in the same feedback message. + TimeDelta feedback_hold_duration = TimeDelta::MinusInfinity(); +}; + +enum class LoggedIceEventType { + kAdded, + kUpdated, + kDestroyed, + kSelected, + kCheckSent, + kCheckReceived, + kCheckResponseSent, + kCheckResponseReceived, +}; + +struct LoggedIceEvent { + uint32_t candidate_pair_id; + int64_t timestamp_us; + LoggedIceEventType event_type; +}; + } // namespace webrtc #endif // LOGGING_RTC_EVENT_LOG_LOGGED_EVENTS_H_ diff --git a/logging/rtc_event_log/rtc_event_log_parser.cc b/logging/rtc_event_log/rtc_event_log_parser.cc index abf6c7b7e5..0cd87a0171 100644 --- a/logging/rtc_event_log/rtc_event_log_parser.cc +++ b/logging/rtc_event_log/rtc_event_log_parser.cc @@ -28,6 +28,7 @@ #include "logging/rtc_event_log/encoder/delta_encoding.h" #include "logging/rtc_event_log/encoder/rtc_event_log_encoder_common.h" #include "logging/rtc_event_log/rtc_event_log.h" +#include "logging/rtc_event_log/rtc_event_processor.h" #include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h" #include "modules/congestion_controller/rtp/transport_feedback_adapter.h" #include "modules/remote_bitrate_estimator/include/bwe_defines.h" @@ -39,6 +40,7 @@ #include "rtc_base/checks.h" #include "rtc_base/logging.h" #include "rtc_base/numerics/safe_conversions.h" +#include "rtc_base/numerics/sequence_number_util.h" #include "rtc_base/protobuf_utils.h" using webrtc_event_logging::ToSigned; @@ -47,6 +49,69 @@ using webrtc_event_logging::ToUnsigned; namespace webrtc { namespace { +constexpr size_t kIpv4Overhead = 20; +constexpr size_t kIpv6Overhead = 40; +constexpr size_t kUdpOverhead = 8; +constexpr size_t kSrtpOverhead = 10; +constexpr size_t kStunOverhead = 4; +constexpr uint16_t kDefaultOverhead = + kUdpOverhead + kSrtpOverhead + kIpv4Overhead; + +// Starting at a multiple of common audio sample rate (48000) and video tick +// rate (90000) to make a tick count of 0 to correspond to something without +// decimals in base 10. +constexpr uint64_t kStartingCaptureTimeTicks = 90 * 48 * 1000; + +struct MediaStreamInfo { + MediaStreamInfo() : unwrap_capture_ticks(kStartingCaptureTimeTicks) {} + MediaStreamInfo(LoggedMediaType media_type, bool rtx) + : media_type(media_type), + rtx(rtx), + unwrap_capture_ticks(kStartingCaptureTimeTicks) {} + LoggedMediaType media_type = LoggedMediaType::kUnknown; + bool rtx = false; + SeqNumUnwrapper unwrap_capture_ticks; +}; + +template +void AddRecvStreamInfos(std::map* streams, + const Iterable configs, + LoggedMediaType media_type) { + for (auto& conf : configs) { + streams->insert({conf.config.remote_ssrc, {media_type, false}}); + if (conf.config.rtx_ssrc != 0) + streams->insert({conf.config.rtx_ssrc, {media_type, true}}); + } +} +template +void AddSendStreamInfos(std::map* streams, + const Iterable configs, + LoggedMediaType media_type) { + for (auto& conf : configs) { + streams->insert({conf.config.local_ssrc, {media_type, false}}); + if (conf.config.rtx_ssrc != 0) + streams->insert({conf.config.rtx_ssrc, {media_type, true}}); + } +} +struct OverheadChangeEvent { + int64_t timestamp_us; + uint16_t overhead; +}; +std::vector GetOverheadChangingEvents( + const std::vector& route_changes, + PacketDirection direction) { + std::vector overheads; + for (auto& event : route_changes) { + uint16_t new_overhead = direction == PacketDirection::kIncomingPacket + ? event.return_overhead + : event.send_overhead; + if (overheads.empty() || new_overhead != overheads.back().overhead) { + overheads.push_back({event.timestamp_us, new_overhead}); + } + } + return overheads; +} + // Conversion functions for legacy wire format. RtcpMode GetRuntimeRtcpMode(rtclog::VideoReceiveConfig::RtcpMode rtcp_mode) { switch (rtcp_mode) { @@ -407,23 +472,6 @@ 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()); -} - template void StoreRtpPackets( const ProtoType& proto, @@ -1766,84 +1814,187 @@ ParsedRtcEventLog::MediaType ParsedRtcEventLog::GetMediaType( return MediaType::ANY; } -const std::vector GetNetworkTrace( - const ParsedRtcEventLog& parsed_log) { - using RtpPacketType = LoggedRtpPacketOutgoing; - using TransportFeedbackType = LoggedRtcpPacketTransportFeedback; +std::vector ParsedRtcEventLog::GetRouteChanges() const { + std::vector route_changes; + for (auto& candidate : ice_candidate_pair_configs()) { + if (candidate.type == IceCandidatePairConfigType::kSelected) { + LoggedRouteChangeEvent route; + route.route_id = candidate.candidate_pair_id; + route.timestamp_us = candidate.log_time_us(); - 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)); + route.send_overhead = kUdpOverhead + kSrtpOverhead + kIpv4Overhead; + if (candidate.remote_address_family == + IceCandidatePairAddressFamily::kIpv6) + route.send_overhead += kIpv6Overhead - kIpv4Overhead; + if (candidate.remote_candidate_type != IceCandidateType::kLocal) + route.send_overhead += kStunOverhead; + route.return_overhead = kUdpOverhead + kSrtpOverhead + kIpv4Overhead; + if (candidate.remote_address_family == + IceCandidatePairAddressFamily::kIpv6) + route.return_overhead += kIpv6Overhead - kIpv4Overhead; + if (candidate.remote_candidate_type != IceCandidateType::kLocal) + route.return_overhead += kStunOverhead; + route_changes.push_back(route); + } + } + return route_changes; +} + +std::vector ParsedRtcEventLog::GetPacketInfos( + PacketDirection direction) const { + std::map streams; + if (direction == PacketDirection::kIncomingPacket) { + AddRecvStreamInfos(&streams, audio_recv_configs(), LoggedMediaType::kAudio); + AddRecvStreamInfos(&streams, video_recv_configs(), LoggedMediaType::kVideo); + } else if (direction == PacketDirection::kOutgoingPacket) { + AddSendStreamInfos(&streams, audio_send_configs(), LoggedMediaType::kAudio); + AddSendStreamInfos(&streams, video_send_configs(), LoggedMediaType::kVideo); } - const std::vector& incoming_rtcp = - parsed_log.transport_feedbacks(kIncomingPacket); - - SimulatedClock clock(0); + // Using one second as an arbitrary starting point. + SimulatedClock clock(1000000); TransportFeedbackAdapter feedback_adapter(&clock); + std::vector overheads = + GetOverheadChangingEvents(GetRouteChanges(), direction); + auto overhead_iter = overheads.begin(); + std::vector packets; + std::map indices; + uint16_t current_overhead = kDefaultOverhead; + int64_t last_log_time_ms = 0; - 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 advance_clock = [&](int64_t log_time_ms) { + if (overhead_iter != overheads.end() && + log_time_ms * 1000 >= overhead_iter->timestamp_us) { + current_overhead = overhead_iter->overhead; + ++overhead_iter; + } + RTC_CHECK_GE(log_time_ms, last_log_time_ms); + clock.AdvanceTimeMilliseconds(log_time_ms - last_log_time_ms); + last_log_time_ms = log_time_ms; }; - 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() >= NextRtpTime()) { - RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtpTime()); - const RtpPacketType& rtp_packet = *rtp_iterator->second; + auto rtp_handler = [&](const LoggedRtpPacket& rtp) { + advance_clock(rtp.log_time_ms()); + MediaStreamInfo* stream = &streams[rtp.header.ssrc]; + uint64_t capture_ticks = + stream->unwrap_capture_ticks.Unwrap(rtp.header.timestamp); + // TODO(srte): Use logged sample rate when it is added to the format. + Timestamp capture_time = Timestamp::seconds( + capture_ticks / + (stream->media_type == LoggedMediaType::kAudio ? 48000.0 : 90000.0)); + LoggedPacketInfo logged(rtp, stream->media_type, stream->rtx, capture_time); + logged.overhead = current_overhead; + if (rtp.header.extension.hasTransportSequenceNumber) { + logged.log_feedback_time = Timestamp::PlusInfinity(); rtc::SentPacket sent_packet; - sent_packet.send_time_ms = rtp_packet.rtp.log_time_ms(); - sent_packet.info.packet_size_bytes = rtp_packet.rtp.total_length; - 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()); - sent_packet.packet_id = - rtp_packet.rtp.header.extension.transportSequenceNumber; - sent_packet.info.included_in_feedback = true; - sent_packet.info.included_in_allocation = true; - feedback_adapter.ProcessSentPacket(sent_packet); + sent_packet.send_time_ms = rtp.log_time_ms(); + sent_packet.info.packet_size_bytes = rtp.total_length; + sent_packet.info.included_in_feedback = true; + sent_packet.packet_id = rtp.header.extension.transportSequenceNumber; + feedback_adapter.AddPacket(rtp.header.ssrc, sent_packet.packet_id, + rtp.total_length, PacedPacketInfo()); + auto sent_packet_msg = feedback_adapter.ProcessSentPacket(sent_packet); + RTC_CHECK(sent_packet_msg); + indices[sent_packet_msg->sequence_number] = packets.size(); + } + packets.push_back(logged); + }; + + auto feedback_handler = [&](const LoggedRtcpPacketTransportFeedback& logged) { + advance_clock(logged.log_time_ms()); + auto msg = + feedback_adapter.ProcessTransportFeedback(logged.transport_feedback); + if (!msg.has_value() || msg->packet_feedbacks.empty()) + return; + + auto& last_fb = msg->packet_feedbacks.back(); + Timestamp last_recv_time = last_fb.receive_time; + for (auto& fb : msg->packet_feedbacks) { + if (indices.find(fb.sent_packet.sequence_number) == indices.end()) { + RTC_LOG(LS_ERROR) << "Received feedback for unknown packet: " + << fb.sent_packet.sequence_number; + continue; + } + LoggedPacketInfo* sent = + &packets[indices[fb.sent_packet.sequence_number]]; + sent->reported_recv_time = fb.receive_time; + sent->log_feedback_time = msg->feedback_time; + if (direction == PacketDirection::kOutgoingPacket) { + sent->feedback_hold_duration = last_recv_time - fb.receive_time; } else { - sent_packet.info.included_in_feedback = false; - // TODO(srte): Make it possible to indicate that all packets are part of - // allocation. - sent_packet.info.included_in_allocation = false; - feedback_adapter.ProcessSentPacket(sent_packet); + sent->feedback_hold_duration = + Timestamp::us(logged.log_time_us()) - sent->log_packet_time; } - ++rtp_iterator; + sent->last_in_feedback = (&fb == &last_fb); } - if (clock.TimeInMicroseconds() >= NextRtcpTime()) { - RTC_DCHECK_EQ(clock.TimeInMicroseconds(), NextRtcpTime()); - feedback_adapter.ProcessTransportFeedback( - 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; + }; + + RtcEventProcessor process; + for (const auto& rtp_packets : rtp_packets_by_ssrc(direction)) { + process.AddEvents(rtp_packets.packet_view, rtp_handler); + } + if (direction == PacketDirection::kOutgoingPacket) { + process.AddEvents(incoming_transport_feedback_, feedback_handler); + } else { + process.AddEvents(outgoing_transport_feedback_, feedback_handler); + } + process.ProcessEventsInOrder(); + return packets; +} + +std::vector ParsedRtcEventLog::GetIceCandidates() + const { + std::vector candidates; + std::set added; + for (auto& candidate : ice_candidate_pair_configs()) { + if (added.find(candidate.candidate_pair_id) == added.end()) { + candidates.push_back(candidate); + added.insert(candidate.candidate_pair_id); + } + } + return candidates; +} + +std::vector ParsedRtcEventLog::GetIceEvents() const { + using CheckType = IceCandidatePairEventType; + using ConfigType = IceCandidatePairConfigType; + using Combined = LoggedIceEventType; + std::map check_map( + {{CheckType::kCheckSent, Combined::kCheckSent}, + {CheckType::kCheckReceived, Combined::kCheckReceived}, + {CheckType::kCheckResponseSent, Combined::kCheckResponseSent}, + {CheckType::kCheckResponseReceived, Combined::kCheckResponseReceived}}); + std::map config_map( + {{ConfigType::kAdded, Combined::kAdded}, + {ConfigType::kUpdated, Combined::kUpdated}, + {ConfigType::kDestroyed, Combined::kDestroyed}, + {ConfigType::kSelected, Combined::kSelected}}); + std::vector logged_events; + auto handle_check = [&](const LoggedIceCandidatePairEvent& check) { + logged_events.push_back(LoggedIceEvent{ + check.candidate_pair_id, check.timestamp_us, check_map[check.type]}); + }; + auto handle_config = [&](const LoggedIceCandidatePairConfig& conf) { + logged_events.push_back(LoggedIceEvent{ + conf.candidate_pair_id, conf.timestamp_us, config_map[conf.type]}); + }; + RtcEventProcessor process; + process.AddEvents(ice_candidate_pair_events(), handle_check); + process.AddEvents(ice_candidate_pair_configs(), handle_config); + return logged_events; +} + +const std::vector GetNetworkTrace( + const ParsedRtcEventLog& parsed_log) { + std::vector rtp_rtcp_matched; + for (auto& packet : + parsed_log.GetPacketInfos(PacketDirection::kOutgoingPacket)) { + if (packet.log_feedback_time.IsFinite() && + packet.reported_recv_time.IsFinite()) { + rtp_rtcp_matched.emplace_back( + packet.log_feedback_time.ms(), packet.log_packet_time.ms(), + packet.reported_recv_time.ms(), packet.size); } - time_us = std::min(NextRtpTime(), NextRtcpTime()); } return rtp_rtcp_matched; } diff --git a/logging/rtc_event_log/rtc_event_log_parser.h b/logging/rtc_event_log/rtc_event_log_parser.h index dc23944057..82807fb1a9 100644 --- a/logging/rtc_event_log/rtc_event_log_parser.h +++ b/logging/rtc_event_log/rtc_event_log_parser.h @@ -466,7 +466,13 @@ class ParsedRtcEventLog { int64_t first_timestamp() const { return first_timestamp_; } int64_t last_timestamp() const { return last_timestamp_; } + std::vector GetPacketInfos(PacketDirection direction) const; + std::vector GetIceCandidates() const; + std::vector GetIceEvents() const; + private: + std::vector GetRouteChanges() const; + bool ParseStreamInternal( std::istream& stream); // no-presubmit-check TODO(webrtc:8982)