From a1e4fbb25371867349a0c2ed6ba62224735a2ec7 Mon Sep 17 00:00:00 2001 From: Sebastian Jansson Date: Tue, 23 Apr 2019 18:58:57 +0200 Subject: [PATCH] Improving robustness of feedback matching code in event log parser. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Removes the dependency on TransportFeedbackAdapter thereby removing some of the complexity that came with it, in particular, we don't fill in missing packets. This makes the code easier to debug and avoids some confusing logging that's not relevant for the parser. Bug: webrtc:9883 Change-Id: I6df8425e8ab410514727c51a5e8d4981d6561f03 Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/133347 Reviewed-by: Stefan Holmer Reviewed-by: Björn Terelius Commit-Queue: Sebastian Jansson Cr-Commit-Position: refs/heads/master@{#27739} --- logging/BUILD.gn | 2 +- logging/rtc_event_log/rtc_event_log_parser.cc | 124 +++++++++--------- .../rtp/transport_feedback_adapter.cc | 18 +-- .../source/rtcp_packet/transport_feedback.cc | 12 ++ .../source/rtcp_packet/transport_feedback.h | 3 + 5 files changed, 81 insertions(+), 78 deletions(-) diff --git a/logging/BUILD.gn b/logging/BUILD.gn index e1d5289cb0..2258a7356a 100644 --- a/logging/BUILD.gn +++ b/logging/BUILD.gn @@ -335,8 +335,8 @@ if (rtc_enable_protobuf) { "../api/units:time_delta", "../api/units:timestamp", "../call:video_stream_api", + "../modules:module_api", "../modules/audio_coding:audio_network_adaptor", - "../modules/congestion_controller/rtp:transport_feedback", "../modules/remote_bitrate_estimator", "../modules/rtp_rtcp", "../modules/rtp_rtcp:rtp_rtcp_format", diff --git a/logging/rtc_event_log/rtc_event_log_parser.cc b/logging/rtc_event_log/rtc_event_log_parser.cc index 289744da27..4d234fcc22 100644 --- a/logging/rtc_event_log/rtc_event_log_parser.cc +++ b/logging/rtc_event_log/rtc_event_log_parser.cc @@ -30,7 +30,7 @@ #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/include/module_common_types.h" #include "modules/remote_bitrate_estimator/include/bwe_defines.h" #include "modules/rtp_rtcp/include/rtp_cvo.h" #include "modules/rtp_rtcp/include/rtp_rtcp_defines.h" @@ -1918,7 +1918,6 @@ std::vector ParsedRtcEventLog::GetPacketInfos( AddSendStreamInfos(&streams, video_send_configs(), LoggedMediaType::kVideo); } - TransportFeedbackAdapter feedback_adapter; std::vector overheads = GetOverheadChangingEvents(GetRouteChanges(), direction); auto overhead_iter = overheads.begin(); @@ -1926,6 +1925,7 @@ std::vector ParsedRtcEventLog::GetPacketInfos( std::map indices; uint16_t current_overhead = kDefaultOverhead; Timestamp last_log_time = Timestamp::Zero(); + SequenceNumberUnwrapper seq_num_unwrapper; auto advance_time = [&](Timestamp new_log_time) { if (overhead_iter != overheads.end() && @@ -1959,72 +1959,74 @@ std::vector ParsedRtcEventLog::GetPacketInfos( } 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(); - - RtpPacketSendInfo packet_info; - packet_info.ssrc = rtp.header.ssrc; - packet_info.transport_sequence_number = - rtp.header.extension.transportSequenceNumber; - packet_info.rtp_sequence_number = rtp.header.sequenceNumber; - packet_info.has_rtp_sequence_number = true; - packet_info.length = rtp.total_length; - feedback_adapter.AddPacket(packet_info, - 0u, // Should this be current_overhead? - Timestamp::ms(rtp.log_time_ms())); - - rtc::SentPacket 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; - auto sent_packet_msg = feedback_adapter.ProcessSentPacket(sent_packet); - RTC_CHECK(sent_packet_msg); - indices[sent_packet_msg->sequence_number] = packets.size(); + if (logged.has_transport_seq_no) { + int64_t unwrapped_seq_num = + seq_num_unwrapper.Unwrap(logged.transport_seq_no); + indices[unwrapped_seq_num] = packets.size(); } packets.push_back(logged); }; - auto feedback_handler = [&](const LoggedRtcpPacketTransportFeedback& logged) { - advance_time(Timestamp::ms(logged.log_time_ms())); - auto msg = feedback_adapter.ProcessTransportFeedback( - logged.transport_feedback, Timestamp::ms(logged.log_time_ms())); - if (!msg.has_value() || msg->packet_feedbacks.empty()) - return; + Timestamp feedback_base_time = Timestamp::MinusInfinity(); + Timestamp last_feedback_base_time = Timestamp::MinusInfinity(); - auto& last_fb = msg->packet_feedbacks.back(); - Timestamp last_recv_time = last_fb.receive_time; - // This can happen if send time info is missing for the real last packet in - // the feedback, allowing the reported last packet to med indicated as lost. - if (last_recv_time.IsInfinite()) - RTC_LOG(LS_WARNING) << "No receive time for last packet in feedback."; - - 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; - // If we have received feedback with a valid receive time for this packet - // before, we keep the previous values. - if (sent->log_feedback_time.IsFinite() && - sent->reported_recv_time.IsFinite()) - continue; - sent->log_feedback_time = msg->feedback_time; - if (last_recv_time.IsFinite()) { - if (direction == PacketDirection::kOutgoingPacket) { - sent->feedback_hold_duration = last_recv_time - fb.receive_time; + auto feedback_handler = + [&](const LoggedRtcpPacketTransportFeedback& logged_rtcp) { + auto log_feedback_time = Timestamp::ms(logged_rtcp.log_time_ms()); + advance_time(log_feedback_time); + const auto& feedback = logged_rtcp.transport_feedback; + // Add timestamp deltas to a local time base selected on first packet + // arrival. This won't be the true time base, but makes it easier to + // manually inspect time stamps. + if (last_feedback_base_time.IsInfinite()) { + feedback_base_time = log_feedback_time; } else { - sent->feedback_hold_duration = - Timestamp::ms(logged.log_time_ms()) - sent->log_packet_time; + feedback_base_time += TimeDelta::us( + feedback.GetBaseDeltaUs(last_feedback_base_time.us())); } - } - sent->last_in_feedback = (&fb == &last_fb); - } - }; + last_feedback_base_time = Timestamp::us(feedback.GetBaseTimeUs()); + + std::vector packet_feedbacks; + packet_feedbacks.reserve(feedback.GetReceivedPackets().size()); + Timestamp receive_timestamp = feedback_base_time; + for (const auto& packet : feedback.GetReceivedPackets()) { + receive_timestamp += TimeDelta::us(packet.delta_us()); + int64_t unwrapped_seq_num = + seq_num_unwrapper.Unwrap(packet.sequence_number()); + auto it = indices.find(unwrapped_seq_num); + if (it == indices.end()) { + RTC_LOG(LS_WARNING) << "Received feedback for unknown packet: " + << unwrapped_seq_num; + continue; + } + LoggedPacketInfo* sent = &packets[it->second]; + if (log_feedback_time - sent->log_packet_time > + TimeDelta::seconds(60)) { + RTC_LOG(LS_WARNING) + << "Received very late feedback, possibly due to wraparound."; + continue; + } + // Ignore if we already received feedback for this packet. + if (sent->log_feedback_time.IsFinite()) + continue; + sent->log_feedback_time = log_feedback_time; + sent->reported_recv_time = Timestamp::ms(receive_timestamp.ms()); + packet_feedbacks.push_back(sent); + } + if (packet_feedbacks.empty()) + return; + LoggedPacketInfo* last = packet_feedbacks.back(); + last->last_in_feedback = true; + for (LoggedPacketInfo* fb : packet_feedbacks) { + if (direction == PacketDirection::kOutgoingPacket) { + fb->feedback_hold_duration = + last->reported_recv_time - fb->reported_recv_time; + } else { + fb->feedback_hold_duration = + log_feedback_time - fb->log_packet_time; + } + } + }; RtcEventProcessor process; for (const auto& rtp_packets : rtp_packets_by_ssrc(direction)) { diff --git a/modules/congestion_controller/rtp/transport_feedback_adapter.cc b/modules/congestion_controller/rtp/transport_feedback_adapter.cc index bb2425db85..02e2088f14 100644 --- a/modules/congestion_controller/rtp/transport_feedback_adapter.cc +++ b/modules/congestion_controller/rtp/transport_feedback_adapter.cc @@ -43,9 +43,6 @@ PacketResult NetworkPacketFeedbackFromRtpPacketFeedback( } // namespace const int64_t kNoTimestamp = -1; const int64_t kSendTimeHistoryWindowMs = 60000; -const int64_t kBaseTimestampScaleFactor = - rtcp::TransportFeedback::kDeltaScaleFactor * (1 << 8); -const int64_t kBaseTimestampRangeSizeUs = kBaseTimestampScaleFactor * (1 << 24); TransportFeedbackAdapter::TransportFeedbackAdapter() : allow_duplicates_(field_trial::IsEnabled( @@ -191,26 +188,15 @@ DataSize TransportFeedbackAdapter::GetOutstandingData() const { std::vector TransportFeedbackAdapter::GetPacketFeedbackVector( const rtcp::TransportFeedback& feedback, Timestamp feedback_time) { - int64_t timestamp_us = feedback.GetBaseTimeUs(); - // Add timestamp deltas to a local time base selected on first packet arrival. // This won't be the true time base, but makes it easier to manually inspect // time stamps. if (last_timestamp_us_ == kNoTimestamp) { current_offset_ms_ = feedback_time.ms(); } else { - int64_t delta = timestamp_us - last_timestamp_us_; - - // Detect and compensate for wrap-arounds in base time. - if (std::abs(delta - kBaseTimestampRangeSizeUs) < std::abs(delta)) { - delta -= kBaseTimestampRangeSizeUs; // Wrap backwards. - } else if (std::abs(delta + kBaseTimestampRangeSizeUs) < std::abs(delta)) { - delta += kBaseTimestampRangeSizeUs; // Wrap forwards. - } - - current_offset_ms_ += delta / 1000; + current_offset_ms_ += feedback.GetBaseDeltaUs(last_timestamp_us_) / 1000; } - last_timestamp_us_ = timestamp_us; + last_timestamp_us_ = feedback.GetBaseTimeUs(); std::vector packet_feedback_vector; if (feedback.GetPacketStatusCount() == 0) { diff --git a/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.cc b/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.cc index ee8b93a6d7..9b1c812755 100644 --- a/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.cc +++ b/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.cc @@ -362,6 +362,18 @@ int64_t TransportFeedback::GetBaseTimeUs() const { return static_cast(base_time_ticks_) * kBaseScaleFactor; } +int64_t TransportFeedback::GetBaseDeltaUs(int64_t prev_timestamp_us) const { + int64_t delta = GetBaseTimeUs() - prev_timestamp_us; + + // Detect and compensate for wrap-arounds in base time. + if (std::abs(delta - kTimeWrapPeriodUs) < std::abs(delta)) { + delta -= kTimeWrapPeriodUs; // Wrap backwards. + } else if (std::abs(delta + kTimeWrapPeriodUs) < std::abs(delta)) { + delta += kTimeWrapPeriodUs; // Wrap forwards. + } + return delta; +} + // De-serialize packet. bool TransportFeedback::Parse(const CommonHeader& packet) { RTC_DCHECK_EQ(packet.type(), kPacketType); diff --git a/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h b/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h index 174ef6bcb5..c9407acc61 100644 --- a/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h +++ b/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h @@ -69,6 +69,9 @@ class TransportFeedback : public Rtpfb { // Get the reference time in microseconds, including any precision loss. int64_t GetBaseTimeUs() const; + // Get the unwrapped delta between current base time and |prev_timestamp_us|. + int64_t GetBaseDeltaUs(int64_t prev_timestamp_us) const; + // Does the feedback packet contain timestamp information? bool IncludeTimestamps() const { return include_timestamps_; }