zqz/platform-external-webrtc
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Improving robustness of feedback matching code in event log parser.

Browse Source 
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}
This commit is contained in:
Sebastian Jansson
2019-04-23 18:58:57 +02:00
committed by Commit Bot
parent 9a86275860
commit a1e4fbb253
5 changed files with 81 additions and 78 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
logging/BUILD.gn
View File

@ -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",

124
logging/rtc_event_log/rtc_event_log_parser.cc
View File

@ -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<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();
@ -1926,6 +1925,7 @@ 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,72 +1959,74 @@ std::vector<LoggedPacketInfo> 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<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)) {

18
modules/congestion_controller/rtp/transport_feedback_adapter.cc
View File

@ -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<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) {

12
modules/rtp_rtcp/source/rtcp_packet/transport_feedback.cc
View File

@ -362,6 +362,18 @@ int64_t TransportFeedback::GetBaseTimeUs() const {
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);

3
modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h
View File

@ -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_; }