aboutsummaryrefslogtreecommitdiff
path: root/logging
diff options
context:
space:
mode:
authorSebastian Jansson <srte@webrtc.org>2019-04-24 15:03:20 +0000
committerCommit Bot <commit-bot@chromium.org>2019-04-24 15:03:36 +0000
commit97bedae224c8fcc020fc7db0af3dfad1b4517354 (patch)
treeb26eefd727d385288c5a0f22e0e9a9608be5da46 /logging
parent637cd3ebd7bf5840bfba33debb9439dce8d119dd (diff)
downloadwebrtc-97bedae224c8fcc020fc7db0af3dfad1b4517354.tar.gz
Revert "Improving robustness of feedback matching code in event log parser."
This reverts commit a1e4fbb25371867349a0c2ed6ba62224735a2ec7. Reason for revert: Breaks downstream. Original change's description: > 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} TBR=terelius@webrtc.org,stefan@webrtc.org,srte@webrtc.org Change-Id: Icdf3231f5a32b6f63a903c7dffc8ca505680a72a No-Presubmit: true No-Tree-Checks: true No-Try: true Bug: webrtc:9883 Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/134105 Reviewed-by: Sebastian Jansson <srte@webrtc.org> Commit-Queue: Sebastian Jansson <srte@webrtc.org> Cr-Commit-Position: refs/heads/master@{#27742}
Diffstat (limited to 'logging')
-rw-r--r--logging/BUILD.gn2
-rw-r--r--logging/rtc_event_log/rtc_event_log_parser.cc126
2 files changed, 63 insertions, 65 deletions
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<LoggedPacketInfo> ParsedRtcEventLog::GetPacketInfos(
AddSendStreamInfos(&streams, video_send_configs(), LoggedMediaType::kVideo);
}
+ TransportFeedbackAdapter feedback_adapter;
std::vector<OverheadChangeEvent> overheads =
GetOverheadChangingEvents(GetRouteChanges(), direction);
auto overhead_iter = overheads.begin();
@@ -1925,7 +1926,6 @@ std::vector<LoggedPacketInfo> ParsedRtcEventLog::GetPacketInfos(
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,74 +1959,72 @@ std::vector<LoggedPacketInfo> 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_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 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& 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()));
- }
- 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;
- }
+ sent->feedback_hold_duration =
+ Timestamp::ms(logged.log_time_ms()) - sent->log_packet_time;
}
- };
+ }
+ sent->last_in_feedback = (&fb == &last_fb);
+ }
+ };
RtcEventProcessor process;
for (const auto& rtp_packets : rtp_packets_by_ssrc(direction)) {