diff --git a/logging/BUILD.gn b/logging/BUILD.gn index 2258a7356a..e1d5289cb0 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 4d234fcc22..289744da27 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/include/module_common_types.h" +#include "modules/congestion_controller/rtp/transport_feedback_adapter.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,6 +1918,7 @@ 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(); @@ -1925,7 +1926,6 @@ 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,74 +1959,72 @@ std::vector ParsedRtcEventLog::GetPacketInfos( } LoggedPacketInfo logged(rtp, stream->media_type, stream->rtx, capture_time); logged.overhead = current_overhead; - 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(); + 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(); } packets.push_back(logged); }; - Timestamp feedback_base_time = Timestamp::MinusInfinity(); - Timestamp last_feedback_base_time = Timestamp::MinusInfinity(); + 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; - 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; + 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; } else { - feedback_base_time += TimeDelta::us( - feedback.GetBaseDeltaUs(last_feedback_base_time.us())); + sent->feedback_hold_duration = + Timestamp::ms(logged.log_time_ms()) - sent->log_packet_time; } - 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; - } - } - }; + } + sent->last_in_feedback = (&fb == &last_fb); + } + }; 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 02e2088f14..bb2425db85 100644 --- a/modules/congestion_controller/rtp/transport_feedback_adapter.cc +++ b/modules/congestion_controller/rtp/transport_feedback_adapter.cc @@ -43,6 +43,9 @@ 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( @@ -188,15 +191,26 @@ 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 { - current_offset_ms_ += feedback.GetBaseDeltaUs(last_timestamp_us_) / 1000; + 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; } - last_timestamp_us_ = feedback.GetBaseTimeUs(); + last_timestamp_us_ = timestamp_us; 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 9b1c812755..ee8b93a6d7 100644 --- a/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.cc +++ b/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.cc @@ -362,18 +362,6 @@ 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 c9407acc61..174ef6bcb5 100644 --- a/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h +++ b/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h @@ -69,9 +69,6 @@ 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_; }