Skip to content

Commit

Permalink
feat: Add a timeline event when the packet was sent over ICE. (#2171)
Browse files Browse the repository at this point in the history 
* feat: Add a timeline event when the packet was sent over ICE.

* feat: Add another analize-timeline script.
  • Loading branch information
@bgrozev
bgrozev authored Jun 11, 2024
1 parent 0083ed0 commit 059cd3e
Show file tree
Hide file tree
Showing 2 changed files with 246 additions and 0 deletions.
2 changes: 2 additions & 0 deletions jvb/src/main/kotlin/org/jitsi/videobridge/Endpoint.kt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -514,6 +514,7 @@ class Endpoint @JvmOverloads constructor(
packetInfo.addEvent(SRTP_QUEUE_EXIT_EVENT)

iceTransport.send(packetInfo.packet.buffer, packetInfo.packet.offset, packetInfo.packet.length)
packetInfo.addEvent(SENT_OVER_ICE_TRANSPORT_EVENT)
PacketTransitStats.packetSent(packetInfo)
ByteBufferPool.returnBuffer(packetInfo.packet.buffer)
packetInfo.sent()
Expand Down Expand Up @@ -1184,6 +1185,7 @@ class Endpoint @JvmOverloads constructor(

private const val SRTP_QUEUE_ENTRY_EVENT = "Entered Endpoint SRTP sender outgoing queue"
private const val SRTP_QUEUE_EXIT_EVENT = "Exited Endpoint SRTP sender outgoing queue"
private const val SENT_OVER_ICE_TRANSPORT_EVENT = "Sent over the ICE transport"

private val statsFilterThreshold: Int by config {
"videobridge.stats-filter-threshold".from(JitsiConfig.newConfig)
Expand Down
244 changes: 244 additions & 0 deletions resources/analyze-timeline2.pl
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,244 @@
#!/usr/bin/perl -w

use Statistics::Descriptive;
use strict;

my %stats;
my @stat_names;

/*
This is extremely ugly, I'm driving perl in first gear because I don't know how to shift :)
It parses the PacketInfo EventTimeline logs (see example below) and produces stats for
the following periods from the life cycle of a packet:
1.Receiver Queue: From the moment the packet is read from the ICE transport (in an IO thread) and added the the Receiver Queue
to the moment it is removed from the Receiver Queue (in a CPU thread) and the pipeline processing starts.
2.Receiver Pipeline: From the start of the Receiver Pipeline to the end, excluding the last Termination node. This is all
performed in the same CPU thread, and includes things like SRTP decryption/authentication, RTP parsing, updating bandwidth
estimation, video codec parsing, etc.
3.Termination Node: This is technically the last Node in the Receiver Pipeline and executes in the same thread, but
it is conceptually different and worth looking at separately. It consists of conference-level handling of the packet: it loops
through all local endpoints and relays, checks whether they "want" the packet, and if they do then clones the packet and puts
the clone on the sender queue (see Conference#sendOut). This workload scales with the number of local endpoits and relays,
and in a large conference is the most computationally expensive.
Note that currently Endpoint#send(PacketInfo) contains code for SSRC rewriting and a transformation from the BitrateController.
This can be offloaded to the sender queue and we plan to do so soon.
4.Sender Queue: From the time the Receiver Pipeline thread places the packet on the Sender Queue, to the time another CPU thread
removes it from the queue and starts executing the Sender Pipeline.
5.Sender Pipeline: From the start of the Sender Pipeline to the end. This executes in a CPU thread and includes stripping unknown (for
this specific receiving endpoint) RTP header extensions, saving a copy of the packet in the NACK cache, adding/updating the transport-cc
header extension, and SRTP encryption.
This script looks only at RTP packets (ignoring RTCP and retransmissions) for simplicity.
6.SRTP Queue: From the time a SRTP packet is placed on the queue by the Sender Pipeline thread to the time an IO thread removes it
from the queue and starts sending it over the ICE transport.
7.Send over ICE transport: The time it took to execute IceTransport.send, which sends the packet through the ice4j socket representation.
8.Total: From the start of 1. to the end of 7.
Example log line:
JVB 2024-06-11 17:57:44.989 FINER: [1531] [confId=6149c0c339432f97 conf_name=loadtest0@conference.xxx meeting_id=ec7261c3 epId=c88aca35 stats_id=Otto-emV] Endpoint.doSendSrtp#544: Reference time: 2024-06-11T17:57:44.988517466Z; (Entered RTP receiver incoming queue, PT0.00000192S); (Exited RTP receiver incoming queue, PT0.000324242S); (Entered node PacketStreamStats, PT0.000324602S); (Exited node PacketStreamStats, PT0.000325042S); (Entered node SRTP/SRTCP demuxer, PT0.000325162S); (Exited node SRTP/SRTCP demuxer, PT0.000325722S); (Entered node RTP Parser, PT0.000325962S); (Exited node RTP Parser, PT0.000326762S); (Entered node Audio level reader (pre-srtp), PT0.000326922S); (Exited node Audio level reader (pre-srtp), PT0.000327242S); (Entered node Video mute node, PT0.000327362S); (Exited node Video mute node, PT0.000327642S); (Entered node SRTP Decrypt Node, PT0.000327762S); (Exited node SRTP Decrypt Node, PT0.000332442S); (Entered node TCC generator, PT0.000332562S); (Exited node TCC generator, PT0.000333562S); (Entered node Remote Bandwidth Estimator, PT0.000344962S); (Exited node Remote Bandwidth Estimator, PT0.000345202S); (Entered node Audio level reader (post-srtp), PT0.000345322S); (Exited node Audio level reader (post-srtp), PT0.000345442S); (Entered node Toggleable pcap writer: 21913831-rx, PT0.000345562S); (Exited node Toggleable pcap writer: 21913831-rx, PT0.000345762S); (Entered node Incoming statistics tracker, PT0.000345882S); (Exited node Incoming statistics tracker, PT0.000351242S); (Entered node Padding termination, PT0.000351362S); (Exited node Padding termination, PT0.000351522S); (Entered node Media Type demuxer, PT0.000351642S); (Exited node Media Type demuxer, PT0.000351962S); (Entered node RTX handler, PT0.000352082S); (Exited node RTX handler, PT0.000352322S); (Entered node Duplicate termination, PT0.000352722S); (Exited node Duplicate termination, PT0.000355442S); (Entered node Retransmission requester, PT0.000355882S); (Exited node Retransmission requester, PT0.000357922S); (Entered node Padding-only discarder, PT0.000358642S); (Exited node Padding-only discarder, PT0.000359842S); (Entered node Video parser, PT0.000360242S); (Exited node Video parser, PT0.000363082S); (Entered node Video quality layer lookup, PT0.000363362S); (Exited node Video quality layer lookup, PT0.000364362S); (Entered node Video bitrate calculator, PT0.000364682S); (Exited node Video bitrate calculator, PT0.000369122S); (Entered node Input pipeline termination node, PT0.000369362S); (Entered node receiver chain handler, PT0.000370122S); (Entered RTP sender incoming queue, PT0.000488083S); (Exited RTP sender incoming queue, PT0.000551283S); (Entered node Pre-processor, PT0.000551723S); (Exited node Pre-processor, PT0.000555843S); (Entered node RedHandler, PT0.000556083S); (Exited node RedHandler, PT0.000556563S); (Entered node Strip header extensions, PT0.000556843S); (Exited node Strip header extensions, PT0.000557523S); (Entered node Packet cache, PT0.000557923S); (Exited node Packet cache, PT0.000561083S); (Entered node Absolute send time, PT0.000561243S); (Exited node Absolute send time, PT0.000561643S); (Entered node Outgoing statistics tracker, PT0.000561923S); (Exited node Outgoing statistics tracker, PT0.000562683S); (Entered node TCC sequence number tagger, PT0.000563003S); (Exited node TCC sequence number tagger, PT0.000563843S); (Entered node Header extension encoder, PT0.000564083S); (Exited node Header extension encoder, PT0.000565163S); (Entered node Toggleable pcap writer: c88aca35-tx, PT0.000565443S); (Exited node Toggleable pcap writer: c88aca35-tx, PT0.000565763S); (Entered node SRTP Encrypt Node, PT0.000566083S); (Exited node SRTP Encrypt Node, PT0.000572883S); (Entered node PacketStreamStats, PT0.000573243S); (Exited node PacketStreamStats, PT0.000573883S); (Entered node Output pipeline termination node, PT0.000574123S); (Entered Endpoint SRTP sender outgoing queue, PT0.000574443S); (Exited node Output pipeline termination node, PT0.000582923S); (Exited Endpoint SRTP sender outgoing queue, PT0.000668003S); (Sent over the ICE transport, PT0.000693284S)
*/

my $receiverQStartName = "Entered RTP receiver incoming queue";
my $receiverQEndName = "Exited RTP receiver incoming queue";
my $receiverPStartName = "Entered node SRTP/SRTCP demuxer";
my $receiverPEndName = "Entered node Input pipeline termination node";
my $terminationNodeStartName = "Entered node Input pipeline termination node";
my $terminationNodeEndName = "Exited node Input pipeline termination node";
my $senderQStartName = "Entered RTP sender incoming queue";
my $senderQEndName = "Exited RTP sender incoming queue";
my $senderPStartName = "Entered node RedHandler";
my $senderPEndName = "Entered Endpoint SRTP sender outgoing queue";
my $srtpQStartName = "Entered Endpoint SRTP sender outgoing queue";
my $srtpQEndName = "Exited Endpoint SRTP sender outgoing queue";
my $iceStartName = "Exited Endpoint SRTP sender outgoing queue";
my $iceEndName = "Sent over the ICE transport";
my $totalStartName = "Entered RTP receiver incoming queue";
my $totalEndName = "Sent over the ICE transport";

while (<>) {
if (/Reference time: /) {
my $prev_time;
my $receiverQStart = -1;
my $receiverQEnd = -1;
my $receiverPStart = -1;
my $receiverPEnd = -1 ;
my $terminationNodeStart = -1 ;
my $terminationNodeEnd = -1;
my $senderQStart = -1;
my $senderQEnd = -1;
my $senderPStart = -1;
my $senderPEnd = -1 ;
my $srtpQStart = -1;
my $srtpQEnd = -1;
my $iceStart = -1;
my $iceEnd = -1;
my $totalStart = -1;
my $totalEnd = -1;

while (/; \(([^)]*), PT([0-9.]*)/g) {
my $name = $1;
my $time = $2;

if ($name eq $receiverQStartName) {
$receiverQStart = $time;
}
if ($name eq $receiverQEndName) {
$receiverQEnd = $time;
}
if ($name eq $receiverPStartName) {
$receiverPStart = $time;
}
if ($name eq $receiverPEndName) {
$receiverPEnd = $time;
}
if ($name eq $terminationNodeStartName) {
$terminationNodeStart = $time;
}
if ($name eq $terminationNodeEndName) {
$terminationNodeEnd = $time;
}
if ($name eq $senderQStartName) {
$senderQStart = $time;
}
if ($name eq $senderQEndName) {
$senderQEnd = $time;
}
if ($name eq $senderPStartName) {
$senderPStart = $time;
}
if ($name eq $senderPEndName) {
$senderPEnd = $time;
}
if ($name eq $srtpQStartName) {
$srtpQStart = $time;
}
if ($name eq $srtpQEndName) {
$srtpQEnd = $time;
}
if ($name eq $iceStartName) {
$iceStart = $time;
}
if ($name eq $iceEndName) {
$iceEnd = $time;
}
if ($name eq $totalStartName) {
$totalStart = $time;
}
if ($name eq $totalEndName) {
$totalEnd = $time;
}

#my $delta_time;
#if (defined $prev_time) {
# $delta_time = $time - $prev_time;
#}
#else {
# $delta_time = $time;
#}
#$prev_time = $time;

#if ($name =~ /Toggleable pcap writer:/) {
# $name =~ s/writer: .*/writer/;
#}
}
if ($receiverQStart > -1 && $receiverQEnd > -1) {
my $name = "1.Receiver Queue";
my $time = $receiverQEnd - $receiverQStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
if ($receiverPStart > -1 && $receiverPEnd > -1) {
my $name = "2.Receiver Pipeline";
my $time = $receiverPEnd - $receiverPStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
if ($terminationNodeStart > -1 && $terminationNodeEnd > -1) {
my $name = "3.Termination Node";
my $time = $terminationNodeEnd - $terminationNodeStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
if ($senderQStart > -1 && $senderQEnd > -1) {
my $name = "4.Sender Queue";
my $time = $senderQEnd - $senderQStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
if ($senderPStart > -1 && $senderPEnd > -1) {
my $name = "5.Sender Pipeline";
my $time = $senderPEnd - $senderPStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
if ($srtpQStart > -1 && $srtpQEnd > -1) {
my $name = "6.SRTP Queue";
my $time = $srtpQEnd - $srtpQStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
if ($iceStart > -1 && $iceEnd > -1) {
my $name = "7.Send over ICE transport";
my $time = $iceEnd - $iceStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
if ($totalStart > -1 && $totalEnd > -1) {
my $name = "8.Total";
my $time = $totalEnd - $totalStart;

if (!defined ($stats{$name})) {
$stats{$name} = Statistics::Descriptive::Full->new();
push(@stat_names, $name);
}
$stats{$name}->add_data($time * 1e3);
}
}
}

for my $name (@stat_names) {
my $s = $stats{$name};
printf("%s: min %.3f ms, mean %.3f ms, median %.3f ms, 90%% %.3f ms, 99%% %.3f ms, max %.3f ms\n",
$name, $s->min(), $s->mean(), $s->median(), scalar($s->percentile(90)), scalar($s->percentile(99)), $s->max());
}

0 comments on commit 059cd3e

Please sign in to comment.