Implement support for RFC8888 in ParsedRtcEventLog::GetPacketInfos
This allow plotting per packet delay if RFC8888 feedback is utilized
Bug: webrtc:436707095
Change-Id: I1769fa25fd200b80009d36158858a82b01264696
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/403380
Reviewed-by: Björn Terelius <terelius@webrtc.org>
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#45302}
diff --git a/logging/BUILD.gn b/logging/BUILD.gn
index 85d3db5..1870196 100644
--- a/logging/BUILD.gn
+++ b/logging/BUILD.gn
@@ -535,6 +535,7 @@
"../api/video:video_frame",
"../modules:module_api_public",
"../modules/audio_coding:audio_network_adaptor",
+ "../modules/rtp_rtcp:ntp_time_util",
"../modules/rtp_rtcp:rtp_rtcp_format",
"../rtc_base:checks",
"../rtc_base:copy_on_write_buffer",
diff --git a/logging/rtc_event_log/rtc_event_log_parser.cc b/logging/rtc_event_log/rtc_event_log_parser.cc
index 35492d1..cb5ca71 100644
--- a/logging/rtc_event_log/rtc_event_log_parser.cc
+++ b/logging/rtc_event_log/rtc_event_log_parser.cc
@@ -76,6 +76,7 @@
#include "modules/rtp_rtcp/include/rtp_cvo.h"
#include "modules/rtp_rtcp/include/rtp_header_extension_map.h"
#include "modules/rtp_rtcp/include/rtp_rtcp_defines.h"
+#include "modules/rtp_rtcp/source/ntp_time_util.h"
#include "modules/rtp_rtcp/source/rtcp_packet/bye.h"
#include "modules/rtp_rtcp/source/rtcp_packet/common_header.h"
#include "modules/rtp_rtcp/source/rtcp_packet/congestion_control_feedback.h"
@@ -2397,10 +2398,36 @@
GetOverheadChangingEvents(GetRouteChanges(), direction);
auto overhead_iter = overheads.begin();
std::vector<LoggedPacketInfo> packets;
- std::map<int64_t, size_t> indices;
+ std::map</*unwrapped transport sequence number*/ int64_t,
+ /*index into packets*/ size_t>
+ twcc_indices;
+ RtpSequenceNumberUnwrapper transport_seq_num_unwrapper;
+
+ class PerSSRCInfo {
+ public:
+ void AddPacketIndex(uint16_t rtp_sequence_number, size_t index) {
+ packet_indices_[rtp_seq_num_unwrapper_.Unwrap(rtp_sequence_number)] =
+ index;
+ }
+ std::optional<size_t> FindPacketIndex(uint16_t rtp_sequence_number) {
+ auto it = packet_indices_.find(
+ rtp_seq_num_unwrapper_.Unwrap(rtp_sequence_number));
+ if (it == packet_indices_.end()) {
+ return std::nullopt;
+ }
+ return it->second;
+ }
+
+ private:
+ RtpSequenceNumberUnwrapper rtp_seq_num_unwrapper_;
+ std::map</*unwrapped rtp sequence number*/ int64_t,
+ /*index into packets*/ size_t>
+ packet_indices_;
+ };
+ std::map</*ssrc*/ uint32_t, PerSSRCInfo> ccfb_indices;
+
uint16_t current_overhead = kDefaultOverhead;
Timestamp last_log_time = Timestamp::Zero();
- RtpSequenceNumberUnwrapper seq_num_unwrapper;
auto advance_time = [&](Timestamp new_log_time) {
if (overhead_iter != overheads.end() &&
@@ -2412,8 +2439,9 @@
// therefore we don't want to match up sequence numbers as we might have had
// a wraparound.
if (new_log_time - last_log_time > TimeDelta::Seconds(30)) {
- seq_num_unwrapper.Reset();
- indices.clear();
+ transport_seq_num_unwrapper.Reset();
+ twcc_indices.clear();
+ ccfb_indices.clear();
}
RTC_DCHECK_GE(new_log_time, last_log_time);
last_log_time = new_log_time;
@@ -2444,25 +2472,28 @@
if (logged.has_transport_seq_no) {
logged.log_feedback_time = Timestamp::PlusInfinity();
int64_t unwrapped_seq_num =
- seq_num_unwrapper.Unwrap(logged.transport_seq_no);
- if (indices.find(unwrapped_seq_num) != indices.end()) {
+ transport_seq_num_unwrapper.Unwrap(logged.transport_seq_no);
+ if (twcc_indices.find(unwrapped_seq_num) != twcc_indices.end()) {
Timestamp prev_log_packet_time =
- packets[indices[unwrapped_seq_num]].log_packet_time;
+ packets[twcc_indices[unwrapped_seq_num]].log_packet_time;
RTC_LOG(LS_WARNING)
<< "Repeated sent packet sequence number: " << unwrapped_seq_num
<< " Packet time:" << prev_log_packet_time.seconds() << "s vs "
<< logged.log_packet_time.seconds()
<< "s at:" << rtp.log_time_ms() / 1000;
}
- indices[unwrapped_seq_num] = packets.size();
+ twcc_indices[unwrapped_seq_num] = packets.size();
+ } else {
+ ccfb_indices[rtp.header.ssrc].AddPacketIndex(rtp.header.sequenceNumber,
+ packets.size());
}
packets.push_back(logged);
};
- Timestamp feedback_base_time = Timestamp::MinusInfinity();
- Timestamp last_feedback_base_time = Timestamp::MinusInfinity();
+ Timestamp twcc_feedback_base_time = Timestamp::MinusInfinity();
+ Timestamp twcc_last_feedback_base_time = Timestamp::MinusInfinity();
- auto feedback_handler =
+ auto twcc_feedback_handler =
[&](const LoggedRtcpPacketTransportFeedback& logged_rtcp) {
auto log_feedback_time = logged_rtcp.log_time();
advance_time(log_feedback_time);
@@ -2470,21 +2501,23 @@
// 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.IsFinite()) {
- feedback_base_time = log_feedback_time;
+ if (!twcc_last_feedback_base_time.IsFinite()) {
+ twcc_feedback_base_time = log_feedback_time;
} else {
- feedback_base_time += feedback.GetBaseDelta(last_feedback_base_time);
+ twcc_feedback_base_time +=
+ feedback.GetBaseDelta(twcc_last_feedback_base_time);
}
- last_feedback_base_time = feedback.BaseTime();
+ twcc_last_feedback_base_time = feedback.BaseTime();
std::vector<LoggedPacketInfo*> packet_feedbacks;
packet_feedbacks.reserve(feedback.GetPacketStatusCount());
std::vector<int64_t> unknown_seq_nums;
feedback.ForAllPackets([&](uint16_t sequence_number,
TimeDelta delta_since_base) {
- int64_t unwrapped_seq_num = seq_num_unwrapper.Unwrap(sequence_number);
- auto it = indices.find(unwrapped_seq_num);
- if (it == indices.end()) {
+ int64_t unwrapped_seq_num =
+ transport_seq_num_unwrapper.Unwrap(sequence_number);
+ auto it = twcc_indices.find(unwrapped_seq_num);
+ if (it == twcc_indices.end()) {
unknown_seq_nums.push_back(unwrapped_seq_num);
return;
}
@@ -2497,7 +2530,8 @@
}
if (delta_since_base.IsFinite()) {
if (sent->reported_recv_time.IsInfinite()) {
- sent->reported_recv_time = feedback_base_time + delta_since_base;
+ sent->reported_recv_time =
+ twcc_feedback_base_time + delta_since_base;
sent->log_feedback_time = log_feedback_time;
}
} else {
@@ -2532,15 +2566,81 @@
}
};
+ Timestamp ccfb_feedback_offset = Timestamp::MinusInfinity();
+ std::optional<uint32_t> last_feedback_compact_ntp_time_;
+ auto ccfb_feedback_handler =
+ [&](const LoggedRtcpCongestionControlFeedback& logged_rtcp) {
+ Timestamp log_feedback_time = logged_rtcp.log_time();
+ advance_time(log_feedback_time);
+ const rtcp::CongestionControlFeedback& feedback =
+ logged_rtcp.congestion_feedback;
+
+ if (ccfb_feedback_offset.IsInfinite()) {
+ ccfb_feedback_offset = log_feedback_time;
+ }
+ TimeDelta feedback_delta =
+ last_feedback_compact_ntp_time_.has_value()
+ ? CompactNtpIntervalToTimeDelta(
+ feedback.report_timestamp_compact_ntp() -
+ *last_feedback_compact_ntp_time_)
+ : TimeDelta::Zero();
+ last_feedback_compact_ntp_time_ =
+ feedback.report_timestamp_compact_ntp();
+ if (feedback_delta < TimeDelta::Zero()) {
+ RTC_LOG(LS_WARNING)
+ << "Unexpected feedback ntp time delta " << feedback_delta << ".";
+ ccfb_feedback_offset = log_feedback_time;
+ } else {
+ ccfb_feedback_offset += feedback_delta;
+ }
+ for (const rtcp::CongestionControlFeedback::PacketInfo& packet :
+ feedback.packets()) {
+ std::optional<size_t> packets_index =
+ ccfb_indices[packet.ssrc].FindPacketIndex(packet.sequence_number);
+ if (!packets_index.has_value()) {
+ RTC_LOG(LS_WARNING)
+ << " Got feedback for unknown packet, ssrc: " << packet.ssrc
+ << " rtp seqno:" << packet.sequence_number;
+ continue;
+ }
+ LoggedPacketInfo* sent = &packets[*packets_index];
+ RTC_DCHECK_EQ(packet.ssrc, sent->ssrc);
+ RTC_DCHECK_EQ(packet.sequence_number, sent->stream_seq_no);
+ if (log_feedback_time - sent->log_packet_time >
+ TimeDelta::Seconds(60)) {
+ RTC_LOG(LS_WARNING)
+ << "Received very late feedback, possibly due to wraparound.";
+ return;
+ }
+ if (packet.arrival_time_offset.IsFinite()) {
+ if (sent->reported_recv_time.IsInfinite()) {
+ sent->log_feedback_time = log_feedback_time;
+ sent->feedback_hold_duration = packet.arrival_time_offset;
+ sent->reported_recv_time =
+ ccfb_feedback_offset - packet.arrival_time_offset;
+ }
+ } else {
+ if (sent->log_feedback_time.IsInfinite()) {
+ sent->log_feedback_time = log_feedback_time;
+ sent->reported_recv_time = Timestamp::PlusInfinity();
+ }
+ }
+ }
+ };
+
RtcEventProcessor process;
for (const auto& rtp_packets : rtp_packets_by_ssrc(direction)) {
process.AddEvents(rtp_packets.packet_view, rtp_handler, direction);
}
if (direction == PacketDirection::kOutgoingPacket) {
- process.AddEvents(incoming_transport_feedback_, feedback_handler,
+ process.AddEvents(incoming_transport_feedback_, twcc_feedback_handler,
+ PacketDirection::kIncomingPacket);
+ process.AddEvents(incoming_congestion_feedback_, ccfb_feedback_handler,
PacketDirection::kIncomingPacket);
} else {
- process.AddEvents(outgoing_transport_feedback_, feedback_handler,
+ process.AddEvents(outgoing_transport_feedback_, twcc_feedback_handler,
+ PacketDirection::kOutgoingPacket);
+ process.AddEvents(outgoing_congestion_feedback_, ccfb_feedback_handler,
PacketDirection::kOutgoingPacket);
}
process.ProcessEventsInOrder();
diff --git a/logging/rtc_event_log/rtc_event_processor_order.h b/logging/rtc_event_log/rtc_event_processor_order.h
index 7c2c7e8..a9a4750 100644
--- a/logging/rtc_event_log/rtc_event_processor_order.h
+++ b/logging/rtc_event_log/rtc_event_processor_order.h
@@ -439,6 +439,20 @@
};
template <>
+class TieBreaker<LoggedRtcpCongestionControlFeedback> {
+ public:
+ static constexpr int type_order(PacketDirection direction) {
+ return static_cast<int>(direction == PacketDirection::kIncomingPacket
+ ? TypeOrder::RtcpIn
+ : TypeOrder::RtcpOut);
+ }
+ static std::optional<uint16_t> transport_seq_num_accessor(
+ const LoggedRtcpCongestionControlFeedback&) {
+ return std::optional<uint16_t>();
+ }
+};
+
+template <>
class TieBreaker<LoggedRtcpPacketSenderReport> {
public:
static constexpr int type_order(PacketDirection direction) {
