Ouroboros Tutorial 08
In Tutorial 04, we ran oping over a unicast Layer on the loopback device and looked at the packets on the wire. In this tutorial, we make that wire lossy and watch how the Flow and Retransmission Control Protocol (FRCT) repairs the flow: on the wire, and in the statistics it keeps for every flow. The Ouroboros Metrics page shows these statistics as graphs in Grafana; this tutorial shows where they come from.
We use the setup and debug build of Tutorial 04, with both IPCPs on lo. Loss and delay are added to lo with tc, so everything stays on one machine. The only requirement beyond Tutorial 04 is the netem queueing discipline, which every Linux distribution ships.
The setup
Save the configuration file of Tutorial 04 as /etc/ouroboros/tut08.conf:
### Ouroboros Tutorial 08
[name.oping-server]
prog=["/usr/bin/oping"]
args=["--listen"]
[unicast.uni-1]
bootstrap="unicast-layer"
autobind=true
eth=["lo"]
reg=["oping-server"]
[unicast.uni-2]
enrol={dst="unicast-layer", eth={}}
autobind=true
eth=["lo"]
conn=[{dst="uni-1", eth={}}]
and create the client security configuration for the three names, as before:
$ for n in unicast-layer uni-1 oping-server; do
> sudo mkdir -p /etc/ouroboros/security/client/$n
> printf 'auth=optional\nencryption=none\n' | sudo tee /etc/ouroboros/security/client/$n/sec.conf > /dev/null
> doneStart tcpdump in one terminal and the IRMd in another:
$ sudo tcpdump -i lo -X ether proto 0xa000$ sudo irmd --stdout --config /etc/ouroboros/tut08.confThe Layer comes up as in Tutorial 04. We keep encryption off, so that the packets stay readable on the wire.
A reliable flow
The pings of Tutorial 04 ran over a best-effort flow. This time we ask for a reliable one with -q msg: a message flow that allows no loss, the QoS the IPCPs use for their own enrollment and management flows. We send 500 pings, 20 ms apart, so that the flow lives for 10 seconds:
$ oping -n oping-server -q msg -c 500 -i 20
Pinging oping-server with 64 bytes of data (500 packets):
64 bytes from oping-server: seq=0 time=0.861 ms
64 bytes from oping-server: seq=1 time=0.459 ms
64 bytes from oping-server: seq=2 time=0.497 ms
64 bytes from oping-server: seq=3 time=0.436 ms
...
--- oping-server ping statistics ---
500 packets transmitted, 500 received, 0 out-of-order, 0% packet loss, time: 10048.424 ms
rtt min/avg/max/mdev = 0.080/0.274/0.861/0.078 msThe FRCT header
On a reliable flow, a 16-byte FRCT header sits between the DTP header and the oping message. This is the first ping:
12:46:25.575746 72:7e:25:fb:b7:fe (oui Unknown) > 76:ed:fa:00:06:6b (oui Unknown), ethertype Unknown (0xa000), length 115:
0x0000: 0002 0060 9bb5 d40f 4000 3c00 0042 0000 ...`....@.<..B..
0x0010: 0042 217d 08c3 0045 f700 0000 00a2 15b7 .B!}...E........
0x0020: 8e00 0000 0000 0000 0000 0000 009d 0e00 ................
0x0030: 0000 0000 00d7 d448 2200 0000 0000 0000 .......H".......
0x0040: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0050: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0060: 0000 0000 00 .....After the 5-byte PoA header and the 16-byte DTP header of Tutorial 04 comes the FRCT header.
uint16_t flags; c300 DATA, DRF, FFGM, LFGM uint16_t hcs; 45f7 header checksum uint32_t window; 0000 0000 the receive window the sender advertises (not valid here, no FC flag) uint32_t seqno; a215 b78e sequence number of this packet, 2719332238 uint32_t ackno; 0000 0000 the next sequence number expected from the peer (not valid here, no ACK flag)
The flags are a bit field:
0x8000 DATA the packet carries data 0x4000 DRF data run flag: the first packet after the sender's window was empty 0x2000 ACK the ackno field is valid 0x1000 NACK negative acknowledgment: the packet carries the sequence number the receiver missed 0x0800 FC the window field is valid 0x0400 RDVS rendez-vous: the sender asks whether the receiver's window has opened 0x0200 FFGM first fragment of a message 0x0100 LFGM last fragment of a message 0x0080 RXM retransmission 0x0040 SACK a list of selective acknowledgment blocks follows the header 0x0020 RTTP round-trip time probe, or its echo 0x0010 KA keepalive 0x0008 FIN end of a stream
The first ping is a data packet (DATA), a message that fits in one packet (FFGM and LFGM both set), and the start of a data run (DRF): the receiver takes its sequence number, which starts at a random value, as the left edge of its receive window. The client has nothing to acknowledge yet, so the ACK and FC flags are clear and the ackno and window fields are zero. The 64-byte oping message follows the header, as in Tutorial 04.
The server's reply is a data packet too, and it carries the acknowledgment of the ping:
12:46:25.576175 76:ed:fa:00:06:6b (oui Unknown) > 72:7e:25:fb:b7:fe (oui Unknown), ethertype Unknown (0xa000), length 115:
0x0000: 0002 0060 9bf8 ff05 2d00 3c00 0042 0000 ...`....-.<..B..
0x0010: 0038 d96c 15eb 0012 15a2 15b8 0f87 57dc .8.l..........W.
0x0020: 48a2 15b7 8f00 0000 0100 0000 009d 0e00 H...............
0x0030: 0000 0000 00d7 d448 2200 0000 0000 0000 .......H".......
0x0040: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0050: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0060: 0000 0000 00 .....Its sequence number starts at a random value of its own, its ackno is the sequence number of the ping plus one, the next one it expects, and the window field is the ackno plus 128: the receiver accepts up to 128 packets beyond the one it is waiting for, the size of its reordering queue. The acknowledgment rides on the reply, so the server never sends a separate one. The client has nothing to send until the next ping, 20 ms later, so after a short delay it acknowledges the reply with a packet of its own:
12:46:25.587092 72:7e:25:fb:b7:fe (oui Unknown) > 76:ed:fa:00:06:6b (oui Unknown), ethertype Unknown (0xa000), length 51:
0x0000: 0002 0020 7db5 d40f 4000 3c00 0042 0000 ....}...@.<..B..
0x0010: 0042 217d 0828 0072 4487 57dc c900 0000 .B!}.(.rD.W.....
0x0020: 0187 57dc 49 ..W.IThis is a control packet: ACK and FC are the only flags, there is no data after the header, and its seqno is 1. Control packets have a counter of their own, which the receiver uses to drop duplicates. It leaves about 11 ms after the reply: FRCT delays an acknowledgment by two ticks of its 5 ms timer, so that it can cover several packets or ride on a data packet, and sends it on its own when neither happens.
Between the pings, you will also see pairs of 75-byte packets with only the RTTP flag. These are round-trip time probes and their echoes: 24 bytes of payload with a probe number, an echo number and a 16-byte random nonce that the echo copies. Over this flow the smoothed round-trip time is a quarter of a millisecond, and each ping comes 20 ms after the last sample, which is more than twice that, so the client sends a probe with nearly every ping. The server only probes a few times at the start, to seed its own estimate.
The statistics in the RIB
While the flow is open, FRCT publishes its state and counters in the Resource Information Base (RIB), a FUSE filesystem under /tmp/ouroboros. Every process with flows has a directory proc.<pid> there, with a directory per flow descriptor, and the file frct in it holds the statistics of that flow. The client runs as your user, so you can read its flow directly. In another terminal, while the pings are running:
$ cat /tmp/ouroboros/proc.$(pgrep -u $USER -x oping)/*/frct
Maximum packet lifetime (ns): 100000000
Max time to Ack (ns): 1000000000
Max time to Retransmit (ns): 32000000000
Smoothed rtt (ns): 278375
RTT standard deviation (ns): 93257
Retransmit timeout RTO (ns): 1048576
Minimum RTT (RACK base, ns): 73314
Sender left window edge: 2719332589
Sender right window edge: 2719332717
Sender inactive (ns): 4794820
Sender current sequence number: 2719332589
Receiver left window edge: 2270682535
Receiver right window edge: 2270682663
Receiver inactive (ns): 4491865
Receiver last ack: 2270682534
RXM (RTO-driven) sent: 0
RXM packets received: 0
duplicates received: 0
RXM (SACK mechanism) sent: 0
RXM (RACK-driven) sent: 0
RXM (zero reorder wnd) sent: 0
RXM (NACK-driven) sent: 0
ACK packets sent: 350
Delayed-ACK timer fires: 350
suppressed (seqno): 0
suppressed (inact): 0
suppressed (rate): 0
ACK packets received: 0
fed RTT estimator: 0
wire dups dropped: 0
Duplicates received: 0
Out-of-window pkts received: 0
Out-of-rqueue pkts received: 0
OOO arrivals: 0
SACKs sent: 0
SACKs received: 0
D-SACKs sent: 0
D-SACKs received: 0
D-SACK out-of-range dropped: 0
Pre-DRF NACKs sent: 0
Pre-DRF NACKs received: 0
Tail loss probes sent: 0
Inactivity drops (silent): 0
DRF window rebases: 1
rq slots cleared by release_rq: 0
RTT probes sent: 316
RTT probe replies received: 4
RTT estimator samples: 667
Rendez-vous packets sent: 0
Rendez-vous packets received: 0
Keepalives sent: 0
Keepalives received: 0
SDU writes fragmented: 0
alloc fail mid-SDU: 0
tx fail mid-SDU: 0
Fragments sent: 0
Fragments received: 0
SDUs delivered reassembled: 0
SDUs delivered (SOLE): 351
Fragments dropped (malformed): 0
Stream bytes sent: 0
Stream bytes received: 0
Stream bytes delivered: 0
Stream packets dropped: 0
Stream FINs dropped: 0
FRCTI_RCV time (ns): 1021273
tw_move time (ns): 155806
drain_rx_nb calls: 1086
RX rbuff queued: 0
TX rbuff queued: 0
RXM-due entries: 350
bail (acked): 350
bail (unowned): 0
bail (aged): 0
bail (defer): 0
defer, no rxm at HoL: 0
skip (fast-rxm set): 0
skip (stuck past rto): 0
skip (no repair budget): 0
RXM-arm malloc failures: 0
RXM cancels (teardown): 0
RXM tx into dead flow: 0
Tx ring drops (any cause): 0
ack: 0
sack: 0
ka: 0
rttp: 0
nack: 0
rdv: 0
other: 0The first three lines are the Delta-t timers of the flow: the maximum packet lifetime of 100 ms set by the Layer, the acknowledgment timer of 1 second and the retransmission timer of 32 seconds, after which FRCT gives up on a packet. Then come the round-trip time estimates. The smoothed round-trip time is about 0.3 ms, with a deviation of 0.1 ms. The retransmission timeout (RTO) is the larger of twice the smoothed round-trip time and the smoothed round-trip time plus four times the deviation, but never less than the resolution of the retransmission queue, 220 ns: on this flow, that floor of about a millisecond is what you see.
The window edges are the sequence numbers of the FRCT header. The sender's left edge is the oldest packet not yet acknowledged, the right edge is 128 beyond it, and the current sequence number is the next one to be sent; with no ping in flight at the moment of reading, it equals the left edge. The receiver's edges and last acknowledgment track the server's sequence numbers the same way.
The counters tell the story of the flow so far. No retransmissions of any kind. The client has sent one acknowledgment packet for every reply (ACK packets sent and Delayed-ACK timer fires, none suppressed), and received none, because the server piggybacks its acknowledgments on the replies. It has sent a round-trip time probe with nearly every ping, received a few from the server and fed the estimator with two samples per ping: one from the piggybacked acknowledgment and one from the probe echo. Every reply arrived as a single-fragment message (SDUs delivered (SOLE)). Near the end, RXM-due entries counts the retransmission timers that were armed, one per ping, and bail (acked) how many of them found their packet acknowledged when they fired: all of them.
The server's side of the flow is in the RIB of the oping server, which the IRMd started as root. Its smoothed round-trip time is about 11 ms, not a third of a millisecond: its only samples come from the client's acknowledgment packets, which the delayed-acknowledgment timer holds for 10 ms. Its RTO is twice that.
Adding loss
Now we make lo drop 2% of the frames it carries. The netem queueing discipline does that for any device:
$ sudo tc qdisc add dev lo root netem loss 2%Every frame passes through lo once, so pings, replies, acknowledgments and retransmissions are all subject to the loss. Run the same 500 pings again:
$ oping -n oping-server -q msg -c 500 -i 20
Pinging oping-server with 64 bytes of data (500 packets):
64 bytes from oping-server: seq=0 time=0.696 ms
64 bytes from oping-server: seq=1 time=0.356 ms
64 bytes from oping-server: seq=2 time=0.132 ms
64 bytes from oping-server: seq=3 time=0.967 ms
...
--- oping-server ping statistics ---
500 packets transmitted, 500 received, 0 out-of-order, 0% packet loss, time: 10052.070 ms
rtt min/avg/max/mdev = 0.054/1.522/31.592/4.839 msWith 2% loss on some 2500 frames, a few dozen of them were dropped, and still every ping was answered: oping reports no loss. Only the maximum round-trip time gives it away.
A lost ping on the wire
The capture shows frames after netem, so a dropped frame simply never appears. This is what a lost ping looks like, with the FRCT header fields decoded in the text below:
12:46:51.313338 72:7e:25:fb:b7:fe (oui Unknown) > 76:ed:fa:00:06:6b (oui Unknown), ethertype Unknown (0xa000), length 115:
0x0000: 0002 0060 9bb5 d40f 4000 3c00 0043 0000 ...`....@.<..C..
0x0010: 00c7 d190 a8eb 005b 3b2f e83a 6c47 54a2 .......[;/.:lGT.
0x0020: 982f e839 ec00 0000 0000 0000 86b7 0e00 ./.9............
0x0030: 0000 0000 0071 46a7 1200 0000 0000 0000 .....qF.........
0x0040: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0050: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0060: 0000 0000 00 .....
12:46:51.313526 76:ed:fa:00:06:6b (oui Unknown) > 72:7e:25:fb:b7:fe (oui Unknown), ethertype Unknown (0xa000), length 115:
0x0000: 0002 0060 9bf8 ff05 2d00 3c00 0043 0000 ...`....-.<..C..
0x0010: 00d6 de11 a0eb 00e8 bb47 54a3 192f e839 .........GT../.9
0x0020: ec47 54a2 9900 0000 0100 0000 86b7 0e00 .GT.............
0x0030: 0000 0000 0071 46a7 1200 0000 0000 0000 .....qF.........
0x0040: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0050: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0060: 0000 0000 00 .....
12:46:51.324269 72:7e:25:fb:b7:fe (oui Unknown) > 76:ed:fa:00:06:6b (oui Unknown), ethertype Unknown (0xa000), length 51:
0x0000: 0002 0020 7db5 d40f 4000 3c00 0043 0000 ....}...@.<..C..
0x0010: 00c7 d190 a828 008d 8c2f e83a 6d00 0000 .....(.../.:m...
0x0020: 812f e839 ed ./.9.
12:46:51.344338 72:7e:25:fb:b7:fe (oui Unknown) > 76:ed:fa:00:06:6b (oui Unknown), ethertype Unknown (0xa000), length 115:
0x0000: 0002 0060 9bb5 d40f 4000 3c00 0043 0000 ...`....@.<..C..
0x0010: 00c7 d190 a8eb 80bf c82f e83a 6d47 54a2 ........./.:mGT.
0x0020: 992f e839 ed00 0000 0000 0000 87b7 0e00 ./.9............
0x0030: 0000 0000 00c7 6cd9 1300 0000 0000 0000 ......l.........
0x0040: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0050: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0060: 0000 0000 00 .....
12:46:51.344525 76:ed:fa:00:06:6b (oui Unknown) > 72:7e:25:fb:b7:fe (oui Unknown), ethertype Unknown (0xa000), length 115:
0x0000: 0002 0060 9bf8 ff05 2d00 3c00 0043 0000 ...`....-.<..C..
0x0010: 00d6 de11 a0eb 005f cd47 54a3 1a2f e839 ......._.GT../.9
0x0020: ed47 54a2 9a00 0000 0100 0000 87b7 0e00 .GT.............
0x0030: 0000 0000 00c7 6cd9 1300 0000 0000 0000 ......l.........
0x0040: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0050: 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0060: 0000 0000 00 .....The first two frames are a ping and its reply, as before, and the third is the client's acknowledgment of the reply. The next ping, sequence number 1196728985, is missing: netem dropped it. A few milliseconds later, the client sends it again. The fourth frame is that retransmission: the same sequence number, and the flags now read eb80 instead of eb00, the RXM bit. The server answers it like any ping, and the flow carries on.
What triggered the retransmission is the retransmission timer. Every data packet arms it for the RTO; when the timer fires and the packet is still unacknowledged, the packet is sent again. On this flow the RTO is a few milliseconds, and the timer is checked every 5 ms, so the repair comes within a tick of the loss.
A lost reply is more involved, because the client cannot tell a lost reply from a lost ping: its timer fires too, and it retransmits a ping the server already has. The server answers the duplicate with a selective acknowledgment that reports the duplicate (a D-SACK), and its own timer retransmits the lost reply. Here is such a D-SACK:
12:46:49.590035 76:ed:fa:00:06:6b (oui Unknown) > 72:7e:25:fb:b7:fe (oui Unknown), ethertype Unknown (0xa000), length 67:
0x0000: 0002 0030 d3f8 ff05 2d00 3c00 0043 0000 ...0....-.<..C..
0x0010: 00d6 de11 a028 404e 8a47 54a2 c300 0000 .....(@N.GT.....
0x0020: 0147 54a2 4300 0100 0047 54a2 4247 54a2 .GT.C....GT.BGT.
0x0030: 4326 ec8c 9a C&...The flags are ACK, FC and SACK, and after the header comes a block list: a 16-bit count (0001), 2 bytes of padding, and one block with a start and an end sequence number. The block lies below the ackno, which says the receiver already has it: that is what makes it a D-SACK.
The statistics after the loss
The counters that are no longer zero tell what happened. On the client, leaving out the zero lines:
$ cat /tmp/ouroboros/proc.$(pgrep -u $USER -x oping)/*/frct | grep -v ' 0$'
Maximum packet lifetime (ns): 100000000
Max time to Ack (ns): 1000000000
Max time to Retransmit (ns): 32000000000
Smoothed rtt (ns): 691668
RTT standard deviation (ns): 4379828
Retransmit timeout RTO (ns): 18210980
Minimum RTT (RACK base, ns): 48302
Sender left window edge: 1196729254
Sender right window edge: 1196729382
Sender inactive (ns): 7057497
Sender current sequence number: 1196729254
Receiver left window edge: 803748602
Receiver right window edge: 803748730
Receiver inactive (ns): 6897262
Receiver last ack: 803748601
RXM (RTO-driven) sent: 17
RXM packets received: 10
ACK packets sent: 379
Delayed-ACK timer fires: 404
suppressed (seqno): 20
suppressed (rate): 5
ACK packets received: 15
fed RTT estimator: 1
OOO arrivals: 8
SACKs sent: 8
SACKs received: 14
D-SACKs received: 14
Tail loss probes sent: 2
DRF window rebases: 1
RTT probes sent: 416
RTT probe replies received: 10
RTT estimator samples: 791
SDUs delivered (SOLE): 404
FRCTI_RCV time (ns): 1015439
tw_move time (ns): 120126
drain_rx_nb calls: 1380
RXM-due entries: 420
bail (acked): 403and on the server, read as root:
Maximum packet lifetime (ns): 100000000
Max time to Ack (ns): 1000000000
Max time to Retransmit (ns): 32000000000
Smoothed rtt (ns): 12141991
RTT standard deviation (ns): 6066129
Retransmit timeout RTO (ns): 36406507
Minimum RTT (RACK base, ns): 3098071
Sender left window edge: 803748598
Sender right window edge: 803748726
Sender inactive (ns): 10604225
Sender current sequence number: 803748599
Receiver left window edge: 1196729251
Receiver right window edge: 1196729379
Receiver inactive (ns): 10616786
Receiver last ack: 1196729251
RXM (RTO-driven) sent: 6
RXM packets received: 19
duplicates received: 14
RXM (SACK mechanism) sent: 3
RXM (RACK-driven) sent: 4
ACK packets sent: 16
Delayed-ACK timer fires: 782
suppressed (seqno): 766
ACK packets received: 373
fed RTT estimator: 357
SACKs sent: 14
SACKs received: 8
D-SACKs sent: 14
DRF window rebases: 1
RTT probes sent: 10
RTT probe replies received: 406
RTT estimator samples: 395
SDUs delivered (SOLE): 401
drain_rx_nb calls: 802
RXM-due entries: 409
bail (acked): 399
bail (unowned): 3
bail (defer): 1Every retransmission the client sent was timer-driven (RXM (RTO-driven)). The server's retransmissions are split: some by its timer, and some by the SACK mechanism. When a reply is lost, the next reply arrives at the client out of order (OOO arrivals) and the client sends a SACK reporting the hole; the server repairs it from the SACK, and most of these repairs count as RACK-driven too, after the time-based loss detection that decides whether a reported hole is a loss or a reordering. The D-SACKs the server sent are the client's needless retransmissions of pings, which the server counts as retransmissions received and duplicates. The client's RTO has grown to about 18 ms: the samples around the losses are irregular, and the deviation term dominates the estimate.
Adding delay
With a round-trip time of a quarter of a millisecond, the timer is always the first to notice a loss. On a real network it is the last resort: with a longer round-trip time, selective acknowledgments report a hole long before the timer would fire. Add 25 ms of delay to lo, which makes the round-trip time 50 ms, and keep the loss:
$ sudo tc qdisc change dev lo root netem loss 2% delay 25ms
$ oping -n oping-server -q msg -c 500 -i 20
Pinging oping-server with 64 bytes of data (500 packets):
64 bytes from oping-server: seq=0 time=50.766 ms
64 bytes from oping-server: seq=1 time=50.411 ms
64 bytes from oping-server: seq=2 time=50.469 ms
64 bytes from oping-server: seq=3 time=50.396 ms
...
--- oping-server ping statistics ---
500 packets transmitted, 500 received, 0 out-of-order, 0% packet loss, time: 10074.866 ms
rtt min/avg/max/mdev = 50.100/60.624/130.520/20.440 msNow the round-trip time exceeds the ping interval, so there are two or three pings in flight at any time, and the acknowledgments ride on the pings and replies: the DRF flag disappears from the data packets, as the sender's window is never empty, and the client sends no round-trip time probes, since a sample now arrives every 20 ms. This is a loss, decoded one packet per line, with the time in seconds from the first line:
0.000 client > server DATA|ACK|FC|FFGM|LFGM seq 4092668236 ack 2191082934
0.005 server > client DATA|ACK|FC|FFGM|LFGM seq 2191082935 ack 4092668236
0.025 server > client DATA|ACK|FC|FFGM|LFGM seq 2191082936 ack 4092668237
0.040 client > server DATA|ACK|FC|FFGM|LFGM seq 4092668238 ack 2191082936
0.060 client > server DATA|ACK|FC|FFGM|LFGM seq 4092668239 ack 2191082937
0.065 server > client ACK|FC|SACK seq 1 ack 4092668237 sack 4092668238
0.080 client > server DATA|ACK|FC|FFGM|LFGM seq 4092668240 ack 2191082937
0.085 server > client ACK|FC|SACK seq 2 ack 4092668237 sack 4092668238-4092668239
0.090 client > server DATA|ACK|FC|FFGM|LFGM|RXM seq 4092668237 ack 2191082937
0.100 client > server DATA|ACK|FC|FFGM|LFGM seq 4092668241 ack 2191082937
0.105 server > client ACK|FC|SACK seq 3 ack 4092668237 sack 4092668238-4092668240
0.116 server > client DATA|DRF|ACK|FC|FFGM|LFGM seq 2191082937 ack 4092668241
0.120 client > server DATA|ACK|FC|FFGM|LFGM seq 4092668242 ack 2191082937
0.125 server > client DATA|ACK|FC|FFGM|LFGM seq 2191082938 ack 4092668242The ping after the first one on the list, sequence number 4092668237, was dropped. The two pings after it arrive at the server out of order, and the server reports the hole at once with a SACK: the ackno still points at the missing packet, and the block says which later packets it has. This is the first of them:
12:47:12.615705 76:ed:fa:00:06:6b (oui Unknown) > 72:7e:25:fb:b7:fe (oui Unknown), ethertype Unknown (0xa000), length 67:
0x0000: 0002 0030 d3f8 ff05 2d00 3c01 3342 0000 ...0....-.<.3B..
0x0010: 00b1 13ca 5528 403d f6f3 f129 cd00 0000 ....U(@=...)....
0x0020: 01f3 f129 4d00 0100 00f3 f129 4ef3 f129 ...)M......)N..)
0x0030: 4f4c 26ea f9 OL&..The SACK takes 25 ms to reach the client, which retransmits the missing ping immediately: the ping before the hole was sent 20 ms before the one the SACK confirms, and 20 ms is more than the reordering window FRCT allows, a quarter of the minimum round-trip time. The retransmitted ping arrives 25 ms later, and the server's next reply acknowledges everything up to the newest ping. The retransmission left 70 ms after the lost ping; the retransmission timer, with an RTO of twice the round-trip time, would have fired after 100 ms.
$ cat /tmp/ouroboros/proc.$(pgrep -u $USER -x oping)/*/frct | grep -v ' 0$'
Maximum packet lifetime (ns): 100000000
Max time to Ack (ns): 1000000000
Max time to Retransmit (ns): 32000000000
Smoothed rtt (ns): 50334911
RTT standard deviation (ns): 2010254
Retransmit timeout RTO (ns): 100669822
Minimum RTT (RACK base, ns): 50093318
Sender left window edge: 4092668594
Sender right window edge: 4092668722
Sender inactive (ns): 9154218
Sender current sequence number: 4092668597
Receiver left window edge: 2191083294
Receiver right window edge: 2191083422
Receiver inactive (ns): 18983279
Receiver last ack: 2191083294
RXM packets received: 8
RXM (SACK mechanism) sent: 6
RXM (RACK-driven) sent: 6
ACK packets sent: 42
Delayed-ACK timer fires: 367
suppressed (seqno): 325
ACK packets received: 18
OOO arrivals: 20
SACKs sent: 21
SACKs received: 18
DRF window rebases: 1
RTT probe replies received: 1
RTT estimator samples: 385
SDUs delivered (SOLE): 399
FRCTI_RCV time (ns): 9948
tw_move time (ns): 1429
drain_rx_nb calls: 1218
RXM-due entries: 403
bail (acked): 397
bail (unowned): 6
skip (stuck past rto): 6The timer did not fire once on this flow: every retransmission was driven by a SACK and confirmed by RACK, and the client did not need a single round-trip time probe. The RTO is 100 ms, twice the smoothed round-trip time of 50 ms.[1]
When you are done, remove the queueing discipline from lo:
$ sudo tc qdisc del dev lo rootWatching it live
The counters in the RIB are what the metrics exporter samples. With the exporter and the Grafana dashboard installed, the RTT-estimation, FRCT — RXM rates and FRCT — ACK rates rows show the round-trip time, the retransmissions by driver and the acknowledgments of a flow as graphs over time, and the other FRCT rows the rest of the counters above.
These panels come from a separate run of the three phases of this tutorial, with the exporter sampling every half second. They show the client's flow; each phase starts a new client:
Notes
- ↑ In this phase, the ecn and cap fields of the DTP header are no longer zero. netem holds every frame for 25 ms in the queueing discipline of lo, and the point of attachment reports that backlog as a queue, so the congestion avoidance marks the packets and estimates a link capacity. It is harmless here, but worth knowing when you read captures taken over netem.