Improving robustness of feedback matching code in event log parser.
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 <stefan@webrtc.org>
Reviewed-by: Björn Terelius <terelius@webrtc.org>
Commit-Queue: Sebastian Jansson <srte@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#27739}
diff --git a/logging/BUILD.gn b/logging/BUILD.gn
index e1d5289..2258a73 100644
--- a/logging/BUILD.gn
+++ b/logging/BUILD.gn
@@ -335,8 +335,8 @@
"../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 289744d..4d234fc 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 @@
AddSendStreamInfos(&streams, video_send_configs(), LoggedMediaType::kVideo);
}
- TransportFeedbackAdapter feedback_adapter;
std::vector<OverheadChangeEvent> overheads =
GetOverheadChangingEvents(GetRouteChanges(), direction);
auto overhead_iter = overheads.begin();
@@ -1926,6 +1925,7 @@
std::map<int64_t, size_t> 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 @@
}
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<LoggedPacketInfo*> 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 bb2425d..02e2088 100644
--- a/modules/congestion_controller/rtp/transport_feedback_adapter.cc
+++ b/modules/congestion_controller/rtp/transport_feedback_adapter.cc
@@ -43,9 +43,6 @@
} // 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 @@
std::vector<PacketFeedback> 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<PacketFeedback> 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 ee8b93a..9b1c812 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 @@
return static_cast<int64_t>(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 174ef6b..c9407ac 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 @@
// 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_; }
