feat: add recovery:loss_timer_updated qlog events#3437
Conversation
bb93845 to
3c91bbb
Compare
There was a problem hiding this comment.
Pull request overview
This PR adds richer qlog instrumentation around loss-recovery timers (PTO/loss detection), alongside some supporting qlog plumbing and congestion-control pacing metrics, to improve observability during recovery behavior.
Changes:
- Emit qlog
loss_timer_updatedevents on PTO set/expiry/cancel points in loss recovery, with new unit tests validating the presence of these events. - Extend qlog metric emission to include a pacing rate metric, including a new
Pacer::rate()helper and CC integration. - Adjust qlog streamer importance threshold handling (and error handling) to support emitting these new events.
Reviewed changes
Copilot reviewed 4 out of 4 changed files in this pull request and generated 3 comments.
Show a summary per file
| File | Description |
|---|---|
test-fixture/src/lib.rs |
Updates the test qlog streamer importance threshold used by fixtures. |
neqo-transport/src/recovery/mod.rs |
Adds qlog loss-timer set/expired/cancelled events and accompanying tests. |
neqo-transport/src/qlog.rs |
Implements helpers/types to emit loss_timer_updated events and adds a pacing rate metric. |
neqo-transport/src/pace.rs |
Refactors pacing math, adds reusable byte-rate helpers, and introduces unit tests for rate calculation. |
neqo-transport/src/cc/classic_cc.rs |
Emits pacing-rate metrics via qlog and tracks last RTT to include pacing rate in more CC state transitions. |
neqo-common/src/qlog.rs |
Adjusts qlog streamer importance threshold and treats qlog::Error::Done as non-fatal. |
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #3437 +/- ##
==========================================
+ Coverage 94.12% 94.18% +0.06%
==========================================
Files 125 129 +4
Lines 38339 38766 +427
Branches 38339 38766 +427
==========================================
+ Hits 36086 36512 +426
+ Misses 1412 1404 -8
- Partials 841 850 +9
Flags with carried forward coverage won't be shown. Click here to find out more.
|
recovery:loss_timer_updated qlog events
3c91bbb to
e703109
Compare
Merging this PR will degrade performance by 49.28%
Performance Changes
Comparing |
e703109 to
027232e
Compare
mxinden
left a comment
There was a problem hiding this comment.
Other than the seemingly unrelated change, this looks good to me.
Sorry, which change is this? |
027232e to
d9ff209
Compare
Also fix `Qlog::add_event_with_stream` incorrectly treating `qlog::Error::Done` (event filtered by importance level) as fatal, and switch the default qlog importance from `Base` to `Extra` — no other `Extra`-importance events are implemented so this adds no overhead.
d9ff209 to
d6a5f0c
Compare
Was referring to the |
Failed Interop TestsQUIC Interop Runner, client vs. server, differences relative to
All resultsSucceeded Interop TestsQUIC Interop Runner, client vs. server neqo-pr as client
neqo-pr as server
Unsupported Interop TestsQUIC Interop Runner, client vs. server neqo-pr as client
neqo-pr as server
|
Client/server transfer resultsPerformance differences relative to 46de5bb. Transfer of 33554432 bytes over loopback, min. 100 runs. All unit-less numbers are in milliseconds.
Table above only shows statistically significant changes. See all results below. All resultsTransfer of 33554432 bytes over loopback, min. 100 runs. All unit-less numbers are in milliseconds.
Download data for |
Benchmark resultsSignificant performance differences relative to 46de5bb. transfer/1-conn/1-100mb-req (aka. Upload)/mtu-1504: 💚 Performance has improved by -1.5680%. time: [204.76 ms 205.10 ms 205.49 ms]
thrpt: [486.64 MiB/s 487.56 MiB/s 488.38 MiB/s]
change:
time: [-1.8861% -1.5680% -1.2751] (p = 0.00 < 0.05)
thrpt: [+1.2916% +1.5930% +1.9224]
Performance has improved.
Found 3 outliers among 100 measurements (3.00%)
2 (2.00%) high mild
1 (1.00%) high severeAll resultstransfer/1-conn/1-100mb-resp (aka. Download)/mtu-1504: Change within noise threshold. time: [202.77 ms 203.14 ms 203.50 ms]
thrpt: [491.41 MiB/s 492.28 MiB/s 493.16 MiB/s]
change:
time: [-0.6200% -0.3640% -0.1266] (p = 0.00 < 0.05)
thrpt: [+0.1268% +0.3653% +0.6238]
Change within noise threshold.
Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) high mildtransfer/1-conn/10_000-parallel-1b-resp (aka. RPS)/mtu-1504: Change within noise threshold. time: [285.48 ms 287.38 ms 289.28 ms]
thrpt: [34.569 Kelem/s 34.798 Kelem/s 35.029 Kelem/s]
change:
time: [-1.9475% -1.1080% -0.2084] (p = 0.01 < 0.05)
thrpt: [+0.2089% +1.1204% +1.9862]
Change within noise threshold.transfer/1-conn/1-1b-resp (aka. HPS)/mtu-1504: No change in performance detected. time: [38.537 ms 38.691 ms 38.866 ms]
thrpt: [25.729 B/s 25.846 B/s 25.949 B/s]
change:
time: [-0.7561% -0.1164% +0.4916] (p = 0.72 > 0.05)
thrpt: [-0.4892% +0.1166% +0.7618]
No change in performance detected.
Found 9 outliers among 100 measurements (9.00%)
3 (3.00%) high mild
6 (6.00%) high severetransfer/1-conn/1-100mb-req (aka. Upload)/mtu-1504: 💚 Performance has improved by -1.5680%. time: [204.76 ms 205.10 ms 205.49 ms]
thrpt: [486.64 MiB/s 487.56 MiB/s 488.38 MiB/s]
change:
time: [-1.8861% -1.5680% -1.2751] (p = 0.00 < 0.05)
thrpt: [+1.2916% +1.5930% +1.9224]
Performance has improved.
Found 3 outliers among 100 measurements (3.00%)
2 (2.00%) high mild
1 (1.00%) high severedecode 4096 bytes, mask ff: No change in performance detected. time: [5.5779 µs 5.5866 µs 5.5954 µs]
change: [-0.1442% +0.1149% +0.3685] (p = 0.40 > 0.05)
No change in performance detected.
Found 6 outliers among 100 measurements (6.00%)
4 (4.00%) high mild
2 (2.00%) high severedecode 1048576 bytes, mask ff: No change in performance detected. time: [1.4285 ms 1.4306 ms 1.4328 ms]
change: [-0.0405% +0.2243% +0.4736] (p = 0.08 > 0.05)
No change in performance detected.decode 4096 bytes, mask 7f: No change in performance detected. time: [8.4534 µs 8.4652 µs 8.4776 µs]
change: [-0.1941% +0.0390% +0.2808] (p = 0.75 > 0.05)
No change in performance detected.
Found 5 outliers among 100 measurements (5.00%)
3 (3.00%) high mild
2 (2.00%) high severedecode 1048576 bytes, mask 7f: No change in performance detected. time: [2.1761 ms 2.1797 ms 2.1837 ms]
change: [-0.3340% -0.0862% +0.1516] (p = 0.50 > 0.05)
No change in performance detected.
Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) high milddecode 4096 bytes, mask 3f: No change in performance detected. time: [6.9118 µs 6.9233 µs 6.9357 µs]
change: [-0.1343% +0.1272% +0.3968] (p = 0.35 > 0.05)
No change in performance detected.
Found 4 outliers among 100 measurements (4.00%)
3 (3.00%) high mild
1 (1.00%) high severedecode 1048576 bytes, mask 3f: No change in performance detected. time: [1.7658 ms 1.7690 ms 1.7725 ms]
change: [-0.1909% +0.0393% +0.2586] (p = 0.75 > 0.05)
No change in performance detected.
Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) high mildstreams/simulated/1-streams/each-1000-bytes: No change in performance detected. time: [129.68 ms 129.68 ms 129.69 ms]
thrpt: [7.5302 KiB/s 7.5304 KiB/s 7.5306 KiB/s]
change:
time: [+0.0000% +0.0037% +0.0076] (p = 0.05 > 0.05)
thrpt: [-0.0076% -0.0037% -0.0000]
No change in performance detected.streams/simulated/1000-streams/each-1-bytes: No change in performance detected. time: [2.5361 s 2.5364 s 2.5367 s]
thrpt: [394.22 B/s 394.27 B/s 394.31 B/s]
change:
time: [-0.0126% +0.0038% +0.0207] (p = 0.65 > 0.05)
thrpt: [-0.0207% -0.0038% +0.0126]
No change in performance detected.
Found 3 outliers among 100 measurements (3.00%)
3 (3.00%) high mildstreams/simulated/1000-streams/each-1000-bytes: Change within noise threshold. time: [6.5841 s 6.5923 s 6.6017 s]
thrpt: [147.93 KiB/s 148.14 KiB/s 148.32 KiB/s]
change:
time: [-0.4942% -0.2640% -0.0309] (p = 0.03 < 0.05)
thrpt: [+0.0309% +0.2647% +0.4966]
Change within noise threshold.
Found 5 outliers among 100 measurements (5.00%)
1 (1.00%) high mild
4 (4.00%) high severestreams/walltime/1-streams/each-1000-bytes: Change within noise threshold. time: [581.47 µs 583.09 µs 585.08 µs]
change: [-1.3995% -0.9221% -0.4317] (p = 0.00 < 0.05)
Change within noise threshold.
Found 6 outliers among 100 measurements (6.00%)
1 (1.00%) high mild
5 (5.00%) high severestreams/walltime/1000-streams/each-1-bytes: Change within noise threshold. time: [12.355 ms 12.373 ms 12.391 ms]
change: [-0.5184% -0.2983% -0.0853] (p = 0.01 < 0.05)
Change within noise threshold.
Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) high mildstreams/walltime/1000-streams/each-1000-bytes: Change within noise threshold. time: [44.812 ms 44.851 ms 44.889 ms]
change: [-1.0819% -0.7488% -0.5146] (p = 0.00 < 0.05)
Change within noise threshold.
Found 2 outliers among 100 measurements (2.00%)
2 (2.00%) low mildcoalesce_acked_from_zero 1+1 entries: No change in performance detected. time: [92.579 ns 92.907 ns 93.236 ns]
change: [-0.2692% +0.2047% +0.6684] (p = 0.40 > 0.05)
No change in performance detected.
Found 14 outliers among 100 measurements (14.00%)
11 (11.00%) high mild
3 (3.00%) high severecoalesce_acked_from_zero 3+1 entries: No change in performance detected. time: [110.24 ns 110.91 ns 112.06 ns]
change: [-0.6423% -0.1094% +0.5080] (p = 0.73 > 0.05)
No change in performance detected.
Found 15 outliers among 100 measurements (15.00%)
1 (1.00%) low severe
1 (1.00%) low mild
5 (5.00%) high mild
8 (8.00%) high severecoalesce_acked_from_zero 10+1 entries: No change in performance detected. time: [109.72 ns 109.93 ns 110.21 ns]
change: [-0.7275% -0.2404% +0.3161] (p = 0.39 > 0.05)
No change in performance detected.
Found 14 outliers among 100 measurements (14.00%)
2 (2.00%) low severe
2 (2.00%) low mild
2 (2.00%) high mild
8 (8.00%) high severecoalesce_acked_from_zero 1000+1 entries: No change in performance detected. time: [94.037 ns 94.150 ns 94.289 ns]
change: [-1.0308% -0.4869% +0.1519] (p = 0.12 > 0.05)
No change in performance detected.
Found 17 outliers among 100 measurements (17.00%)
8 (8.00%) high mild
9 (9.00%) high severeRxStreamOrderer::inbound_frame(): Change within noise threshold. time: [109.45 ms 109.56 ms 109.66 ms]
change: [-0.2888% -0.1531% -0.0209] (p = 0.02 < 0.05)
Change within noise threshold.sent::Packets::take_ranges: No change in performance detected. time: [4.4826 µs 4.5951 µs 4.7074 µs]
change: [-9.7681% -3.0740% +2.4145] (p = 0.39 > 0.05)
No change in performance detected.
Found 3 outliers among 100 measurements (3.00%)
3 (3.00%) high mildtransfer/simulated/pacing-false/varying-seeds: No change in performance detected. time: [23.941 s 23.941 s 23.941 s]
thrpt: [171.09 KiB/s 171.09 KiB/s 171.09 KiB/s]
change:
time: [+0.0000% +0.0000% +0.0000] (p = NaN > 0.05)
thrpt: [+0.0000% +0.0000% +0.0000]
No change in performance detected.transfer/simulated/pacing-true/varying-seeds: No change in performance detected. time: [23.676 s 23.676 s 23.676 s]
thrpt: [173.01 KiB/s 173.01 KiB/s 173.01 KiB/s]
change:
time: [+0.0000% +0.0000% +0.0000] (p = NaN > 0.05)
thrpt: [+0.0000% +0.0000% +0.0000]
No change in performance detected.transfer/simulated/pacing-false/same-seed: No change in performance detected. time: [23.941 s 23.941 s 23.941 s]
thrpt: [171.09 KiB/s 171.09 KiB/s 171.09 KiB/s]
change:
time: [+0.0000% +0.0000% +0.0000] (p = NaN > 0.05)
thrpt: [+0.0000% +0.0000% +0.0000]
No change in performance detected.transfer/simulated/pacing-true/same-seed: No change in performance detected. time: [23.676 s 23.676 s 23.676 s]
thrpt: [173.01 KiB/s 173.01 KiB/s 173.01 KiB/s]
change:
time: [+0.0000% +0.0000% +0.0000] (p = NaN > 0.05)
thrpt: [+0.0000% +0.0000% +0.0000]
No change in performance detected.transfer/walltime/pacing-false/varying-seeds: Change within noise threshold. time: [23.391 ms 23.419 ms 23.454 ms]
change: [+0.7595% +0.9084% +1.0730] (p = 0.00 < 0.05)
Change within noise threshold.
Found 2 outliers among 100 measurements (2.00%)
1 (1.00%) high mild
1 (1.00%) high severetransfer/walltime/pacing-true/varying-seeds: Change within noise threshold. time: [23.394 ms 23.419 ms 23.449 ms]
change: [-0.3961% -0.2672% -0.1231] (p = 0.00 < 0.05)
Change within noise threshold.
Found 4 outliers among 100 measurements (4.00%)
3 (3.00%) low mild
1 (1.00%) high severetransfer/walltime/pacing-false/same-seed: Change within noise threshold. time: [23.010 ms 23.041 ms 23.085 ms]
change: [-1.9257% -1.7649% -1.5540] (p = 0.00 < 0.05)
Change within noise threshold.
Found 2 outliers among 100 measurements (2.00%)
1 (1.00%) high mild
1 (1.00%) high severetransfer/walltime/pacing-true/same-seed: Change within noise threshold. time: [23.391 ms 23.408 ms 23.425 ms]
change: [-0.9866% -0.8726% -0.7689] (p = 0.00 < 0.05)
Change within noise threshold.
Found 3 outliers among 100 measurements (3.00%)
2 (2.00%) low mild
1 (1.00%) high mildDownload data for |
No description provided.