network-quality / goresponsiveness

A draft-ietf-ippm-responsiveness client in Go.
GNU General Public License v2.0
133 stars 10 forks source link

Incorrect BPS readings at very low link speeds #20

Open richb-hanover opened 2 years ago

richb-hanover commented 2 years ago

I have used up my data cap on my LTE wifi hotspot, consequently, my cell provider is only giving speeds much lower than 100 kbps download. This is evidenced by these tests from Speedtest.net and betterspeedtest.sh

  1. Speedtest.net shows 0.6/3.6 mbps - https://www.speedtest.net/result/13183816484

  2. Betterspeedtest.sh shows 0.4/3.25 mbps

    √ OpenWrtScripts % sh betterspeedtest.sh -t 20 -p 4.2.2.1 -H netperf-west.bufferbloat.net -n 1
    2022-05-21 21:43:10 Testing against netperf-west.bufferbloat.net (ipv4) with 1 simultaneous sessions while pinging 4.2.2.1 (20 seconds in each direction)
    ........................
    Download: 0.04 Mbps
     Latency: (in msec, 19 pings, 20.83% packet loss)
         Min: 38.601
       10pct: 38.723
      Median: 61.631
         Avg: 73.435
       90pct: 100.576
         Max: 185.555
    ......................
      Upload: 3.25 Mbps
     Latency: (in msec, 19 pings, 9.52% packet loss)
         Min: 41.995
       10pct: 43.859
      Median: 49.968
         Avg: 56.577
       90pct: 58.630
         Max: 129.630
  3. But... Go Responsiveness test sometimes shows very low speeds (expected) and ordinary speeds (8/5 mbps). In other cases, the test didn't complete normally. Here are a bunch of runs, including debugging runs.

Full output is at https://gist.github.com/richb-hanover/c9235c555d91b8fb00015995d4d2e54f

What other information could I collect? Thanks.

?1 OpenWrtScripts % docker run goresp
05-21-2022 23:20:34 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:   0.000 Mbps (  0.000 MBps), using 12 parallel connections.
Upload:     1.375 Mbps (  0.172 MBps), using 24 parallel connections.
Error occurred calculating RPM -- no probe measurements received.

√ OpenWrtScripts % docker run goresp
05-21-2022 23:21:03 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:   8.406 Mbps (  1.051 MBps), using 12 parallel connections.
Upload:     5.688 Mbps (  0.711 MBps), using 24 parallel connections.
Total RTTs measured: 25
RPM:   564

√ OpenWrtScripts % docker run goresp
05-21-2022 23:30:17 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Download:   8.562 Mbps (  1.070 MBps), using 20 parallel connections.
Upload:     3.938 Mbps (  0.492 MBps), using 28 parallel connections.
Total RTTs measured: 10
RPM:    70

√ OpenWrtScripts % docker run goresp
05-22-2022 00:49:31 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Error: Saturation could not be completed in time and no provisional rates could be accessed. Test failed.

√ OpenWrtScripts % docker run goresp --config mensura.cdn-apple.com --port 443 --path /api/v1/gm/config --debug
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: usqas2-edge-bx-018.aaplimg.com

Test will end earlier than 2022-05-22 00:50:32.423441061 +0000 UTC m=+20.001530846
Timeout expected to end at 2022-05-22 00:50:32.423441061 +0000 UTC m=+20.001530846
05-22-2022 00:50:12 UTC Go Responsiveness to mensura.cdn-apple.com:443...
Started a load-generating upload (id: 1).
Started a load-generating upload (id: 3).
Started a load-generating upload (id: 4).
Started a load-generating upload (id: 5).
upload: Sleeping until 2022-05-22 00:50:13.665373484 +0000 UTC m=+1.243463271
Started a load-generating download (id: 2).
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-22 00:50:13.665459364 +0000 UTC m=+1.243549154
Started getting connection for 8 @ 2022-05-22 00:50:12.665523999 +0000 UTC m=+0.243613788
DNS Start for 8: {mensura.cdn-apple.com}
Started getting connection for 2 @ 2022-05-22 00:50:12.665934572 +0000 UTC m=+0.244024383
DNS Start for 2: {mensura.cdn-apple.com}
Started getting connection for 6 @ 2022-05-22 00:50:12.666091335 +0000 UTC m=+0.244181124
DNS Start for 6: {mensura.cdn-apple.com}
Started getting connection for 7 @ 2022-05-22 00:50:12.66620136 +0000 UTC m=+0.244291150
DNS Start for 7: {mensura.cdn-apple.com}
DNS Done for 7: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 7 at 2022-05-22 00:50:12.670414855 +0000 UTC m=+0.248504659
DNS Done for 8: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 8 at 2022-05-22 00:50:12.670694646 +0000 UTC m=+0.248784449
DNS Done for 2: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
DNS Done for 6: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 2 at 2022-05-22 00:50:12.67081637 +0000 UTC m=+0.248906173
TCP Start for 6 at 2022-05-22 00:50:12.670893568 +0000 UTC m=+0.248983374
TCP Done for 7 (with error <nil>) @ 2022-05-22 00:50:12.718841936 +0000 UTC m=+0.296931747
TCP Done for 6 (with error <nil>) @ 2022-05-22 00:50:12.727369844 +0000 UTC m=+0.305459658
TCP Done for 2 (with error <nil>) @ 2022-05-22 00:50:12.727835253 +0000 UTC m=+0.305925079
TCP Done for 8 (with error <nil>) @ 2022-05-22 00:50:12.728239542 +0000 UTC m=+0.306329340
Got connection for 6 at 2022-05-22 00:50:12.789481776 +0000 UTC m=+0.367571565 with info {0xc000075500 false false 0s}
(lgd) Http finished writing request for 6 at 2022-05-22 00:50:12.790038078 +0000 UTC m=+0.368127865 with info {<nil>}
Got connection for 7 at 2022-05-22 00:50:12.794039882 +0000 UTC m=+0.372129668 with info {0xc000075180 false false 0s}
(lgd) Http finished writing request for 7 at 2022-05-22 00:50:12.79452216 +0000 UTC m=+0.372611943 with info {<nil>}
Got connection for 2 at 2022-05-22 00:50:12.801321402 +0000 UTC m=+0.379411191 with info {0xc0002c2000 false false 0s}
(lgd) Http finished writing request for 2 at 2022-05-22 00:50:12.8014667 +0000 UTC m=+0.379556494 with info {<nil>}
Got connection for 8 at 2022-05-22 00:50:12.805414931 +0000 UTC m=+0.383504713 with info {0xc000075880 false false 0s}
(lgd) Http finished writing request for 8 at 2022-05-22 00:50:12.805509685 +0000 UTC m=+0.383599474 with info {<nil>}
Got the first byte of HTTP response headers for 6 at 2022-05-22 00:50:12.850487631 +0000 UTC m=+0.428577465
Got the first byte of HTTP response headers for 7 at 2022-05-22 00:50:12.858748312 +0000 UTC m=+0.436838123
Got the first byte of HTTP response headers for 2 at 2022-05-22 00:50:12.871298536 +0000 UTC m=+0.449388387
Got the first byte of HTTP response headers for 8 at 2022-05-22 00:50:12.886467453 +0000 UTC m=+0.464557251
download: Transferred: 229376
download: Transferred: 163840
download: Transferred: 98304
download: Transferred: 180224
download: Instantaneous goodput: 0.640625 MB.
download: Previous moving average: 0.000000 MB.
download: Current moving average: 0.640625 MB.
download: Moving average delta: 200.000000.
download: Sleeping until 2022-05-22 00:50:14.666565687 +0000 UTC m=+2.244655468
upload: Transferred: 114688
upload: Transferred: 163840
upload: Transferred: 163840
upload: Transferred: 114688
upload: Instantaneous goodput: 0.531250 MB.
upload: Previous moving average: 0.000000 MB.
upload: Current moving average: 0.531250 MB.
upload: Moving average delta: 200.000000.
upload: Sleeping until 2022-05-22 00:50:14.666629192 +0000 UTC m=+2.244718974
upload: Transferred: 163840
upload: Transferred: 311296
upload: Transferred: 360448
upload: Transferred: 163840
upload: Instantaneous goodput: 0.421875 MB.
upload: Previous moving average: 0.531250 MB.
upload: Current moving average: 0.476562 MB.
upload: Moving average delta: -10.852713.
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).
Started a load-generating upload (id: 10).
Started a load-generating upload (id: 11).
Started a load-generating upload (id: 12).
upload: Sleeping until 2022-05-22 00:50:15.666867275 +0000 UTC m=+3.244957064
download: Transferred: 524288
download: Transferred: 393216
download: Transferred: 229376
download: Transferred: 409600
download: Instantaneous goodput: 0.843750 MB.
download: Previous moving average: 0.640625 MB.
download: Current moving average: 0.742188 MB.
download: Moving average delta: 14.689266.
download: We are unsaturated, but it still too early to add anything.
download: Sleeping until 2022-05-22 00:50:15.667170625 +0000 UTC m=+3.245260424
upload: Transferred: 212992
upload: Transferred: 458752
upload: Transferred: 507904
upload: Transferred: 212992
upload: Transferred: 65536
upload: Transferred: 65536
upload: Transferred: 65536
upload: Transferred: 65536
upload: Instantaneous goodput: 0.625000 MB.
upload: Previous moving average: 0.476562 MB.
upload: Current moving average: 0.526042 MB.
upload: Moving average delta: 9.870130.
upload: We are unsaturated, but it still too early to add anything.
upload: Sleeping until 2022-05-22 00:50:16.66738574 +0000 UTC m=+4.245475547
download: Transferred: 802816
download: Transferred: 622592
download: Transferred: 360448
download: Transferred: 638976
download: Instantaneous goodput: 0.828125 MB.
download: Previous moving average: 0.742188 MB.
download: Current moving average: 0.770833 MB.
download: Moving average delta: 3.786575.
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-22 00:50:16.667548248 +0000 UTC m=+4.245638055
Started getting connection for 13 @ 2022-05-22 00:50:15.668752137 +0000 UTC m=+3.246842038
DNS Start for 13: {mensura.cdn-apple.com}
Started getting connection for 16 @ 2022-05-22 00:50:15.669670268 +0000 UTC m=+3.247760071
DNS Start for 16: {mensura.cdn-apple.com}
Started getting connection for 15 @ 2022-05-22 00:50:15.669630615 +0000 UTC m=+3.247720412
DNS Start for 15: {mensura.cdn-apple.com}
Started getting connection for 14 @ 2022-05-22 00:50:15.669689174 +0000 UTC m=+3.247778972
DNS Start for 14: {mensura.cdn-apple.com}
DNS Done for 14: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
DNS Done for 15: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 15 at 2022-05-22 00:50:15.677048569 +0000 UTC m=+3.255138372
DNS Done for 16: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 16 at 2022-05-22 00:50:15.677119882 +0000 UTC m=+3.255209682
DNS Done for 13: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 13 at 2022-05-22 00:50:15.677284329 +0000 UTC m=+3.255374128
TCP Start for 14 at 2022-05-22 00:50:15.677035607 +0000 UTC m=+3.255125398
TCP Done for 15 (with error <nil>) @ 2022-05-22 00:50:15.946652518 +0000 UTC m=+3.524742314
TCP Done for 16 (with error <nil>) @ 2022-05-22 00:50:15.954099657 +0000 UTC m=+3.532189499
TCP Done for 13 (with error <nil>) @ 2022-05-22 00:50:15.956859192 +0000 UTC m=+3.534948992
TCP Done for 14 (with error <nil>) @ 2022-05-22 00:50:15.95685047 +0000 UTC m=+3.534940265
Got connection for 15 at 2022-05-22 00:50:16.232641797 +0000 UTC m=+3.810731591 with info {0xc00032ce00 false false 0s}
(lgd) Http finished writing request for 15 at 2022-05-22 00:50:16.232904661 +0000 UTC m=+3.810994458 with info {<nil>}
Got connection for 16 at 2022-05-22 00:50:16.234324952 +0000 UTC m=+3.812414741 with info {0xc00032d180 false false 0s}
(lgd) Http finished writing request for 16 at 2022-05-22 00:50:16.234633583 +0000 UTC m=+3.812723406 with info {<nil>}
Got connection for 13 at 2022-05-22 00:50:16.251843129 +0000 UTC m=+3.829932918 with info {0xc000594380 false false 0s}
(lgd) Http finished writing request for 13 at 2022-05-22 00:50:16.25214135 +0000 UTC m=+3.830231146 with info {<nil>}
Got connection for 14 at 2022-05-22 00:50:16.255896877 +0000 UTC m=+3.833986657 with info {0xc0002c2700 false false 0s}
(lgd) Http finished writing request for 14 at 2022-05-22 00:50:16.256055526 +0000 UTC m=+3.834145343 with info {<nil>}
Got the first byte of HTTP response headers for 15 at 2022-05-22 00:50:16.53542236 +0000 UTC m=+4.113512186
Got the first byte of HTTP response headers for 16 at 2022-05-22 00:50:16.553748838 +0000 UTC m=+4.131838633
Got the first byte of HTTP response headers for 14 at 2022-05-22 00:50:16.574846697 +0000 UTC m=+4.152936485
Got the first byte of HTTP response headers for 13 at 2022-05-22 00:50:16.596647125 +0000 UTC m=+4.174736915
upload: Transferred: 262144                                                                                       upload: Transferred: 606208
upload: Transferred: 655360
upload: Transferred: 311296
upload: Transferred: 114688
upload: Transferred: 114688
upload: Transferred: 114688
upload: Transferred: 114688
upload: Instantaneous goodput: 0.609375 MB.
upload: Previous moving average: 0.526042 MB.
upload: Current moving average: 0.546875 MB.
upload: Moving average delta: 3.883495.
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: Transferred: 1114040
download: Transferred: 819200
download: Transferred: 475136
download: Transferred: 884736
Started a load-generating upload (id: 18).
Started a load-generating upload (id: 19).
Started a load-generating upload (id: 20).
upload: Sleeping until 2022-05-22 00:50:17.668467508 +0000 UTC m=+5.246557282
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Instantaneous goodput: 0.828056 MB.
download: Previous moving average: 0.770833 MB.
download: Current moving average: 0.785139 MB.
download: Moving average delta: 1.838818.
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: 21).
Started a load-generating download (id: 22).
Started getting connection for 21 @ 2022-05-22 00:50:16.669564317 +0000 UTC m=+4.247654103
DNS Start for 21: {mensura.cdn-apple.com}
Started a load-generating download (id: 23).
Started a load-generating download (id: 24).
Started getting connection for 22 @ 2022-05-22 00:50:16.670158021 +0000 UTC m=+4.248247806
DNS Start for 22: {mensura.cdn-apple.com}
download: Sleeping until 2022-05-22 00:50:17.668762057 +0000 UTC m=+5.246851832
Started getting connection for 23 @ 2022-05-22 00:50:16.670391906 +0000 UTC m=+4.248481693
Started getting connection for 24 @ 2022-05-22 00:50:16.670451694 +0000 UTC m=+4.248541482
DNS Start for 24: {mensura.cdn-apple.com}
DNS Start for 23: {mensura.cdn-apple.com}
DNS Done for 22: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 22 at 2022-05-22 00:50:16.672782869 +0000 UTC m=+4.250872662
DNS Done for 23: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 23 at 2022-05-22 00:50:16.672956869 +0000 UTC m=+4.251046673
DNS Done for 24: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 24 at 2022-05-22 00:50:16.673112219 +0000 UTC m=+4.251202013
DNS Done for 21: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 21 at 2022-05-22 00:50:16.673337823 +0000 UTC m=+4.251427619
TCP Start for 22 at 2022-05-22 00:50:16.973108408 +0000 UTC m=+4.551198204TCP Start for 24 at 2022-05-22 00:50:16.973152333 +0000 UTC m=+4.551242111
TCP Done for 22 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.97320759 +0000 UTC m=+4.551297373
TCP Start for 22 at 2022-05-22 00:50:16.973263291 +0000 UTC m=+4.551353075
TCP Done for 24 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.973270539 +0000 UTC m=+4.551360330
TCP Start for 24 at 2022-05-22 00:50:16.9732815 +0000 UTC m=+4.551371291
TCP Start for 23 at 2022-05-22 00:50:16.973111755 +0000 UTC m=+4.551201538
TCP Done for 22 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.97330009 +0000 UTC m=+4.551389874
TCP Done for 24 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.973305798 +0000 UTC m=+4.551395582
TCP Done for 23 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.973309898 +0000 UTC m=+4.551399681
TCP Start for 23 at 2022-05-22 00:50:16.973323179 +0000 UTC m=+4.551412962
TCP Start for 21 at 2022-05-22 00:50:16.973342313 +0000 UTC m=+4.551432094
TCP Done for 23 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.973406706 +0000 UTC m=+4.551496497
TCP Done for 21 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.973438445 +0000 UTC m=+4.551528222
TCP Start for 21 at 2022-05-22 00:50:16.9734878 +0000 UTC m=+4.551577589
TCP Done for 21 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:16.97358931 +0000 UTC m=+4.551679101
TCP Done for 22 (with error <nil>) @ 2022-05-22 00:50:17.094005364 +0000 UTC m=+4.672095161
TCP Done for 24 (with error <nil>) @ 2022-05-22 00:50:17.094711004 +0000 UTC m=+4.672800802
TCP Done for 23 (with error <nil>) @ 2022-05-22 00:50:17.097279226 +0000 UTC m=+4.675369027
TCP Done for 21 (with error <nil>) @ 2022-05-22 00:50:17.112170751 +0000 UTC m=+4.690260529
Got connection for 22 at 2022-05-22 00:50:17.574764909 +0000 UTC m=+5.152854704 with info {0xc0000d9500 false false 0s}
(lgd) Http finished writing request for 22 at 2022-05-22 00:50:17.575099116 +0000 UTC m=+5.153188923 with info {<nil>}
Got connection for 23 at 2022-05-22 00:50:17.586686669 +0000 UTC m=+5.164776450 with info {0xc0002c3880 false false 0s}
(lgd) Http finished writing request for 23 at 2022-05-22 00:50:17.586979698 +0000 UTC m=+5.165069509 with info {<nil>}
Got connection for 24 at 2022-05-22 00:50:17.609288184 +0000 UTC m=+5.187377969 with info {0xc00032dc00 false false 0s}
(lgd) Http finished writing request for 24 at 2022-05-22 00:50:17.609392477 +0000 UTC m=+5.187482267 with info {<nil>}
Got connection for 21 at 2022-05-22 00:50:17.62600713 +0000 UTC m=+5.204096931 with info {0xc0000d9880 false false 0s}
(lgd) Http finished writing request for 21 at 2022-05-22 00:50:17.626141544 +0000 UTC m=+5.204231345 with info {<nil>}
upload: Transferred: 311296
upload: Transferred: 704512
upload: Transferred: 753664
upload: Transferred: 311296
upload: Transferred: 163840
upload: Transferred: 114688
upload: Transferred: 163840
upload: Transferred: 163840
upload: Transferred: 65536
upload: Transferred: 65536
upload: Transferred: 65536
upload: Transferred: 65536
upload: Instantaneous goodput: 0.625000 MB.
upload: Previous moving average: 0.546875 MB.
upload: Current moving average: 0.570312 MB.
upload: Moving average delta: 4.195804.
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: 25).
download: Transferred: 1327032
download: Transferred: 999424
download: Transferred: 589824
download: Transferred: 1064888
download: Transferred: 65536
download: Transferred: 32768
download: Transferred: 65536
download: Transferred: 65536
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Instantaneous goodput: 0.874931 MB.
download: Previous moving average: 0.785139 MB.
download: Current moving average: 0.843716 MB.
download: Moving average delta: 7.192364.
download: We are unsaturated, but it still too early to add anything.
download: Sleeping until 2022-05-22 00:50:18.66933924 +0000 UTC m=+6.247429025
Started a load-generating upload (id: 26).
Started a load-generating upload (id: 27).
Started a load-generating upload (id: 28).
upload: Sleeping until 2022-05-22 00:50:18.669221378 +0000 UTC m=+6.247311160
Got the first byte of HTTP response headers for 22 at 2022-05-22 00:50:18.11658778 +0000 UTC m=+5.694677581
Got the first byte of HTTP response headers for 23 at 2022-05-22 00:50:18.136576972 +0000 UTC m=+5.714666774
Got the first byte of HTTP response headers for 24 at 2022-05-22 00:50:18.15849424 +0000 UTC m=+5.736584027
Got the first byte of HTTP response headers for 21 at 2022-05-22 00:50:18.174960381 +0000 UTC m=+5.753050165
download: Transferred: 1540024
download: Transferred: 1130424
download: Transferred: 688128
download: Transferred: 1212344
download: Transferred: 147456
download: Transferred: 81920
download: Transferred: 131072
download: Transferred: 131072
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Instantaneous goodput: 0.812431 MB.
download: Previous moving average: 0.843716 MB.
download: Current moving average: 0.835886 MB.
download: Moving average delta: -0.932324.
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: 29).
Started a load-generating download (id: 30).
Started a load-generating download (id: 31).
Started a load-generating download (id: 32).
download: Sleeping until 2022-05-22 00:50:19.670247942 +0000 UTC m=+7.248337733
Started getting connection for 30 @ 2022-05-22 00:50:18.670586656 +0000 UTC m=+6.248676469
Started getting connection for 32 @ 2022-05-22 00:50:18.670431962 +0000 UTC m=+6.248521776
DNS Start for 30: {mensura.cdn-apple.com}
DNS Start for 32: {mensura.cdn-apple.com}
Started getting connection for 31 @ 2022-05-22 00:50:18.670646744 +0000 UTC m=+6.248736548
DNS Start for 31: {mensura.cdn-apple.com}
upload: Transferred: 311296
upload: Transferred: 802816
upload: Transferred: 802816
upload: Transferred: 360448
upload: Transferred: 212992
upload: Transferred: 163840
upload: Transferred: 163840
upload: Transferred: 163840
upload: Transferred: 65536
upload: Transferred: 65536
upload: Transferred: 65536
upload: Transferred: 65536
upload: Transferred: 0
upload: Transferred: 0
upload: Transferred: 0
upload: Transferred: 0
upload: Instantaneous goodput: 0.281250 MB.
upload: Previous moving average: 0.570312 MB.
upload: Current moving average: 0.535156 MB.
upload: Moving average delta: -6.360424.
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 (0.535156MBps, 16 flows)!
Started getting connection for 29 @ 2022-05-22 00:50:18.670419802 +0000 UTC m=+6.248509644
DNS Start for 29: {mensura.cdn-apple.com}
DNS Done for 29: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
DNS Done for 32: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
DNS Done for 30: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 29 at 2022-05-22 00:50:18.677383045 +0000 UTC m=+6.255472839
TCP Start for 30 at 2022-05-22 00:50:18.677389015 +0000 UTC m=+6.255478814
DNS Done for 31: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 32 at 2022-05-22 00:50:18.677582121 +0000 UTC m=+6.255671920
TCP Start for 31 at 2022-05-22 00:50:18.677584285 +0000 UTC m=+6.255674094
TCP Start for 31 at 2022-05-22 00:50:18.978332884 +0000 UTC m=+6.556422686
TCP Start for 32 at 2022-05-22 00:50:18.978462841 +0000 UTC m=+6.556552639
TCP Start for 30 at 2022-05-22 00:50:18.978738775 +0000 UTC m=+6.556828572
TCP Done for 31 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.978867098 +0000 UTC m=+6.556956897
TCP Start for 31 at 2022-05-22 00:50:18.978894089 +0000 UTC m=+6.556983887
TCP Start for 29 at 2022-05-22 00:50:18.978716081 +0000 UTC m=+6.556805874
TCP Done for 32 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.978858912 +0000 UTC m=+6.556948712
TCP Start for 32 at 2022-05-22 00:50:18.979409031 +0000 UTC m=+6.557498831
TCP Done for 31 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.97924509 +0000 UTC m=+6.557334872
TCP Done for 30 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.979292288 +0000 UTC m=+6.557382079
TCP Start for 30 at 2022-05-22 00:50:18.979592121 +0000 UTC m=+6.557681907
TCP Done for 30 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.979718632 +0000 UTC m=+6.557808446
TCP Done for 29 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.979299342 +0000 UTC m=+6.557389145
TCP Start for 29 at 2022-05-22 00:50:18.979841572 +0000 UTC m=+6.557931386
TCP Done for 32 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.979957767 +0000 UTC m=+6.558047565
TCP Done for 29 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:18.979977786 +0000 UTC m=+6.558067585
TCP Done for 29 (with error <nil>) @ 2022-05-22 00:50:19.416019469 +0000 UTC m=+6.994109289
TCP Done for 32 (with error <nil>) @ 2022-05-22 00:50:19.420479045 +0000 UTC m=+6.998568843
TCP Done for 30 (with error <nil>) @ 2022-05-22 00:50:19.420804279 +0000 UTC m=+6.998894088
TCP Done for 31 (with error <nil>) @ 2022-05-22 00:50:19.42713718 +0000 UTC m=+7.005226985
download: Transferred: 1687480
download: Transferred: 1261496
download: Transferred: 819200
download: Transferred: 1343416
download: Transferred: 180224
download: Transferred: 98304
download: Transferred: 163840
download: Transferred: 180224
download: Transferred: 49152
download: Transferred: 65536
download: Transferred: 65536
download: Transferred: 65536
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Instantaneous goodput: 0.875000 MB.
download: Previous moving average: 0.835886 MB.
download: Current moving average: 0.847605 MB.
download: Moving average delta: 1.392197.
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: 33).
Started a load-generating download (id: 34).
Started a load-generating download (id: 35).
Started a load-generating download (id: 36).
download: Sleeping until 2022-05-22 00:50:20.670888581 +0000 UTC m=+8.248978372
Started getting connection for 34 @ 2022-05-22 00:50:19.672531424 +0000 UTC m=+7.250621222
Started getting connection for 35 @ 2022-05-22 00:50:19.67279644 +0000 UTC m=+7.250886240
DNS Start for 35: {mensura.cdn-apple.com}
Started getting connection for 36 @ 2022-05-22 00:50:19.67308611 +0000 UTC m=+7.251175935
DNS Start for 34: {mensura.cdn-apple.com}
DNS Start for 36: {mensura.cdn-apple.com}
Started getting connection for 33 @ 2022-05-22 00:50:19.672491499 +0000 UTC m=+7.250581325
DNS Start for 33: {mensura.cdn-apple.com}
DNS Done for 33: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
DNS Done for 34: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
DNS Done for 35: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 35 at 2022-05-22 00:50:19.680711478 +0000 UTC m=+7.258801289
TCP Start for 34 at 2022-05-22 00:50:19.680745557 +0000 UTC m=+7.258835355
DNS Done for 36: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> true}
TCP Start for 36 at 2022-05-22 00:50:19.681081177 +0000 UTC m=+7.259170977
TCP Start for 33 at 2022-05-22 00:50:19.681370988 +0000 UTC m=+7.259460766
TCP Start for 34 at 2022-05-22 00:50:19.98166027 +0000 UTC m=+7.559750097
TCP Start for 36 at 2022-05-22 00:50:19.981726603 +0000 UTC m=+7.559816451
TCP Start for 33 at 2022-05-22 00:50:19.981809086 +0000 UTC m=+7.559898907
TCP Done for 34 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.981897673 +0000 UTC m=+7.559987518
TCP Start for 34 at 2022-05-22 00:50:19.981925962 +0000 UTC m=+7.560015802
TCP Done for 33 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.981974021 +0000 UTC m=+7.560063867
TCP Start for 33 at 2022-05-22 00:50:19.982067263 +0000 UTC m=+7.560157071
TCP Done for 36 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.982026894 +0000 UTC m=+7.560116736
TCP Done for 33 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.982156192 +0000 UTC m=+7.560246012
TCP Start for 36 at 2022-05-22 00:50:19.982163515 +0000 UTC m=+7.560253363
TCP Start for 35 at 2022-05-22 00:50:19.982147344 +0000 UTC m=+7.560237202
TCP Done for 35 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.983071366 +0000 UTC m=+7.561161191
TCP Done for 36 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.982299098 +0000 UTC m=+7.560388919
TCP Done for 34 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.982001573 +0000 UTC m=+7.560091394
TCP Start for 35 at 2022-05-22 00:50:19.983476279 +0000 UTC m=+7.561566073
TCP Done for 35 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:19.983890308 +0000 UTC m=+7.561980118
Got connection for 32 at 2022-05-22 00:50:20.368856735 +0000 UTC m=+7.946946520 with info {0xc0003b2380 false false 0s}
(lgd) Http finished writing request for 32 at 2022-05-22 00:50:20.369050589 +0000 UTC m=+7.947140378 with info {<nil>}
Got connection for 30 at 2022-05-22 00:50:20.395813154 +0000 UTC m=+7.973902932 with info {0xc0001be700 false false 0s}
(lgd) Http finished writing request for 30 at 2022-05-22 00:50:20.395998071 +0000 UTC m=+7.974087869 with info {<nil>}
Got connection for 29 at 2022-05-22 00:50:20.39785657 +0000 UTC m=+7.975946348 with info {0xc00037c380 false false 0s}
(lgd) Http finished writing request for 29 at 2022-05-22 00:50:20.398081016 +0000 UTC m=+7.976170794 with info {<nil>}
Got connection for 31 at 2022-05-22 00:50:20.398315529 +0000 UTC m=+7.976405307 with info {0xc000482000 false false 0s}
(lgd) Http finished writing request for 31 at 2022-05-22 00:50:20.398419923 +0000 UTC m=+7.976509702 with info {<nil>}
TCP Done for 35 (with error <nil>) @ 2022-05-22 00:50:20.668297349 +0000 UTC m=+8.246387168
TCP Done for 34 (with error <nil>) @ 2022-05-22 00:50:20.668298578 +0000 UTC m=+8.246388419
TCP Done for 33 (with error <nil>) @ 2022-05-22 00:50:20.67006384 +0000 UTC m=+8.248153650
TCP Done for 36 (with error <nil>) @ 2022-05-22 00:50:20.670179002 +0000 UTC m=+8.248268798
download: Transferred: 1851320
download: Transferred: 1408952
download: Transferred: 950272
download: Transferred: 1507256
download: Transferred: 229376
download: Transferred: 131072
download: Transferred: 212992
download: Transferred: 212992
download: Transferred: 81920
download: Transferred: 114688
download: Transferred: 98304
download: Transferred: 98304
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Transferred: 0
download: Instantaneous goodput: 0.875000 MB.
download: Previous moving average: 0.847605 MB.
download: Current moving average: 0.859341 MB.
download: Moving average delta: 1.375078.
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 (0.859341MBps, 20 flows)!
Timeout expected to end at 2022-05-22 00:50:30.674430147 +0000 UTC m=+18.252519939
(Probe) Started getting connection for 37 @ 2022-05-22 00:50:20.674896882 +0000 UTC m=+8.252986672
(Probe) DNS Start for 37: {mensura.cdn-apple.com}
(Probe) DNS Done for 37: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> false}
(Probe) TCP Start for 37 at 2022-05-22 00:50:20.679702599 +0000 UTC m=+8.257792398
(Probe) TCP Start for 37 at 2022-05-22 00:50:20.980044798 +0000 UTC m=+8.558134590
(Probe) TCP Done for 37 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:20.980312445 +0000 UTC m=+8.558402228
(Probe) TCP Start for 37 at 2022-05-22 00:50:20.98036767 +0000 UTC m=+8.558457454
(Probe) TCP Done for 37 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:20.980424586 +0000 UTC m=+8.558514369
Got the first byte of HTTP response headers for 32 at 2022-05-22 00:50:21.423154158 +0000 UTC m=+9.001243967
Got the first byte of HTTP response headers for 30 at 2022-05-22 00:50:21.438058083 +0000 UTC m=+9.016147882
Got the first byte of HTTP response headers for 31 at 2022-05-22 00:50:21.467083676 +0000 UTC m=+9.045173459
Got the first byte of HTTP response headers for 29 at 2022-05-22 00:50:21.477917024 +0000 UTC m=+9.056006803
Got connection for 35 at 2022-05-22 00:50:21.749228884 +0000 UTC m=+9.327318676 with info {0xc0003b2700 false false 0s}
Got connection for 34 at 2022-05-22 00:50:21.749335166 +0000 UTC m=+9.327424979 with info {0xc000482380 false false 0s}
(lgd) Http finished writing request for 35 at 2022-05-22 00:50:21.749402932 +0000 UTC m=+9.327492723 with info {<nil>}
(lgd) Http finished writing request for 34 at 2022-05-22 00:50:21.749774714 +0000 UTC m=+9.327864503 with info {<nil>}
Got connection for 33 at 2022-05-22 00:50:21.768603509 +0000 UTC m=+9.346693316 with info {0xc0003b2a80 false false 0s}
(lgd) Http finished writing request for 33 at 2022-05-22 00:50:21.76872164 +0000 UTC m=+9.346811418 with info {<nil>}
(Probe) TCP Done for 37 (with error <nil>) @ 2022-05-22 00:50:22.650116438 +0000 UTC m=+10.249484547
Got the first byte of HTTP response headers for 34 at 2022-05-22 00:50:22.687193432 +0000 UTC m=+10.286561506
Got the first byte of HTTP response headers for 35 at 2022-05-22 00:50:22.699467027 +0000 UTC m=+10.298835109
Got the first byte of HTTP response headers for 33 at 2022-05-22 00:50:22.721994678 +0000 UTC m=+10.321362745
(Probe) Got connection for 37 at 2022-05-22 00:50:23.397089998 +0000 UTC m=+10.996458082 with info {0xc0001bf180 false false 0s}
(Probe) Http finished writing request for 37 at 2022-05-22 00:50:23.397248041 +0000 UTC m=+10.996616125 with info {<nil>}
(Probe) Http response is ready for 37 at 2022-05-22 00:50:24.450531808 +0000 UTC m=+12.049899910
(Probe 37): Http TLS and Header Time: 1.800415363s
(Probe 37): Http Download Time: 137.913µs
(Probe 37): DNS Time: 4.187129ms
(Probe 37): TCP Connection Time: 1.691027093s
(Probe 37) sanity vs total: 3.797084448s vs 3.495767498s
rttProbe: (Probe 37): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> false}
ConnInfo: {0xc0001bf180 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-22 00:50:20.67525556 +0000 UTC m=+8.253345347
DnsDoneTime: 2022-05-22 00:50:20.679442696 +0000 UTC m=+8.257532476
TLSDoneTime: None
ConnectStartTime: 2022-05-22 00:50:20.98036767 +0000 UTC m=+8.558457454
ConnectDoneTime: 2022-05-22 00:50:22.650116438 +0000 UTC m=+10.249484547
GetConnectionStartTime: 2022-05-22 00:50:20.674896882 +0000 UTC m=+8.252986672
GetConnectionDoneTime: 2022-05-22 00:50:23.397089998 +0000 UTC m=+10.996458082
HttpResponseReadyTime: 2022-05-22 00:50:24.450531808 +0000 UTC m=+12.049899910

sequentialRTTsTime: 3.495767498
(Probe) Started getting connection for 39 @ 2022-05-22 00:50:24.451827283 +0000 UTC m=+12.051195407
(Probe) DNS Start for 39: {mensura.cdn-apple.com}
(Probe) DNS Done for 39: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> false}
(Probe) TCP Start for 39 at 2022-05-22 00:50:24.456935078 +0000 UTC m=+12.056303163
(Probe) TCP Start for 39 at 2022-05-22 00:50:24.757614389 +0000 UTC m=+12.356982504
(Probe) TCP Done for 39 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:24.757846717 +0000 UTC m=+12.357214854
(Probe) TCP Start for 39 at 2022-05-22 00:50:24.758091015 +0000 UTC m=+12.357459135
(Probe) TCP Done for 39 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:24.758585007 +0000 UTC m=+12.357953110
(Probe) TCP Done for 39 (with error <nil>) @ 2022-05-22 00:50:25.449501163 +0000 UTC m=+13.048869242
Got connection for 36 at 2022-05-22 00:50:25.697802262 +0000 UTC m=+13.297170341 with info {0xc000482700 false false 0s}
(lgd) Http finished writing request for 36 at 2022-05-22 00:50:25.698073887 +0000 UTC m=+13.297441968 with info {<nil>}
(Probe) Got connection for 39 at 2022-05-22 00:50:26.34391607 +0000 UTC m=+13.943284171 with info {0xc0001bf880 false false 0s}
(Probe) Http finished writing request for 39 at 2022-05-22 00:50:26.344117839 +0000 UTC m=+13.943485984 with info {<nil>}
Got the first byte of HTTP response headers for 36 at 2022-05-22 00:50:26.702738775 +0000 UTC m=+14.302106907
(Probe) Http response is ready for 39 at 2022-05-22 00:50:27.401060307 +0000 UTC m=+15.000428464
(Probe 39): Http TLS and Header Time: 1.951559222s
(Probe 39): Http Download Time: 305.388µs
(Probe 39): DNS Time: 4.8892ms
(Probe 39): TCP Connection Time: 691.410107ms
(Probe 39) sanity vs total: 2.94957284s vs 2.648163917s
rttProbe: (Probe 39): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> false}
ConnInfo: {0xc0001bf880 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-22 00:50:24.451927713 +0000 UTC m=+12.051295798
DnsDoneTime: 2022-05-22 00:50:24.456816928 +0000 UTC m=+12.056184998
TLSDoneTime: None
ConnectStartTime: 2022-05-22 00:50:24.758091015 +0000 UTC m=+12.357459135
ConnectDoneTime: 2022-05-22 00:50:25.449501163 +0000 UTC m=+13.048869242
GetConnectionStartTime: 2022-05-22 00:50:24.451827283 +0000 UTC m=+12.051195407
GetConnectionDoneTime: 2022-05-22 00:50:26.34391607 +0000 UTC m=+13.943284171
HttpResponseReadyTime: 2022-05-22 00:50:27.401060307 +0000 UTC m=+15.000428464

sequentialRTTsTime: 2.6481639169999998
(Probe) Started getting connection for 41 @ 2022-05-22 00:50:27.402061786 +0000 UTC m=+15.001429871
(Probe) DNS Start for 41: {mensura.cdn-apple.com}
(Probe) DNS Done for 41: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> false}
(Probe) TCP Start for 41 at 2022-05-22 00:50:27.407116292 +0000 UTC m=+15.006484373
(Probe) TCP Start for 41 at 2022-05-22 00:50:27.70880768 +0000 UTC m=+15.308175945
(Probe) TCP Done for 41 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:27.70909035 +0000 UTC m=+15.308458512
(Probe) TCP Start for 41 at 2022-05-22 00:50:27.709209625 +0000 UTC m=+15.308577764
(Probe) TCP Done for 41 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:27.709310973 +0000 UTC m=+15.308679122
(Probe) TCP Done for 41 (with error <nil>) @ 2022-05-22 00:50:28.449222832 +0000 UTC m=+16.048590937
(Probe) Got connection for 41 at 2022-05-22 00:50:29.394008048 +0000 UTC m=+16.993376127 with info {0xc00037d880 false false 0s}
(Probe) Http finished writing request for 41 at 2022-05-22 00:50:29.394191008 +0000 UTC m=+16.993559128 with info {<nil>}
(Probe) Http response is ready for 41 at 2022-05-22 00:50:30.304185354 +0000 UTC m=+17.903553439
(Probe 41): Http TLS and Header Time: 1.854962502s
(Probe 41): Http Download Time: 129.887µs
(Probe 41): DNS Time: 4.742304ms
(Probe 41): TCP Connection Time: 740.013173ms
(Probe 41) sanity vs total: 2.902365692s vs 2.599847866s
rttProbe: (Probe 41): stats: DnsStart: {mensura.cdn-apple.com}
DnsDone: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> false}
ConnInfo: {0xc00037d880 false false 0s}
HttpInfo: {<nil>}
TLSConnInfo: {0 false false 0  false  [] [] [] [] [] <nil>}
ConnectDoneError: <nil>
DnsStartTime: 2022-05-22 00:50:27.402199636 +0000 UTC m=+15.001567721
DnsDoneTime: 2022-05-22 00:50:27.40694194 +0000 UTC m=+15.006310025
TLSDoneTime: None
ConnectStartTime: 2022-05-22 00:50:27.709209625 +0000 UTC m=+15.308577764
ConnectDoneTime: 2022-05-22 00:50:28.449222832 +0000 UTC m=+16.048590937
GetConnectionStartTime: 2022-05-22 00:50:27.402061786 +0000 UTC m=+15.001429871
GetConnectionDoneTime: 2022-05-22 00:50:29.394008048 +0000 UTC m=+16.993376127
HttpResponseReadyTime: 2022-05-22 00:50:30.304185354 +0000 UTC m=+17.903553439

sequentialRTTsTime: 2.599847866
(Probe) Started getting connection for 43 @ 2022-05-22 00:50:30.304611979 +0000 UTC m=+17.903980061
(Probe) DNS Start for 43: {mensura.cdn-apple.com}
(Probe) DNS Done for 43: {[{17.253.21.206 } {17.253.21.202 } {2620:149:a10:f100::4 } {2620:149:a10:f000::1 }] <nil> false}
(Probe) TCP Start for 43 at 2022-05-22 00:50:30.309269532 +0000 UTC m=+17.908637615
(Probe) TCP Start for 43 at 2022-05-22 00:50:30.609858901 +0000 UTC m=+18.209227025
(Probe) TCP Done for 43 (with error dial tcp [2620:149:a10:f100::4]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:30.6101186 +0000 UTC m=+18.209486732
(Probe) TCP Start for 43 at 2022-05-22 00:50:30.610145279 +0000 UTC m=+18.209513388
(Probe) TCP Done for 43 (with error dial tcp [2620:149:a10:f000::1]:443: connect: cannot assign requested address) @ 2022-05-22 00:50:30.610199897 +0000 UTC m=+18.209568006
Timeout ended at 2022-05-22 00:50:30.653573228 +0000 UTC m=+18.252941328
Download:   6.875 Mbps (  0.859 MBps), using 20 parallel connections.
Upload:     4.281 Mbps (  0.535 MBps), using 16 parallel connections.
Total RTTs measured: 15
RPM:   103
In debugging mode, we will cool down.
(Probe) TCP Done for 43 (with error dial tcp 17.253.21.206:443: operation was canceled) @ 2022-05-22 00:50:30.655264983 +0000 UTC m=+18.254633083
Done cooling down.

... see below. for more...

Remainder of output is at https://gist.github.com/richb-hanover/c9235c555d91b8fb00015995d4d2e54f

hawkinsw commented 2 years ago

Thanks for the report.