admin/webrtc_m130
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

stats: add frame assembly time stats

Browse Source 
implements a total frame assembly time statistic that measures the
cumulative time between the arrival of the first packet of a frame
(the lowest reception time) and the time all packets of the frame have
been received (i.e. the highest reception time)

This is similar to totalProcessingDelay
  https://w3c.github.io/webrtc-stats/#dom-rtcinboundrtpstreamstats-totalprocessingdelay
in particular with respect to only being incremented for frames that are being decoded but does not include the amount of time spent decoding the frame.

This statistic is useful for evaluating mechanisms like NACK and FEC
and gives some insight into the behavior of the pacer sending the
packets.
Note that for frames with just a single packet the assembly time will be zero. In order to calculate an average assembly time an additional frames_assembled_from_multiple_packets counter for frames with more than a single packet is added.

Currently this is a nonstandard stat so will only show up in webrtc-internals and not in getStats. Formally it can be defined as

totalAssemblyTime of type double
	Only exists for video. 	The sum of the time, in seconds, each video frame takes from the time the first RTP packet is received (reception timestamp) and to the time the last RTP packet of a frame is received.
    Given the complexities involved, the time of arrival or the reception timestamp is measured as close to the network layer as possible.

    This metric is not incremented for frames that are not decoded, i.e., framesDropped, partialFramesLost or frames that fail decoding for other reasons (if any). Only incremented for frames consisting of more than one RTP packet. The average frame assembly time can be calculated by dividing the totalAssemblyTime with framesAssembledFromMultiplePacket.

framesAssembledFromMultiplePacket of type unsigned long
	Only exists for video. It represents the total number of frames correctly decoded for this RTP stream that consist of more than one RTP packet.
	For such frames the totalAssemblyTime is incremented.

BUG=webrtc:13986

Change-Id: Ie0ae431d72a57a0001c3240daba8eda35955f04e
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/260920
Reviewed-by: Harald Alvestrand <hta@webrtc.org>
Reviewed-by: Henrik Boström <hbos@webrtc.org>
Commit-Queue: Harald Alvestrand <hta@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#36922}
This commit is contained in:
Philipp Hancke 2022-05-05 15:55:36 +02:00 committed by WebRTC LUCI CQ
parent 94c09169a2
commit 0359ba2225
12 changed files with 145 additions and 16 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
api/stats/rtcstats_objects.h
View File

@ -536,6 +536,9 @@ class RTC_EXPORT RTCInboundRTPStreamStats final
RTCStatsMember<uint32_t> frames_dropped;
RTCStatsMember<double> total_decode_time;
RTCStatsMember<double> total_processing_delay;
// TODO(bugs.webrtc.org/13986): standardize
RTCNonStandardStatsMember<double> total_assembly_time;
RTCNonStandardStatsMember<uint32_t> frames_assembled_from_multiple_packets;
RTCStatsMember<double> total_inter_frame_delay;
RTCStatsMember<double> total_squared_inter_frame_delay;
// https://henbos.github.io/webrtc-provisional-stats/#dom-rtcinboundrtpstreamstats-contenttype

3
call/video_receive_stream.h
View File

@ -108,6 +108,9 @@ class VideoReceiveStream : public MediaReceiveStream {
uint64_t total_decode_time_ms = 0;
// https://w3c.github.io/webrtc-stats/#dom-rtcinboundrtpstreamstats-totalprocessingdelay
webrtc::TimeDelta total_processing_delay = webrtc::TimeDelta::Millis(0);
// TODO(bugs.webrtc.org/13986): standardize
webrtc::TimeDelta total_assembly_time = webrtc::TimeDelta::Millis(0);
uint32_t frames_assembled_from_multiple_packets = 0;
// Total inter frame delay in seconds.
// https://w3c.github.io/webrtc-stats/#dom-rtcinboundrtpstreamstats-totalinterframedelay
double total_inter_frame_delay = 0;

2
media/base/media_channel.h
View File

@ -615,6 +615,8 @@ struct VideoReceiverInfo : public MediaReceiverInfo {
uint64_t total_decode_time_ms = 0;
// https://w3c.github.io/webrtc-stats/#dom-rtcinboundrtpstreamstats-totalprocessingdelay
webrtc::TimeDelta total_processing_delay = webrtc::TimeDelta::Millis(0);
webrtc::TimeDelta total_assembly_time = webrtc::TimeDelta::Millis(0);
uint32_t frames_assembled_from_multiple_packets = 0;
double total_inter_frame_delay = 0;
double total_squared_inter_frame_delay = 0;
int64_t interframe_delay_max_ms = -1;

3
media/engine/webrtc_video_engine.cc
View File

@ -3180,6 +3180,9 @@ WebRtcVideoChannel::WebRtcVideoReceiveStream::GetVideoReceiverInfo(
info.qp_sum = stats.qp_sum;
info.total_decode_time_ms = stats.total_decode_time_ms;
info.total_processing_delay = stats.total_processing_delay;
info.total_assembly_time = stats.total_assembly_time;
info.frames_assembled_from_multiple_packets =
stats.frames_assembled_from_multiple_packets;
info.last_packet_received_timestamp_ms =
stats.rtp_stats.last_packet_received_timestamp_ms;
info.estimated_playout_ntp_timestamp_ms =

5
media/engine/webrtc_video_engine_unittest.cc
View File

@ -6116,6 +6116,8 @@ TEST_F(WebRtcVideoChannelTest, GetStatsTranslatesDecodeStatsCorrectly) {
stats.frames_decoded = 14;
stats.qp_sum = 15;
stats.total_decode_time_ms = 16;
stats.total_assembly_time = webrtc::TimeDelta::Millis(4);
stats.frames_assembled_from_multiple_packets = 2;
stream->SetStats(stats);
cricket::VideoMediaInfo info;
@ -6144,6 +6146,9 @@ TEST_F(WebRtcVideoChannelTest, GetStatsTranslatesDecodeStatsCorrectly) {
info.receivers[0].key_frames_decoded);
EXPECT_EQ(stats.qp_sum, info.receivers[0].qp_sum);
EXPECT_EQ(stats.total_decode_time_ms, info.receivers[0].total_decode_time_ms);
EXPECT_EQ(stats.total_assembly_time, info.receivers[0].total_assembly_time);
EXPECT_EQ(stats.frames_assembled_from_multiple_packets,
info.receivers[0].frames_assembled_from_multiple_packets);
}
TEST_F(WebRtcVideoChannelTest,

5
pc/rtc_stats_collector.cc
View File

@ -560,6 +560,11 @@ void SetInboundRTPStreamStatsFromVideoReceiverInfo(
inbound_video->total_processing_delay =
static_cast<double>(video_receiver_info.total_processing_delay.ms()) /
rtc::kNumMillisecsPerSec;
inbound_video->total_assembly_time =
static_cast<double>(video_receiver_info.total_assembly_time.ms()) /
rtc::kNumMillisecsPerSec;
inbound_video->frames_assembled_from_multiple_packets =
video_receiver_info.frames_assembled_from_multiple_packets;
inbound_video->total_inter_frame_delay =
video_receiver_info.total_inter_frame_delay;
inbound_video->total_squared_inter_frame_delay =

5
pc/rtc_stats_collector_unittest.cc
View File

@ -2141,6 +2141,9 @@ TEST_F(RTCStatsCollectorTest, CollectRTCInboundRTPStreamStats_Video) {
video_media_info.receivers[0].total_decode_time_ms = 9000;
video_media_info.receivers[0].total_processing_delay =
webrtc::TimeDelta::Millis(600);
video_media_info.receivers[0].total_assembly_time =
webrtc::TimeDelta::Millis(500);
video_media_info.receivers[0].frames_assembled_from_multiple_packets = 23;
video_media_info.receivers[0].total_inter_frame_delay = 0.123;
video_media_info.receivers[0].total_squared_inter_frame_delay = 0.00456;
video_media_info.receivers[0].jitter_ms = 1199;
@ -2191,6 +2194,8 @@ TEST_F(RTCStatsCollectorTest, CollectRTCInboundRTPStreamStats_Video) {
// `expected_video.qp_sum` should be undefined.
expected_video.total_decode_time = 9.0;
expected_video.total_processing_delay = 0.6;
expected_video.total_assembly_time = 0.5;
expected_video.frames_assembled_from_multiple_packets = 23;
expected_video.total_inter_frame_delay = 0.123;
expected_video.total_squared_inter_frame_delay = 0.00456;
expected_video.jitter = 1.199;

7
pc/rtc_stats_integrationtest.cc
View File

@ -916,6 +916,10 @@ class RTCStatsReportVerifier {
inbound_stream.total_decode_time);
verifier.TestMemberIsNonNegative<double>(
inbound_stream.total_processing_delay);
verifier.TestMemberIsNonNegative<double>(
inbound_stream.total_assembly_time);
verifier.TestMemberIsDefined(
inbound_stream.frames_assembled_from_multiple_packets);
verifier.TestMemberIsNonNegative<double>(
inbound_stream.total_inter_frame_delay);
verifier.TestMemberIsNonNegative<double>(
@ -929,6 +933,9 @@ class RTCStatsReportVerifier {
verifier.TestMemberIsUndefined(inbound_stream.frames_dropped);
verifier.TestMemberIsUndefined(inbound_stream.total_decode_time);
verifier.TestMemberIsUndefined(inbound_stream.total_processing_delay);
verifier.TestMemberIsUndefined(inbound_stream.total_assembly_time);
verifier.TestMemberIsUndefined(
inbound_stream.frames_assembled_from_multiple_packets);
verifier.TestMemberIsUndefined(inbound_stream.total_inter_frame_delay);
verifier.TestMemberIsUndefined(
inbound_stream.total_squared_inter_frame_delay);

8
stats/rtcstats_objects.cc
View File

@ -708,6 +708,8 @@ WEBRTC_RTCSTATS_IMPL(
&frames_dropped,
&total_decode_time,
&total_processing_delay,
&total_assembly_time,
&frames_assembled_from_multiple_packets,
&total_inter_frame_delay,
&total_squared_inter_frame_delay,
&content_type,
@ -764,6 +766,9 @@ RTCInboundRTPStreamStats::RTCInboundRTPStreamStats(std::string&& id,
frames_dropped("framesDropped"),
total_decode_time("totalDecodeTime"),
total_processing_delay("totalProcessingDelay"),
total_assembly_time("totalAssemblyTime"),
frames_assembled_from_multiple_packets(
"framesAssembledFromMultiplePackets"),
total_inter_frame_delay("totalInterFrameDelay"),
total_squared_inter_frame_delay("totalSquaredInterFrameDelay"),
content_type("contentType"),
@ -816,6 +821,9 @@ RTCInboundRTPStreamStats::RTCInboundRTPStreamStats(
frames_dropped(other.frames_dropped),
total_decode_time(other.total_decode_time),
total_processing_delay(other.total_processing_delay),
total_assembly_time(other.total_assembly_time),
frames_assembled_from_multiple_packets(
other.frames_assembled_from_multiple_packets),
total_inter_frame_delay(other.total_inter_frame_delay),
total_squared_inter_frame_delay(other.total_squared_inter_frame_delay),
content_type(other.content_type),

27
video/receive_statistics_proxy2.cc
View File

@ -833,23 +833,31 @@ void ReceiveStatisticsProxy::OnDecodedFrame(const VideoFrame& frame,
webrtc::TimeDelta processing_delay = webrtc::TimeDelta::Millis(0);
webrtc::Timestamp current_time = clock_->CurrentTime();
// TODO(bugs.webrtc.org/13984): some tests do not fill packet_infos().
webrtc::TimeDelta assembly_time = webrtc::TimeDelta::Millis(0);
if (frame.packet_infos().size() > 0) {
auto first_packet = std::min_element(
const auto [first_packet, last_packet] = std::minmax_element(
frame.packet_infos().cbegin(), frame.packet_infos().cend(),
[](const webrtc::RtpPacketInfo& a, const webrtc::RtpPacketInfo& b) {
return a.receive_time() < b.receive_time();
});
processing_delay = current_time - first_packet->receive_time();
if (first_packet->receive_time().IsFinite()) {
processing_delay = current_time - first_packet->receive_time();
// Extract frame assembly time (i.e. time between earliest and latest
// packet arrival). Note: for single-packet frames this will be 0.
assembly_time =
last_packet->receive_time() - first_packet->receive_time();
}
}
// See VCMDecodedFrameCallback::Decoded for more info on what thread/queue we
// may be on. E.g. on iOS this gets called on
// "com.apple.coremedia.decompressionsession.clientcallback"
VideoFrameMetaData meta(frame, current_time);
worker_thread_->PostTask(ToQueuedTask(task_safety_, [meta, qp, decode_time_ms,
processing_delay,
content_type, this]() {
OnDecodedFrame(meta, qp, decode_time_ms, processing_delay, content_type);
}));
worker_thread_->PostTask(
ToQueuedTask(task_safety_, [meta, qp, decode_time_ms, processing_delay,
assembly_time, content_type, this]() {
OnDecodedFrame(meta, qp, decode_time_ms, processing_delay,
assembly_time, content_type);
}));
}
void ReceiveStatisticsProxy::OnDecodedFrame(
@ -857,6 +865,7 @@ void ReceiveStatisticsProxy::OnDecodedFrame(
absl::optional<uint8_t> qp,
int32_t decode_time_ms,
webrtc::TimeDelta processing_delay,
webrtc::TimeDelta assembly_time,
VideoContentType content_type) {
RTC_DCHECK_RUN_ON(&main_thread_);
@ -898,6 +907,10 @@ void ReceiveStatisticsProxy::OnDecodedFrame(
stats_.decode_ms = decode_time_ms;
stats_.total_decode_time_ms += decode_time_ms;
stats_.total_processing_delay += processing_delay;
stats_.total_assembly_time += assembly_time;
if (!assembly_time.IsZero()) {
++stats_.frames_assembled_from_multiple_packets;
}
if (enable_decode_time_histograms_) {
UpdateDecodeTimeHistograms(frame_meta.width, frame_meta.height,
decode_time_ms);

3
video/receive_statistics_proxy2.h
View File

@ -68,7 +68,8 @@ class ReceiveStatisticsProxy : public VCMReceiveStatisticsCallback,
void OnDecodedFrame(const VideoFrameMetaData& frame_meta,
absl::optional<uint8_t> qp,
int32_t decode_time_ms,
webrtc::TimeDelta processing_delay_ms,
webrtc::TimeDelta processing_delay,
webrtc::TimeDelta assembly_time,
VideoContentType content_type);
void OnSyncOffsetUpdated(int64_t video_playout_ntp_ms,

90
video/receive_statistics_proxy2_unittest.cc
View File

@ -213,6 +213,72 @@ TEST_F(ReceiveStatisticsProxy2Test, OnDecodedFrameIncreasesProcessingDelay) {
statistics_proxy_->GetStats().total_processing_delay);
}
TEST_F(ReceiveStatisticsProxy2Test, OnDecodedFrameIncreasesAssemblyTime) {
const TimeDelta kAssemblyTime = TimeDelta::Millis(7);
EXPECT_EQ(0u, statistics_proxy_->GetStats().frames_decoded);
webrtc::VideoFrame frame = CreateFrame(kWidth, kHeight);
TimeDelta expected_total_assembly_time = TimeDelta::Millis(0);
unsigned int expected_frames_decoded = 0;
unsigned int expected_frames_assembled_from_multiple_packets = 0;
// A single-packet frame will not increase total assembly time
// and frames assembled.
RtpPacketInfos::vector_type single_packet_frame = {
RtpPacketInfo({}, {}, {}, {}, {}, Now())};
frame.set_packet_infos(RtpPacketInfos(single_packet_frame));
statistics_proxy_->OnDecodedFrame(frame, absl::nullopt, 1,
VideoContentType::UNSPECIFIED);
++expected_frames_decoded;
loop_.Flush();
EXPECT_EQ(expected_total_assembly_time,
statistics_proxy_->GetStats().total_assembly_time);
EXPECT_EQ(
expected_frames_assembled_from_multiple_packets,
statistics_proxy_->GetStats().frames_assembled_from_multiple_packets);
// In an ordered frame the first and last packet matter.
RtpPacketInfos::vector_type ordered_frame = {
RtpPacketInfo({}, {}, {}, {}, {}, Now()),
RtpPacketInfo({}, {}, {}, {}, {}, Now() + kAssemblyTime),
RtpPacketInfo({}, {}, {}, {}, {}, Now() + 2 * kAssemblyTime),
};
frame.set_packet_infos(RtpPacketInfos(ordered_frame));
statistics_proxy_->OnDecodedFrame(frame, 1u, 3,
VideoContentType::UNSPECIFIED);
++expected_frames_decoded;
++expected_frames_assembled_from_multiple_packets;
expected_total_assembly_time += 2 * kAssemblyTime;
loop_.Flush();
EXPECT_EQ(expected_frames_decoded,
statistics_proxy_->GetStats().frames_decoded);
EXPECT_EQ(expected_total_assembly_time,
statistics_proxy_->GetStats().total_assembly_time);
EXPECT_EQ(
expected_frames_assembled_from_multiple_packets,
statistics_proxy_->GetStats().frames_assembled_from_multiple_packets);
// "First" and "last" are in receive time, not sequence number.
RtpPacketInfos::vector_type unordered_frame = {
RtpPacketInfo({}, {}, {}, {}, {}, Now() + 2 * kAssemblyTime),
RtpPacketInfo({}, {}, {}, {}, {}, Now()),
RtpPacketInfo({}, {}, {}, {}, {}, Now() + kAssemblyTime),
};
frame.set_packet_infos(RtpPacketInfos(unordered_frame));
statistics_proxy_->OnDecodedFrame(frame, 1u, 3,
VideoContentType::UNSPECIFIED);
++expected_frames_decoded;
++expected_frames_assembled_from_multiple_packets;
expected_total_assembly_time += 2 * kAssemblyTime;
loop_.Flush();
EXPECT_EQ(expected_frames_decoded,
statistics_proxy_->GetStats().frames_decoded);
EXPECT_EQ(expected_total_assembly_time,
statistics_proxy_->GetStats().total_assembly_time);
EXPECT_EQ(
expected_frames_assembled_from_multiple_packets,
statistics_proxy_->GetStats().frames_assembled_from_multiple_packets);
}
TEST_F(ReceiveStatisticsProxy2Test, OnDecodedFrameIncreasesQpSum) {
EXPECT_EQ(absl::nullopt, statistics_proxy_->GetStats().qp_sum);
webrtc::VideoFrame frame = CreateFrame(kWidth, kHeight);
@ -1388,7 +1454,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, FreezesAreReported) {
for (int i = 0; i < kMinRequiredSamples; ++i) {
VideoFrameMetaData meta = MetaData(frame);
statistics_proxy_->OnDecodedFrame(
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
fake_clock_.AdvanceTimeMilliseconds(kInterFrameDelayMs);
}
@ -1396,7 +1463,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, FreezesAreReported) {
fake_clock_.AdvanceTimeMilliseconds(kFreezeDelayMs);
VideoFrameMetaData meta = MetaData(frame);
statistics_proxy_->OnDecodedFrame(
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
FlushAndUpdateHistograms(absl::nullopt, StreamDataCounters(), nullptr);
@ -1480,7 +1548,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, PausesAreIgnored) {
for (int i = 0; i <= kMinRequiredSamples; ++i) {
VideoFrameMetaData meta = MetaData(frame);
statistics_proxy_->OnDecodedFrame(
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
fake_clock_.AdvanceTimeMilliseconds(kInterFrameDelayMs);
}
@ -1491,7 +1560,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, PausesAreIgnored) {
for (int i = 0; i <= kMinRequiredSamples * 3; ++i) {
VideoFrameMetaData meta = MetaData(frame);
statistics_proxy_->OnDecodedFrame(
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
fake_clock_.AdvanceTimeMilliseconds(kInterFrameDelayMs);
}
@ -1553,7 +1623,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, TimeInHdReported) {
for (int i = 0; i < kMinRequiredSamples; ++i) {
VideoFrameMetaData meta = MetaData(frame_hd);
statistics_proxy_->OnDecodedFrame(
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
fake_clock_.AdvanceTimeMilliseconds(kInterFrameDelayMs);
}
@ -1561,7 +1632,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, TimeInHdReported) {
for (int i = 0; i < 2 * kMinRequiredSamples; ++i) {
VideoFrameMetaData meta = MetaData(frame_sd);
statistics_proxy_->OnDecodedFrame(
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, absl::nullopt, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
fake_clock_.AdvanceTimeMilliseconds(kInterFrameDelayMs);
}
@ -1591,7 +1663,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, TimeInBlockyVideoReported) {
for (int i = 0; i < kMinRequiredSamples; ++i) {
VideoFrameMetaData meta = MetaData(frame);
statistics_proxy_->OnDecodedFrame(
meta, kLowQp, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, kLowQp, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
fake_clock_.AdvanceTimeMilliseconds(kInterFrameDelayMs);
}
@ -1599,7 +1672,8 @@ TEST_P(ReceiveStatisticsProxy2TestWithContent, TimeInBlockyVideoReported) {
for (int i = 0; i < 2 * kMinRequiredSamples; ++i) {
VideoFrameMetaData meta = MetaData(frame);
statistics_proxy_->OnDecodedFrame(
meta, kHighQp, 0, webrtc::TimeDelta::Millis(0), content_type_);
meta, kHighQp, 0, webrtc::TimeDelta::Millis(0),
webrtc::TimeDelta::Millis(0), content_type_);
statistics_proxy_->OnRenderedFrame(meta);
fake_clock_.AdvanceTimeMilliseconds(kInterFrameDelayMs);
}