Hi All,

Sorry for the spam. I'm trying to support a meaningful TCP message latency w/iperf 2 from the sender side w/o requiring e2e clock synchronization. I thought I'd try to use the TCP_NOTSENT_LOWAT event to help with this. It seems that this event goes off when the bytes are in flight vs have reached the destination network stack. If that's the case, then iperf 2 client (sender) may be able to produce the message latency by adding the drain time (write start to TCP_NOTSENT_LOWAT) and the sampled RTT. 

Does this seem reasonable?

Below are some sample outputs of a 10G wired sending to a 1G wired. These systems do have e2e clock sync so the server side message latency is correct. The RTT + Drain does approximately equal the server side e2e msg latency

First with BBR

[root@ryzen3950 iperf2-code]# iperf -c 192.168.1.156 -i 1 -e --tcp-drain --realtime -Z bbr --trip-times -l 1M
------------------------------------------------------------
Client connecting to 192.168.1.156, TCP port 5001 with pid 206299 (1 flows)
Write buffer size: 1048576 Byte (drain-enabled)
TCP congestion control set to bbr
TCP window size:  128 KByte (default)
------------------------------------------------------------
[  1] local 192.168.1.133%enp4s0 port 60684 connected with 192.168.1.156 port 5001 (MSS=1448) (trip-times) (sock=3) (ct=0.26 ms) on 2021-10-21 17:44:10 (PDT)
[ ID] Interval        Transfer    Bandwidth       Write/Err  Rtry     Cwnd/RTT        NetPwr  Drain avg/min/max/stdev (cnt)
[  1] 0.00-1.00 sec   112 MBytes   940 Mbits/sec  113/0          0      263K/1906 us  61616  8.947/8.322/13.465/0.478 ms (112)
[  1] 1.00-2.00 sec   112 MBytes   940 Mbits/sec  112/0          0      260K/1987 us  59104  8.911/8.229/9.569/0.229 ms (112)
[  1] 2.00-3.00 sec   113 MBytes   948 Mbits/sec  113/0          0      254K/2087 us  56775  8.910/8.311/9.564/0.221 ms (113)
[  1] 3.00-4.00 sec   112 MBytes   940 Mbits/sec  112/0          0      263K/1710 us  68679  8.911/8.297/9.618/0.217 ms (112)
[  1] 4.00-5.00 sec   112 MBytes   940 Mbits/sec  112/0          0      254K/2024 us  58024  8.907/8.470/9.641/0.197 ms (112)
[  1] 5.00-6.00 sec   112 MBytes   940 Mbits/sec  112/0          0      263K/2124 us  55292  8.911/8.291/9.325/0.198 ms (112)
[  1] 6.00-7.00 sec   113 MBytes   948 Mbits/sec  113/0          0      265K/2012 us  58891  8.913/8.226/9.569/0.229 ms (113)
[  1] 7.00-8.00 sec   112 MBytes   940 Mbits/sec  112/0          0      265K/1989 us  59045  8.908/8.313/9.366/0.194 ms (112)
[  1] 8.00-9.00 sec   112 MBytes   940 Mbits/sec  112/0          0      263K/1999 us  58750  8.908/8.212/9.402/0.211 ms (112)
[  1] 9.00-10.00 sec   112 MBytes   940 Mbits/sec  112/0          0        5K/242 us  485291  8.947/8.319/12.754/0.414 ms (112)
[  1] 0.00-10.06 sec  1.10 GBytes   937 Mbits/sec  1125/0          0        5K/242 us  483764  8.950/8.212/45.293/1.120 ms (1123)

[root@localhost rjmcmahon]# iperf -s -e -B 192.168.1.156%enp4s0f0 -i 1 --realtime
------------------------------------------------------------
Server listening on TCP port 5001 with pid 53099
Binding to local address 192.168.1.156 and iface enp4s0f0
Read buffer size:  128 KByte (Dist bin width=16.0 KByte)
TCP window size:  128 KByte (default)
------------------------------------------------------------
[  1] local 192.168.1.156%enp4s0f0 port 5001 connected with 192.168.1.133 port 60684 (MSS=1448) (trip-times) (sock=4) (peer 2.1.4-master) on 2021-10-21 20:44:10 (EDT)
[ ID] Interval        Transfer    Bandwidth    Burst Latency avg/min/max/stdev (cnt/size) inP NetPwr  Reads=Dist
[  1] 0.00-1.00 sec   112 MBytes   936 Mbits/sec  10.629/9.890/14.998/1.507 ms (111/1053964) 1.20 MByte 11007  4347=412:3927:7:0:1:0:0:0
[  1] 1.00-2.00 sec   112 MBytes   942 Mbits/sec  10.449/9.736/10.740/0.237 ms (112/1050799) 1.18 MByte 11263  4403=465:3938:0:0:0:0:0:0
[  1] 2.00-3.00 sec   112 MBytes   942 Mbits/sec  10.426/9.873/10.698/0.246 ms (113/1041489) 1.16 MByte 11288  4382=420:3962:0:0:0:0:0:0
[  1] 3.00-4.00 sec   112 MBytes   941 Mbits/sec  10.485/9.724/10.716/0.208 ms (112/1050541) 1.18 MByte 11221  4393=446:3946:1:0:0:0:0:0
[  1] 4.00-5.00 sec   112 MBytes   942 Mbits/sec  10.487/9.902/10.736/0.216 ms (112/1050786) 1.18 MByte 11222  4392=448:3944:0:0:0:0:0:0
[  1] 5.00-6.00 sec   112 MBytes   942 Mbits/sec  10.484/9.758/10.748/0.236 ms (112/1050799) 1.18 MByte 11226  4397=456:3940:0:1:0:0:0:0
[  1] 6.00-7.00 sec   112 MBytes   941 Mbits/sec  10.475/9.756/10.753/0.248 ms (112/1050515) 1.18 MByte 11232  4403=473:3930:0:0:0:0:0:0
[  1] 7.00-8.00 sec   112 MBytes   942 Mbits/sec  10.435/9.759/10.757/0.288 ms (113/1041502) 1.16 MByte 11278  4414=480:3934:0:0:0:0:0:0
[  1] 8.00-9.00 sec   112 MBytes   942 Mbits/sec  10.485/9.762/10.759/0.277 ms (112/1050799) 1.18 MByte 11225  4409=470:3939:0:0:0:0:0:0
[  1] 9.00-10.00 sec   112 MBytes   942 Mbits/sec  10.550/10.000/10.759/0.191 ms (112/1050786) 1.19 MByte 11155  4399=455:3944:0:0:0:0:0:0
[  1] 0.00-10.05 sec  1.10 GBytes   937 Mbits/sec  10.524/9.724/45.519/1.173 ms (1123/1048576) 1.18 MByte 11132  44149=4725:39414:8:1:1:0:0:0

Now with CUBIC

[root@ryzen3950 iperf2-code]# iperf -c 192.168.1.156 -i 1 -e --tcp-drain --realtime -Z cubic --trip-times -l 1M
------------------------------------------------------------
Client connecting to 192.168.1.156, TCP port 5001 with pid 206487 (1 flows)
Write buffer size: 1048576 Byte (drain-enabled)
TCP congestion control set to cubic
TCP window size: 85.0 KByte (default)
------------------------------------------------------------
[  1] local 192.168.1.133%enp4s0 port 60686 connected with 192.168.1.156 port 5001 (MSS=1448) (trip-times) (sock=3) (ct=0.49 ms) on 2021-10-21 17:47:02 (PDT)
[ ID] Interval        Transfer    Bandwidth       Write/Err  Rtry     Cwnd/RTT        NetPwr  Drain avg/min/max/stdev (cnt)
[  1] 0.00-1.00 sec   113 MBytes   948 Mbits/sec  114/0         66     1527K/13168 us  8998  8.855/4.757/15.949/0.995 ms (113)
[  1] 1.00-2.00 sec   113 MBytes   948 Mbits/sec  113/0          0     1668K/14380 us  8240  8.899/8.450/9.425/0.270 ms (113)
[  1] 2.00-3.00 sec   112 MBytes   940 Mbits/sec  112/0          0     1781K/15335 us  7658  8.904/8.446/9.314/0.258 ms (112)
[  1] 3.00-4.00 sec   112 MBytes   940 Mbits/sec  112/0          0     1867K/16127 us  7282  8.900/8.570/9.313/0.252 ms (112)
[  1] 4.00-5.00 sec   113 MBytes   948 Mbits/sec  113/0          0     1931K/16537 us  7165  8.908/8.330/9.431/0.290 ms (113)
[  1] 5.00-6.00 sec   111 MBytes   931 Mbits/sec  111/0          1     1439K/12342 us  9431  8.945/4.303/18.970/1.091 ms (111)
[  1] 6.00-7.00 sec   113 MBytes   948 Mbits/sec  113/0          0     1515K/12845 us  9225  8.904/8.451/9.432/0.298 ms (113)
[  1] 7.00-8.00 sec   112 MBytes   940 Mbits/sec  112/0          0     1569K/13353 us  8795  8.907/8.569/9.314/0.283 ms (112)
[  1] 8.00-9.00 sec   112 MBytes   940 Mbits/sec  112/0          0     1606K/13718 us  8561  8.909/8.571/9.312/0.275 ms (112)
[  1] 9.00-10.00 sec   113 MBytes   948 Mbits/sec  113/0          0     1630K/13930 us  8506  8.906/8.569/9.316/0.298 ms (113)
[  1] 0.00-10.04 sec  1.10 GBytes   940 Mbits/sec  1127/0         67     1630K/13930 us  8431  8.904/4.303/18.970/0.526 ms (1125)

[root@localhost rjmcmahon]# iperf -s -e -B 192.168.1.156%enp4s0f0 -i 1 --realtime
------------------------------------------------------------
Server listening on TCP port 5001 with pid 53121
Binding to local address 192.168.1.156 and iface enp4s0f0
Read buffer size:  128 KByte (Dist bin width=16.0 KByte)
TCP window size:  128 KByte (default)
------------------------------------------------------------
[  1] local 192.168.1.156%enp4s0f0 port 5001 connected with 192.168.1.133 port 60686 (MSS=1448) (trip-times) (sock=4) (peer 2.1.4-master) on 2021-10-21 20:47:02 (EDT)
[ ID] Interval        Transfer    Bandwidth    Burst Latency avg/min/max/stdev (cnt/size) inP NetPwr  Reads=Dist
[  1] 0.00-1.00 sec   111 MBytes   935 Mbits/sec  20.327/10.445/39.920/4.341 ms (111/1053090) 2.33 MByte 5751  4344=521:3791:7:2:1:9:0:11
[  1] 1.00-2.00 sec   112 MBytes   942 Mbits/sec  22.492/21.768/23.254/0.397 ms (112/1050799) 2.53 MByte 5233  4487=594:3893:0:0:0:0:0:0
[  1] 2.00-3.00 sec   112 MBytes   941 Mbits/sec  23.624/22.987/24.248/0.327 ms (112/1050502) 2.66 MByte 4980  4462=548:3912:1:1:0:0:0:0
[  1] 3.00-4.00 sec   112 MBytes   941 Mbits/sec  24.475/23.741/24.971/0.287 ms (113/1041476) 2.73 MByte 4808  4483=575:3908:0:0:0:0:0:0
[  1] 4.00-5.00 sec   112 MBytes   942 Mbits/sec  25.146/24.597/25.459/0.254 ms (112/1050799) 2.83 MByte 4680  4523=642:3880:0:1:0:0:0:0
[  1] 5.00-6.00 sec   112 MBytes   942 Mbits/sec  21.592/15.549/36.567/2.358 ms (112/1050786) 2.42 MByte 5450  4373=489:3868:0:1:0:0:1:12
[  1] 6.00-7.00 sec   112 MBytes   941 Mbits/sec  21.447/20.800/22.024/0.275 ms (112/1050528) 2.41 MByte 5486  4464=559:3904:0:1:0:0:0:0
[  1] 7.00-8.00 sec   112 MBytes   942 Mbits/sec  22.021/21.536/22.519/0.216 ms (113/1041502) 2.46 MByte 5344  4475=557:3918:0:0:0:0:0:0
[  1] 8.00-9.00 sec   112 MBytes   942 Mbits/sec  22.445/22.023/22.774/0.209 ms (112/1050799) 2.53 MByte 5243  4407=474:3932:0:1:0:0:0:0
[  1] 9.00-10.00 sec   112 MBytes   941 Mbits/sec  22.680/22.269/23.024/0.184 ms (112/1050541) 2.55 MByte 5188  4511=635:3875:1:0:0:0:0:0
[  1] 0.00-10.03 sec  1.10 GBytes   941 Mbits/sec  22.629/10.445/39.920/2.083 ms (1125/1048576) 2.54 MByte 5197  44659=5598:39007:9:7:1:9:1:23

Thanks,
Bob



This electronic communication and the information and any files transmitted with it, or attached to it, are confidential and are intended solely for the use of the individual or entity to whom it is addressed and may contain information that is confidential, legally privileged, protected by privacy laws, or otherwise restricted from disclosure to anyone else. If you are not the intended recipient or the person responsible for delivering the e-mail to the intended recipient, you are hereby notified that any use, copying, distributing, dissemination, forwarding, printing, or copying of this e-mail is strictly prohibited. If you received this e-mail in error, please return the e-mail to the sender, delete it from your computer, and destroy any printed copy of it.