Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Measurements seem quite short... #14

Open
moeller0 opened this issue Mar 27, 2022 · 9 comments
Open

Measurements seem quite short... #14

moeller0 opened this issue Mar 27, 2022 · 9 comments

Comments

@moeller0
Copy link

moeller0 commented Mar 27, 2022

The total measurement duration of the test against apples servers appears quite short. It would be nice if the duration could be controlled from the client (or if that is not according to the spec if the servers could be configured to measure for longer durations):

[email protected]:~/CODE/goresponsiveness$ time ./networkQuality --config mensura.cdn-apple.com --port 443 --path /api/v1/gm/config --timeout 60
03-27-2022 17:51:51 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:  87.499 Mbps ( 10.937 MBps), using 12 parallel connections.
Upload:    26.531 Mbps (  3.316 MBps), using 12 parallel connections.
Total RTTs measured: 5
RPM:   829

real    0m5.504s
user    0m1.277s
sys     0m1.225s

~6 seconds, that is even shorter than run-of-the-mill speedtests... This might or might not result in a saturating load, but it most certainly will result in an imprecise throughput measurement...

Experience with bufferbloat measurements seems to indicate that >= 20-30 seconds testing is required to fully saturate a link (and be sure about that fact).

Trying to confirm this with flent/netperf:

date ; ping -c 10 netperf-eu.bufferbloat.net ; ./run-flent --ipv4 -l 30 -H netperf-eu.bufferbloat.net rrul_var [email protected] [email protected] --step-size=.05 --socket-stats --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_SQM_cake_layer-cake_LLA-ETH_OH34_U097pct36000of36998K-D090pct105000of116797K_work-horse-eth0_2_TurrisOmnia-TurrisOS.5.3.6-pppoe-wan-eth2.7_2_bridged-BTHH5A-OpenWrt-r18441-ba7cee05ed-Hvt-VDSL100_2_netperf-eu.bufferbloat.net --log-file

[...]

Ping (ms) ICMP 1.1.1.1 (extra)       :        12.20        12.10        21.91 ms              914
 Ping (ms) avg                        :        26.11          N/A          N/A ms              914
 Ping (ms)::ICMP                      :        25.30        25.10        35.11 ms              914
 Ping (ms)::UDP 0 (0)                 :        25.42        25.43        33.43 ms              914
 Ping (ms)::UDP 1 (0)                 :        25.36        25.32        33.77 ms              914
 Ping (ms)::UDP 2 (0)                 :        26.99        26.88        36.13 ms              914
 Ping (ms)::UDP 3 (0)                 :        25.27        25.20        34.42 ms              914
 Ping (ms)::UDP 4 (0)                 :        25.26        25.22        33.32 ms              914
 Ping (ms)::UDP 5 (0)                 :        27.99        27.85        37.20 ms              914
 Ping (ms)::UDP 6 (0)                 :        27.95        27.89        36.29 ms              914
 Ping (ms)::UDP 7 (0)                 :        25.42        25.32        34.56 ms              914
 TCP download avg                     :        11.93          N/A          N/A Mbits/s         914
 TCP download sum                     :        95.44          N/A          N/A Mbits/s         914
 TCP download::0 (0)                  :        11.85        12.26        13.97 Mbits/s         914
 TCP download::1 (0)                  :        11.81        12.28        13.81 Mbits/s         914
 TCP download::2 (0)                  :        12.13        12.31        16.28 Mbits/s         914
 TCP download::3 (0)                  :        12.04        12.31        13.76 Mbits/s         914
 TCP download::4 (0)                  :        11.78        12.28        13.83 Mbits/s         914
 TCP download::5 (0)                  :        12.07        12.30        14.44 Mbits/s         914
 TCP download::6 (0)                  :        11.78        12.29        13.67 Mbits/s         914
 TCP download::7 (0)                  :        11.98        12.30        13.92 Mbits/s         914
 TCP totals                           :       126.34          N/A          N/A Mbits/s         914
 TCP upload avg                       :         3.86          N/A          N/A Mbits/s         914
 TCP upload sum                       :        30.90          N/A          N/A Mbits/s         914

This is a bidirectional test that only reports actual TCP goodput, neither the latency probes nor the reverse ACK traffic is accounted and yet:
Download: 95.44
Upload: 30.90

which compared to the actual shape settings of 105/36 (with 34 bytes overhead) seems sane:
theoretical maximal throughput:
105 * ((1500-8-20-20-12)/(1500+26)) = 99.08 Mbps
36 * ((1500-8-20-20-12)/(1500+26)) = 33.97 Mbps

Compared to these numbers the reported 87.499/26.531 do not seems either saturating or precise, probably neither....

@hawkinsw
Copy link
Member

So, you are saying that the "fluent" tool got you 95.44/30.90 and goresponsiveness 87.499/26.531? Just want to make sure that I am parsing what you are saying! Also, this may be the same as #12 .

@moeller0
Copy link
Author

Yes flent/netperf gave a throughput of 95.44/30.90 while goresponsiveness gave 87.499/26.531 (this is with my SQM traffic shaper configured for a gross rate of 105/36).
And yes this seems to be related to #12

@hawkinsw
Copy link
Member

hawkinsw commented Mar 28, 2022 via email

@hawkinsw
Copy link
Member

hawkinsw commented May 6, 2022

@moeller0 Would you be willing to run you

./networkQuality --config mensura.cdn-apple.com --port 443 --path /api/v1/gm/config

test with the -debug flag? I am having trouble reproducing the "short" execution times on my end.

Thank you!

@moeller0
Copy link
Author

moeller0 commented May 6, 2022

moeller@work-horse:~/CODE/goresponsiveness$ time ./networkQuality --config mensura.cdn-apple.com --port 443 --path /api/v1/gm/config  --debug > go_networkQuality_$(date +%Y%m%d_%H%M%S)_debug.out

real    0m8.479s
user    0m1.765s
sys     0m1.799s

here is the captured debug output:

Configuration: Version: 1
Small URL: https://mensura.cdn-apple.com/api/v1/gm/small
Large URL: https://mensura.cdn-apple.com/api/v1/gm/large
Upload URL: https://mensura.cdn-apple.com/api/v1/gm/slurp
Endpoint: defra3-edge-bx-011.aaplimg.com

Test will end earlier than 2022-05-06 08:57:31.828734294 +0200 CEST m=+20.000688835
05-06-2022 06:57:11 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Started a load-generating upload (id: 1).
Started a load-generating upload (id: 2).
Timeout expected to end at 2022-05-06 08:57:31.828734294 +0200 CEST m=+20.000688835
Started a load-generating upload (id: 3).
Started a load-generating upload (id: 4).
upload: Sleeping until 2022-05-06 08:57:12.950125095 +0200 CEST m=+1.122079594
Started a load-generating download (id: 5).
Started a load-generating download (id: 6).
Started a load-generating download (id: 7).
Started a load-generating download (id: 8).
download: Sleeping until 2022-05-06 08:57:12.950248684 +0200 CEST m=+1.122203239
Started getting connection for 6 @ 2022-05-06 08:57:11.950265752 +0200 CEST m=+0.122220231
Started getting connection for 8 @ 2022-05-06 08:57:11.950287638 +0200 CEST m=+0.122242140
DNS Start for 6: {mensura.cdn-apple.com}
DNS Start for 8: {mensura.cdn-apple.com}
Started getting connection for 5 @ 2022-05-06 08:57:11.950347699 +0200 CEST m=+0.122302204
DNS Start for 5: {mensura.cdn-apple.com}
Started getting connection for 7 @ 2022-05-06 08:57:11.950395827 +0200 CEST m=+0.122350335
DNS Done for 5: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
TCP Start for 5 at 2022-05-06 08:57:11.950481541 +0200 CEST m=+0.122436025
DNS Start for 7: {mensura.cdn-apple.com}
DNS Done for 6: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
DNS Done for 8: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
TCP Start for 6 at 2022-05-06 08:57:11.950529349 +0200 CEST m=+0.122483848
TCP Start for 8 at 2022-05-06 08:57:11.950564457 +0200 CEST m=+0.122518949
DNS Done for 7: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> false}
TCP Start for 7 at 2022-05-06 08:57:11.950874235 +0200 CEST m=+0.122828727
TCP Done for 5 (with error <nil>) @ 2022-05-06 08:57:11.967355325 +0200 CEST m=+0.139309840
TCP Done for 8 (with error <nil>) @ 2022-05-06 08:57:11.967696788 +0200 CEST m=+0.139651295
TCP Done for 7 (with error <nil>) @ 2022-05-06 08:57:11.967710837 +0200 CEST m=+0.139665350
TCP Done for 6 (with error <nil>) @ 2022-05-06 08:57:11.967849822 +0200 CEST m=+0.139804333
Got connection for 6 at 2022-05-06 08:57:11.988474318 +0200 CEST m=+0.160428875 with info {0xc0003b2380 false false 0s}
(lgd) Http finished writing request for 6 at 2022-05-06 08:57:11.988584367 +0200 CEST m=+0.160538874 with info {<nil>}
Got connection for 5 at 2022-05-06 08:57:11.988625632 +0200 CEST m=+0.160580180 with info {0xc00043a000 false false 0s}
(lgd) Http finished writing request for 5 at 2022-05-06 08:57:11.988712466 +0200 CEST m=+0.160666973 with info {<nil>}
Got connection for 8 at 2022-05-06 08:57:11.988877882 +0200 CEST m=+0.160832402 with info {0xc00030c380 false false 0s}
(lgd) Http finished writing request for 8 at 2022-05-06 08:57:11.988967207 +0200 CEST m=+0.160921712 with info {<nil>}
Got connection for 7 at 2022-05-06 08:57:11.990359547 +0200 CEST m=+0.162314066 with info {0xc00051c000 false false 0s}
(lgd) Http finished writing request for 7 at 2022-05-06 08:57:11.991036851 +0200 CEST m=+0.162991356 with info {<nil>}
Got the first byte of HTTP response headers for 6 at 2022-05-06 08:57:12.007705056 +0200 CEST m=+0.179659592
Got the first byte of HTTP response headers for 8 at 2022-05-06 08:57:12.009423133 +0200 CEST m=+0.181377650
Got the first byte of HTTP response headers for 5 at 2022-05-06 08:57:12.010074226 +0200 CEST m=+0.182028756
Got the first byte of HTTP response headers for 7 at 2022-05-06 08:57:12.01182549 +0200 CEST m=+0.183780018
upload: Transferred: 851968
upload: Transferred: 851968
upload: Transferred: 704512
upload: Transferred: 802816
upload: Instantaneous goodput: 3.062500 MB.
upload: Previous moving average: 0.000000 MB.
upload: Current moving average: 3.062500 MB.
upload: Moving average delta: 200.000000.
upload: Sleeping until 2022-05-06 08:57:13.950217446 +0200 CEST m=+2.122171938
download: Transferred: 2703216
download: Transferred: 2703216
download: Transferred: 2703216
download: Transferred: 2703216
download: Instantaneous goodput: 10.311951 MB.
download: Previous moving average: 0.000000 MB.
download: Current moving average: 10.311951 MB.
download: Moving average delta: 200.000000.
download: Sleeping until 2022-05-06 08:57:13.950315988 +0200 CEST m=+2.122270481
download: Transferred: 5676984
download: Transferred: 5676984
download: Transferred: 5676984
download: Transferred: 5660600
upload: Transferred: 1703936
upload: Transferred: 1703936
upload: Transferred: 1540096
upload: Transferred: 1687552
upload: Instantaneous goodput: 3.265625 MB.
upload: Previous moving average: 3.062500 MB.
upload: Current moving average: 3.164062 MB.
upload: Moving average delta: 3.262233.
upload: Network reached saturation with current flow count.
upload: New flows to add to try to increase our saturation!
Started a load-generating upload (id: 9).
download: Instantaneous goodput: 11.328400 MB.
download: Previous moving average: 10.311951 MB.
download: Current moving average: 10.820175 MB.
Started a load-generating upload (id: 10).
Started a load-generating upload (id: 11).
Started a load-generating upload (id: 12).
download: Moving average delta: 4.809970.
upload: Sleeping until 2022-05-06 08:57:14.950344797 +0200 CEST m=+3.122299330
download: Network reached saturation with current flow count.
download: New flows to add to try to increase our saturation!
Started a load-generating download (id: 13).
Started a load-generating download (id: 14).
Started a load-generating download (id: 15).
Started a load-generating download (id: 16).
download: Sleeping until 2022-05-06 08:57:14.950333283 +0200 CEST m=+3.122287801
Started getting connection for 14 @ 2022-05-06 08:57:13.950684024 +0200 CEST m=+2.122638552
Started getting connection for 13 @ 2022-05-06 08:57:13.95067687 +0200 CEST m=+2.122631411
DNS Start for 14: {mensura.cdn-apple.com}
Started getting connection for 16 @ 2022-05-06 08:57:13.950740803 +0200 CEST m=+2.122695328
DNS Start for 13: {mensura.cdn-apple.com}
Started getting connection for 15 @ 2022-05-06 08:57:13.951312726 +0200 CEST m=+2.123267274
DNS Start for 15: {mensura.cdn-apple.com}
DNS Start for 16: {mensura.cdn-apple.com}
DNS Done for 14: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
TCP Start for 14 at 2022-05-06 08:57:13.95183908 +0200 CEST m=+2.123793600
DNS Done for 16: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> true}
TCP Start for 16 at 2022-05-06 08:57:13.95280408 +0200 CEST m=+2.124758585
DNS Done for 15: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> true}
DNS Done for 13: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> true}
TCP Start for 13 at 2022-05-06 08:57:13.952925382 +0200 CEST m=+2.124879902
TCP Start for 15 at 2022-05-06 08:57:13.952866704 +0200 CEST m=+2.124821225
TCP Done for 14 (with error <nil>) @ 2022-05-06 08:57:13.970054671 +0200 CEST m=+2.142009204
TCP Done for 16 (with error <nil>) @ 2022-05-06 08:57:13.97258165 +0200 CEST m=+2.144536170
TCP Done for 13 (with error <nil>) @ 2022-05-06 08:57:13.972604838 +0200 CEST m=+2.144559376
TCP Done for 15 (with error <nil>) @ 2022-05-06 08:57:13.972656658 +0200 CEST m=+2.144611190
Got connection for 14 at 2022-05-06 08:57:13.991609825 +0200 CEST m=+2.163564360 with info {0xc000188a80 false false 0s}
(lgd) Http finished writing request for 14 at 2022-05-06 08:57:13.991747006 +0200 CEST m=+2.163701508 with info {<nil>}
Got connection for 16 at 2022-05-06 08:57:14.001398248 +0200 CEST m=+2.173352791 with info {0xc00030ce00 false false 0s}
(lgd) Http finished writing request for 16 at 2022-05-06 08:57:14.001476094 +0200 CEST m=+2.173430619 with info {<nil>}
Got connection for 15 at 2022-05-06 08:57:14.003782649 +0200 CEST m=+2.175737207 with info {0xc000188e00 false false 0s}
(lgd) Http finished writing request for 15 at 2022-05-06 08:57:14.003892936 +0200 CEST m=+2.175847439 with info {<nil>}
Got connection for 13 at 2022-05-06 08:57:14.01025475 +0200 CEST m=+2.182209288 with info {0xc00043ae00 false false 0s}
(lgd) Http finished writing request for 13 at 2022-05-06 08:57:14.010370211 +0200 CEST m=+2.182324729 with info {<nil>}
Got the first byte of HTTP response headers for 14 at 2022-05-06 08:57:14.017995914 +0200 CEST m=+2.189950450
Got the first byte of HTTP response headers for 15 at 2022-05-06 08:57:14.030911216 +0200 CEST m=+2.202865736
Got the first byte of HTTP response headers for 16 at 2022-05-06 08:57:14.031421037 +0200 CEST m=+2.203375582
Got the first byte of HTTP response headers for 13 at 2022-05-06 08:57:14.038621182 +0200 CEST m=+2.210575738
upload: Transferred: 2195456
upload: Transferred: 2146304
download: Transferred: 7282544
download: Transferred: 7282544
download: Transferred: 7282544
download: Transferred: 7282544
download: Transferred: 1277880
download: Transferred: 1310648
download: Transferred: 1294264
download: Transferred: 1294264
download: Instantaneous goodput: 11.077576 MB.
download: Previous moving average: 10.820175 MB.
upload: Transferred: 1998848
upload: Transferred: 2129920
upload: Transferred: 409600
upload: Transferred: 409600
upload: Transferred: 458752
upload: Transferred: 458752
upload: Instantaneous goodput: 3.406250 MB.
upload: Previous moving average: 3.164062 MB.
upload: Current moving average: 3.244792 MB.
upload: Moving average delta: 2.519301.
upload: Network reached saturation with current flow count.
upload: New flows to add to try to increase our saturation!
Started a load-generating upload (id: 17).
download: Current moving average: 10.905975 MB.
download: Moving average delta: 0.789833.
download: Network reached saturation with current flow count.
Started a load-generating upload (id: 18).
Started a load-generating upload (id: 19).
Started a load-generating upload (id: 20).
download: New flows to add to try to increase our saturation!
upload: Sleeping until 2022-05-06 08:57:15.950439728 +0200 CEST m=+4.122394258
Started a load-generating download (id: 21).
Started a load-generating download (id: 22).
Started a load-generating download (id: 23).
Started a load-generating download (id: 24).
download: Sleeping until 2022-05-06 08:57:15.950451316 +0200 CEST m=+4.122405837
Started getting connection for 22 @ 2022-05-06 08:57:14.950887766 +0200 CEST m=+3.122842259
Started getting connection for 24 @ 2022-05-06 08:57:14.950913278 +0200 CEST m=+3.122867782
DNS Start for 22: {mensura.cdn-apple.com}
DNS Start for 24: {mensura.cdn-apple.com}
Started getting connection for 21 @ 2022-05-06 08:57:14.950897808 +0200 CEST m=+3.122852330
Started getting connection for 23 @ 2022-05-06 08:57:14.95092402 +0200 CEST m=+3.122878546
DNS Start for 21: {mensura.cdn-apple.com}
DNS Start for 23: {mensura.cdn-apple.com}
DNS Done for 23: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
DNS Done for 22: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
DNS Done for 21: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
TCP Start for 23 at 2022-05-06 08:57:14.951385535 +0200 CEST m=+3.123340043
TCP Start for 21 at 2022-05-06 08:57:14.951426852 +0200 CEST m=+3.123381375
TCP Start for 22 at 2022-05-06 08:57:14.951443169 +0200 CEST m=+3.123397684
DNS Done for 24: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> true}
TCP Start for 24 at 2022-05-06 08:57:14.951530305 +0200 CEST m=+3.123484825
TCP Done for 23 (with error <nil>) @ 2022-05-06 08:57:14.970008921 +0200 CEST m=+3.141963464
TCP Done for 24 (with error <nil>) @ 2022-05-06 08:57:14.970067842 +0200 CEST m=+3.142022365
TCP Done for 21 (with error <nil>) @ 2022-05-06 08:57:14.970073302 +0200 CEST m=+3.142027850
TCP Done for 22 (with error <nil>) @ 2022-05-06 08:57:14.971714858 +0200 CEST m=+3.143669401
Got connection for 21 at 2022-05-06 08:57:14.995067758 +0200 CEST m=+3.167022318 with info {0xc0002d0e00 false false 0s}
(lgd) Http finished writing request for 21 at 2022-05-06 08:57:14.995228522 +0200 CEST m=+3.167183037 with info {<nil>}
Got connection for 22 at 2022-05-06 08:57:14.999076609 +0200 CEST m=+3.171031142 with info {0xc000189500 false false 0s}
(lgd) Http finished writing request for 22 at 2022-05-06 08:57:14.999203982 +0200 CEST m=+3.171158535 with info {<nil>}
Got connection for 23 at 2022-05-06 08:57:15.000843541 +0200 CEST m=+3.172798107 with info {0xc00043bc00 false false 0s}
(lgd) Http finished writing request for 23 at 2022-05-06 08:57:15.000935214 +0200 CEST m=+3.172889742 with info {<nil>}
Got connection for 24 at 2022-05-06 08:57:15.002873356 +0200 CEST m=+3.174827931 with info {0xc000189180 false false 0s}
(lgd) Http finished writing request for 24 at 2022-05-06 08:57:15.002989193 +0200 CEST m=+3.174943736 with info {<nil>}
Got the first byte of HTTP response headers for 21 at 2022-05-06 08:57:15.017146829 +0200 CEST m=+3.189101326
Got the first byte of HTTP response headers for 22 at 2022-05-06 08:57:15.024243552 +0200 CEST m=+3.196198049
Got the first byte of HTTP response headers for 23 at 2022-05-06 08:57:15.025935694 +0200 CEST m=+3.197890188
Got the first byte of HTTP response headers for 24 at 2022-05-06 08:57:15.03272715 +0200 CEST m=+3.204681639
download: Transferred: 8314664
download: Transferred: 8298280
upload: Transferred: 2441216
upload: Transferred: 2441216
upload: Transferred: 2293760
upload: Transferred: 2424832
upload: Transferred: 704512
upload: Transferred: 704512
upload: Transferred: 753664
upload: Transferred: 704512
upload: Transferred: 311296
upload: Transferred: 311296
upload: Transferred: 311296
upload: Transferred: 311296
download: Transferred: 8314664
download: Transferred: 8298280
download: Transferred: 2293616
download: Transferred: 2342768
download: Transferred: 2310000
download: Transferred: 2310000
download: Transferred: 901120
download: Transferred: 884736
download: Transferred: 884736
download: Transferred: 868352
download: Instantaneous goodput: 11.171326 MB.
download: Previous moving average: 10.905975 MB.
upload: Instantaneous goodput: 3.343750 MB.
upload: Previous moving average: 3.244792 MB.
upload: Current moving average: 3.269531 MB.
upload: Moving average delta: 0.759544.
upload: Network reached saturation with current flow count.
upload: New flows added within the last four seconds and the moving-average average is consistent!
################# upload is  saturated (3.269531MBps, 12 flows)!
download: Current moving average: 10.972313 MB.
download: Moving average delta: 0.606424.
download: Network reached saturation with current flow count.
download: New flows added within the last four seconds and the moving-average average is consistent!
################# download is  saturated (10.972313MBps, 12 flows)!
Timeout expected to end at 2022-05-06 08:57:25.950899536 +0200 CEST m=+14.122854071
(Probe) Started getting connection for 25 @ 2022-05-06 08:57:15.95100543 +0200 CEST m=+4.122959945
(Probe) DNS Start for 25: {mensura.cdn-apple.com}
(Probe) DNS Done for 25: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> false}
(Probe) TCP Start for 25 at 2022-05-06 08:57:15.951826225 +0200 CEST m=+4.123780727
(Probe) TCP Done for 25 (with error <nil>) @ 2022-05-06 08:57:15.970117292 +0200 CEST m=+4.142071809
(Probe) Got connection for 25 at 2022-05-06 08:57:15.995252409 +0200 CEST m=+4.167206926 with info {0xc0002d1880 false false 0s}
(Probe) Http finished writing request for 25 at 2022-05-06 08:57:15.99534932 +0200 CEST m=+4.167303823 with info {<nil>}
(Probe) Http response is ready for 25 at 2022-05-06 08:57:16.016457521 +0200 CEST m=+4.188412023
(Probe 25): Http TLS and Header Time: 46.340214ms
(Probe 25): Http Download Time: 63.213µs
(Probe 25): DNS Time: 626.453µs
(Probe 25): TCP Connection Time: 18.291082ms
(Probe 25) sanity vs total: 65.563334ms vs 65.320962ms
rttProbe: (Probe 25): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> false}
ConnInfo: {0xc0002d1880 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-06 08:57:15.951117875 +0200 CEST m=+4.123072377
DnsDoneTime: 2022-05-06 08:57:15.951744287 +0200 CEST m=+4.123698830
TLSDoneTime: None
ConnectStartTime: 2022-05-06 08:57:15.951826225 +0200 CEST m=+4.123780727
ConnectDoneTime: 2022-05-06 08:57:15.970117292 +0200 CEST m=+4.142071809
GetConnectionStartTime: 2022-05-06 08:57:15.95100543 +0200 CEST m=+4.122959945
GetConnectionDoneTime: 2022-05-06 08:57:15.995252409 +0200 CEST m=+4.167206926
HttpResponseReadyTime: 2022-05-06 08:57:16.016457521 +0200 CEST m=+4.188412023


sequentialRTTsTime: 0.065320962
(Probe) Started getting connection for 27 @ 2022-05-06 08:57:16.016763726 +0200 CEST m=+4.188718228
(Probe) DNS Start for 27: {mensura.cdn-apple.com}
(Probe) DNS Done for 27: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> false}
(Probe) TCP Start for 27 at 2022-05-06 08:57:16.017376329 +0200 CEST m=+4.189330834
(Probe) TCP Done for 27 (with error <nil>) @ 2022-05-06 08:57:16.036644351 +0200 CEST m=+4.208598871
(Probe) Got connection for 27 at 2022-05-06 08:57:16.062925495 +0200 CEST m=+4.234880071 with info {0xc0002d1c00 false false 0s}
(Probe) Http finished writing request for 27 at 2022-05-06 08:57:16.06305134 +0200 CEST m=+4.235005855 with info {<nil>}
(Probe) Http response is ready for 27 at 2022-05-06 08:57:16.088226836 +0200 CEST m=+4.260181366
(Probe 27): Http TLS and Header Time: 51.582495ms
(Probe 27): Http Download Time: 68.555µs
(Probe 27): DNS Time: 496.158µs
(Probe 27): TCP Connection Time: 19.268037ms
(Probe 27) sanity vs total: 71.557431ms vs 71.415245ms
rttProbe: (Probe 27): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> false}
ConnInfo: {0xc0002d1c00 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-06 08:57:16.01681654 +0200 CEST m=+4.188771045
DnsDoneTime: 2022-05-06 08:57:16.017312683 +0200 CEST m=+4.189267203
TLSDoneTime: None
ConnectStartTime: 2022-05-06 08:57:16.017376329 +0200 CEST m=+4.189330834
ConnectDoneTime: 2022-05-06 08:57:16.036644351 +0200 CEST m=+4.208598871
GetConnectionStartTime: 2022-05-06 08:57:16.016763726 +0200 CEST m=+4.188718228
GetConnectionDoneTime: 2022-05-06 08:57:16.062925495 +0200 CEST m=+4.234880071
HttpResponseReadyTime: 2022-05-06 08:57:16.088226836 +0200 CEST m=+4.260181366


sequentialRTTsTime: 0.071415245
(Probe) Started getting connection for 29 @ 2022-05-06 08:57:16.088491387 +0200 CEST m=+4.260445889
(Probe) DNS Start for 29: {mensura.cdn-apple.com}
(Probe) DNS Done for 29: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> false}
(Probe) TCP Start for 29 at 2022-05-06 08:57:16.089183319 +0200 CEST m=+4.261137822
(Probe) TCP Done for 29 (with error <nil>) @ 2022-05-06 08:57:16.109808622 +0200 CEST m=+4.281763152
(Probe) Got connection for 29 at 2022-05-06 08:57:16.137629675 +0200 CEST m=+4.309584237 with info {0xc00051dc00 false false 0s}
(Probe) Http finished writing request for 29 at 2022-05-06 08:57:16.137758283 +0200 CEST m=+4.309712798 with info {<nil>}
(Probe) Http response is ready for 29 at 2022-05-06 08:57:16.160716969 +0200 CEST m=+4.332671499
(Probe 29): Http TLS and Header Time: 50.908347ms
(Probe 29): Http Download Time: 67.771µs
(Probe 29): DNS Time: 525.558µs
(Probe 29): TCP Connection Time: 20.62533ms
(Probe 29) sanity vs total: 72.329407ms vs 72.127006ms
rttProbe: (Probe 29): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> false}
ConnInfo: {0xc00051dc00 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-06 08:57:16.088583916 +0200 CEST m=+4.260538419
DnsDoneTime: 2022-05-06 08:57:16.08910946 +0200 CEST m=+4.261063977
TLSDoneTime: None
ConnectStartTime: 2022-05-06 08:57:16.089183319 +0200 CEST m=+4.261137822
ConnectDoneTime: 2022-05-06 08:57:16.109808622 +0200 CEST m=+4.281763152
GetConnectionStartTime: 2022-05-06 08:57:16.088491387 +0200 CEST m=+4.260445889
GetConnectionDoneTime: 2022-05-06 08:57:16.137629675 +0200 CEST m=+4.309584237
HttpResponseReadyTime: 2022-05-06 08:57:16.160716969 +0200 CEST m=+4.332671499


sequentialRTTsTime: 0.072127006
(Probe) Started getting connection for 31 @ 2022-05-06 08:57:16.161401991 +0200 CEST m=+4.333356521
(Probe) DNS Start for 31: {mensura.cdn-apple.com}
(Probe) DNS Done for 31: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> false}
(Probe) TCP Start for 31 at 2022-05-06 08:57:16.162232693 +0200 CEST m=+4.334187213
(Probe) TCP Done for 31 (with error <nil>) @ 2022-05-06 08:57:16.182861483 +0200 CEST m=+4.354816003
(Probe) Got connection for 31 at 2022-05-06 08:57:16.209477131 +0200 CEST m=+4.381431667 with info {0xc0004a6700 false false 0s}
(Probe) Http finished writing request for 31 at 2022-05-06 08:57:16.20960781 +0200 CEST m=+4.381562315 with info {<nil>}
(Probe) Http response is ready for 31 at 2022-05-06 08:57:16.233414917 +0200 CEST m=+4.405369437
(Probe 31): Http TLS and Header Time: 50.553434ms
(Probe 31): Http Download Time: 65.258µs
(Probe 31): DNS Time: 669.795µs
(Probe 31): TCP Connection Time: 20.62879ms
(Probe 31) sanity vs total: 72.114524ms vs 71.917277ms
rttProbe: (Probe 31): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{2a01:b740:a04:f000::7 } {2a01:b740:a10:f000::3 } {17.253.57.205 } {17.253.55.207 }] <nil> false}
ConnInfo: {0xc0004a6700 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-06 08:57:16.161490576 +0200 CEST m=+4.333445087
DnsDoneTime: 2022-05-06 08:57:16.162160337 +0200 CEST m=+4.334114882
TLSDoneTime: None
ConnectStartTime: 2022-05-06 08:57:16.162232693 +0200 CEST m=+4.334187213
ConnectDoneTime: 2022-05-06 08:57:16.182861483 +0200 CEST m=+4.354816003
GetConnectionStartTime: 2022-05-06 08:57:16.161401991 +0200 CEST m=+4.333356521
GetConnectionDoneTime: 2022-05-06 08:57:16.209477131 +0200 CEST m=+4.381431667
HttpResponseReadyTime: 2022-05-06 08:57:16.233414917 +0200 CEST m=+4.405369437


sequentialRTTsTime: 0.071917277
(Probe) Started getting connection for 33 @ 2022-05-06 08:57:16.233718687 +0200 CEST m=+4.405673192
(Probe) DNS Start for 33: {mensura.cdn-apple.com}
(Probe) DNS Done for 33: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> false}
(Probe) TCP Start for 33 at 2022-05-06 08:57:16.234356279 +0200 CEST m=+4.406310782
(Probe) TCP Done for 33 (with error <nil>) @ 2022-05-06 08:57:16.253848411 +0200 CEST m=+4.425802941
(Probe) Got connection for 33 at 2022-05-06 08:57:16.280245523 +0200 CEST m=+4.452200095 with info {0xc000148000 false false 0s}
(Probe) Http finished writing request for 33 at 2022-05-06 08:57:16.280355687 +0200 CEST m=+4.452310189 with info {<nil>}
(Probe) Http response is ready for 33 at 2022-05-06 08:57:16.301927087 +0200 CEST m=+4.473881607
(Probe 33): Http TLS and Header Time: 48.078666ms
(Probe 33): Http Download Time: 51.98µs
(Probe 33): DNS Time: 515.496µs
(Probe 33): TCP Connection Time: 19.492159ms
(Probe 33) sanity vs total: 68.289794ms vs 68.138301ms
rttProbe: (Probe 33): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{2a01:b740:a10:f000::3 } {2a01:b740:a04:f000::7 } {17.253.55.207 } {17.253.57.205 }] <nil> false}
ConnInfo: {0xc000148000 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-06 08:57:16.23377764 +0200 CEST m=+4.405732143
DnsDoneTime: 2022-05-06 08:57:16.234293096 +0200 CEST m=+4.406247639
TLSDoneTime: None
ConnectStartTime: 2022-05-06 08:57:16.234356279 +0200 CEST m=+4.406310782
ConnectDoneTime: 2022-05-06 08:57:16.253848411 +0200 CEST m=+4.425802941
GetConnectionStartTime: 2022-05-06 08:57:16.233718687 +0200 CEST m=+4.405673192
GetConnectionDoneTime: 2022-05-06 08:57:16.280245523 +0200 CEST m=+4.452200095
HttpResponseReadyTime: 2022-05-06 08:57:16.301927087 +0200 CEST m=+4.473881607


sequentialRTTsTime: 0.068138301
Download:  87.779 Mbps ( 10.972 MBps), using 12 parallel connections.
Upload:    26.156 Mbps (  3.270 MBps), using 12 parallel connections.
Total RTTs measured: 25
RPM:  4299
In debugging mode, we will cool down.
Done cooling down.

Cooling down seems to take 2-3 seconds, so out of the 8.5 seconds total time, the saturation tests could at most have taken < 8 seconds, but at 12 flows even with bi-directional testing, I naively expected at least 12 seconds measurement time, 4 seconds for each set of 4 additional flows.

Feature request, in debug mode, could we prefix every line output with a timestamp (say in microseconds after test start-up, or milliseconds as float?)

@richb-hanover
Copy link
Contributor

richb-hanover commented May 6, 2022

Update after 7113efc fix:

  • Apple's networkQuality runs for about 9 seconds on my fiber optic connection.
  • goresponsiveness runs for as little as 5 seconds, and as much as 12 seconds

Apple's networkQuality

richb@Mac ~ % time !!
time networkQuality -v
==== SUMMARY ====
Upload capacity: 21.752 Mbps
Download capacity: 19.267 Mbps
Upload flows: 12
Download flows: 12
Responsiveness: High (3706 RPM)
Base RTT: 11
Start: 5/6/22, 6:28:00 AM
End: 5/6/22, 6:28:10 AM
OS Version: Version 12.3.1 (Build 21E258)
networkQuality -v  0.97s user 0.87s system 19% cpu 9.589 total
richb@Mac ~ % time networkQuality -v
==== SUMMARY ====
Upload capacity: 21.657 Mbps
Download capacity: 19.173 Mbps
Upload flows: 12
Download flows: 12
Responsiveness: High (3416 RPM)
Base RTT: 11
Start: 5/6/22, 6:28:18 AM
End: 5/6/22, 6:28:27 AM
OS Version: Version 12.3.1 (Build 21E258)
networkQuality -v  0.96s user 0.80s system 18% cpu 9.334 total
richb@Mac ~ % time networkQuality -v
==== SUMMARY ====
Upload capacity: 21.925 Mbps
Download capacity: 18.972 Mbps
Upload flows: 12
Download flows: 12
Responsiveness: High (3028 RPM)
Base RTT: 11
Start: 5/6/22, 6:28:30 AM
End: 5/6/22, 6:28:39 AM
OS Version: Version 12.3.1 (Build 21E258)
networkQuality -v  1.01s user 0.82s system 19% cpu 9.386 total
richb@Mac ~ % time networkQuality -v
==== SUMMARY ====
Upload capacity: 22.274 Mbps
Download capacity: 20.503 Mbps
Upload flows: 12
Download flows: 12
Responsiveness: High (3555 RPM)
Base RTT: 11
Start: 5/6/22, 7:02:33 AM
End: 5/6/22, 7:02:43 AM
OS Version: Version 12.3.1 (Build 21E258)
networkQuality -v  0.99s user 0.83s system 18% cpu 9.650 total
richb@Mac ~ % time networkQuality -v
==== SUMMARY ====
Upload capacity: 22.069 Mbps
Download capacity: 20.539 Mbps
Upload flows: 12
Download flows: 12
Responsiveness: High (2167 RPM)
Base RTT: 18
Start: 5/6/22, 7:02:45 AM
End: 5/6/22, 7:02:54 AM
OS Version: Version 12.3.1 (Build 21E258)
networkQuality -v  1.11s user 0.93s system 21% cpu 9.612 total
richb@Mac ~ % time networkQuality -v
==== SUMMARY ====
Upload capacity: 21.935 Mbps
Download capacity: 20.698 Mbps
Upload flows: 12
Download flows: 12
Responsiveness: High (2513 RPM)
Base RTT: 11
Start: 5/6/22, 7:02:56 AM
End: 5/6/22, 7:03:05 AM
OS Version: Version 12.3.1 (Build 21E258)
networkQuality -v  1.02s user 0.85s system 20% cpu 9.327 total

Average RPM: 3064

goresponsiveness

√ goresponsiveness-1 % time !!
time docker run goresp
05-06-2022 10:24:18 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:  20.843 Mbps (  2.605 MBps), using 12 parallel connections.
Upload:    22.344 Mbps (  2.793 MBps), using 20 parallel connections.
Total RTTs measured: 25
RPM:  4233
docker run goresp  0.11s user 0.07s system 1% cpu 8.962 total
√ goresponsiveness-1 % time docker run goresp
05-06-2022 10:24:34 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:  20.374 Mbps (  2.547 MBps), using 12 parallel connections.
Upload:    21.438 Mbps (  2.680 MBps), using 12 parallel connections.
Total RTTs measured: 25
RPM:  3950
docker run goresp  0.10s user 0.07s system 3% cpu 4.950 total
√ goresponsiveness-1 % time docker run goresp
05-06-2022 10:27:04 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Failed to calculate a time for sequential RTTs: Get "https://mensura.cdn-apple.com/api/v1/gm/small": EOF
Download:  19.311 Mbps (  2.414 MBps), using 20 parallel connections.
Upload:    17.562 Mbps (  2.195 MBps), using 24 parallel connections.
Total RTTs measured: 5
RPM:   511
docker run goresp  0.11s user 0.15s system 1% cpu 20.899 total
√ goresponsiveness-1 % time docker run goresp
05-06-2022 10:27:31 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:  19.624 Mbps (  2.453 MBps), using 28 parallel connections.
Upload:    21.625 Mbps (  2.703 MBps), using 20 parallel connections.
Total RTTs measured: 25
RPM:  2029
docker run goresp  0.11s user 0.10s system 1% cpu 12.521 total
√ goresponsiveness-1 % time docker run goresp
05-06-2022 10:27:47 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:  18.890 Mbps (  2.361 MBps), using 20 parallel connections.
Upload:    22.156 Mbps (  2.770 MBps), using 20 parallel connections.
Total RTTs measured: 25
RPM:  2395
docker run goresp  0.11s user 0.07s system 1% cpu 9.284 total
√ goresponsiveness-1 % time docker run goresp
05-06-2022 10:29:20 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:  20.343 Mbps (  2.543 MBps), using 12 parallel connections.
Upload:    21.688 Mbps (  2.711 MBps), using 12 parallel connections.
Total RTTs measured: 25
RPM:  4395
docker run goresp  0.11s user 0.14s system 4% cpu 5.283 total
√ goresponsiveness-1 % time docker run goresp
05-06-2022 10:29:34 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:  20.281 Mbps (  2.535 MBps), using 12 parallel connections.
Upload:    21.469 Mbps (  2.684 MBps), using 12 parallel connections.
Total RTTs measured: 25
RPM:  4347
docker run goresp  0.11s user 0.07s system 3% cpu 4.935 total

Average RPM: 3558 (excluding error run)

@moeller0
Copy link
Author

moeller0 commented May 6, 2022

I am probably exceptionally daft today, but how to interpret docker run goresp 0.11s user 0.07s system 3% cpu 4.935 total? I am missing the wall-clock time in that output, what am I missing?

@richb-hanover
Copy link
Contributor

I don't know why the times are formatted differently for my shell - all on one line, instead of separate lines. I'm using zsh, macOS 10.15.7, and the last number looks to be the wall-clock time. See:

?1 goresponsiveness-1 % time sleep 4
sleep 4  0.00s user 0.00s system 0% cpu 4.006 total

@moeller0
Copy link
Author

moeller0 commented May 6, 2022

Ah, thanks I guess I am daft today ;)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants