fix: Don't condition neqo_common::log::init on cfg(test)#3024
fix: Don't condition neqo_common::log::init on cfg(test)#3024larseggert wants to merge 6 commits into
neqo_common::log::init on cfg(test)#3024Conversation
Turns out we cannot make the initialization conditioned on `cfg(test)`, because before a test uses one of the logging macros, the log init won't happen and there will no output :-( Fixes mozilla#2368
There was a problem hiding this comment.
Pull Request Overview
This PR fixes a logging initialization issue by removing conditional compilation flags from log initialization calls in logging macros. The problem was that neqo_common::log::init was only being called during tests or benchmarks, preventing log output in other contexts when logging macros were used before explicit initialization.
- Removes
#[cfg(any(test, feature = "bench"))]conditions from all logging macros - Ensures log initialization happens regardless of compilation context
- Fixes issue #2368 where logging output was missing in non-test scenarios
Tip: Customize your code reviews with copilot-instructions.md. Create the file or learn how to get started.
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #3024 +/- ##
==========================================
- Coverage 93.37% 93.34% -0.04%
==========================================
Files 123 123
Lines 35887 35887
Branches 35887 35887
==========================================
- Hits 33511 33500 -11
- Misses 1533 1545 +12
+ Partials 843 842 -1
|
|
| Branch | fix-2368 |
| Testbed | On-prem |
🚨 1 Alert
| Benchmark | Measure Units | View | Benchmark Result (Result Δ%) | Upper Boundary (Limit %) |
|---|---|---|---|---|
| decode 1048576 bytes, mask ff | Latency milliseconds (ms) | 📈 plot 🚷 threshold 🚨 alert (🔔) | 3.05 ms(+0.56%)Baseline: 3.03 ms | 3.04 ms (100.15%) |
Click to view all benchmark results
| Benchmark | Latency | Benchmark Result nanoseconds (ns) (Result Δ%) | Upper Boundary nanoseconds (ns) (Limit %) |
|---|---|---|---|
| 1-conn/1-100mb-req/mtu-1504 (aka. Upload)/client | 📈 view plot 🚷 view threshold | 198,850,000.00 ns(-4.83%)Baseline: 208,952,485.88 ns | 218,094,024.51 ns (91.18%) |
| 1-conn/1-100mb-resp/mtu-1504 (aka. Download)/client | 📈 view plot 🚷 view threshold | 194,430,000.00 ns(-4.22%)Baseline: 202,993,220.34 ns | 212,907,214.98 ns (91.32%) |
| 1-conn/1-1b-resp/mtu-1504 (aka. HPS)/client | 📈 view plot 🚷 view threshold | 28,373,000.00 ns(-0.14%)Baseline: 28,412,401.13 ns | 28,867,395.64 ns (98.29%) |
| 1-conn/10_000-parallel-1b-resp/mtu-1504 (aka. RPS)/client | 📈 view plot 🚷 view threshold | 285,470,000.00 ns(-3.14%)Baseline: 294,737,853.11 ns | 306,115,720.70 ns (93.26%) |
| 1-streams/each-1000-bytes/simulated-time | 📈 view plot 🚷 view threshold | 119,190,000.00 ns(+0.74%)Baseline: 118,316,610.17 ns | 120,894,626.36 ns (98.59%) |
| 1-streams/each-1000-bytes/wallclock-time | 📈 view plot 🚷 view threshold | 581,710.00 ns(-2.77%)Baseline: 598,297.97 ns | 623,196.03 ns (93.34%) |
| 1000-streams/each-1-bytes/simulated-time | 📈 view plot 🚷 view threshold | 14,984,000,000.00 ns(-0.05%)Baseline: 14,991,779,661.02 ns | 15,010,287,868.13 ns (99.82%) |
| 1000-streams/each-1-bytes/wallclock-time | 📈 view plot 🚷 view threshold | 13,455,000.00 ns(-5.34%)Baseline: 14,214,672.32 ns | 14,995,822.76 ns (89.72%) |
| 1000-streams/each-1000-bytes/simulated-time | 📈 view plot 🚷 view threshold | 19,081,000,000.00 ns(+0.90%)Baseline: 18,911,203,389.83 ns | 19,161,653,024.67 ns (99.58%) |
| 1000-streams/each-1000-bytes/wallclock-time | 📈 view plot 🚷 view threshold | 46,722,000.00 ns(-10.64%)Baseline: 52,286,022.60 ns | 58,779,071.96 ns (79.49%) |
| RxStreamOrderer::inbound_frame() | 📈 view plot 🚷 view threshold | 109,250,000.00 ns(-0.54%)Baseline: 109,846,214.69 ns | 111,991,379.69 ns (97.55%) |
| coalesce_acked_from_zero 1+1 entries | 📈 view plot 🚷 view threshold | 88.40 ns(-0.26%)Baseline: 88.63 ns | 89.31 ns (98.99%) |
| coalesce_acked_from_zero 10+1 entries | 📈 view plot 🚷 view threshold | 105.85 ns(-0.23%)Baseline: 106.10 ns | 107.09 ns (98.84%) |
| coalesce_acked_from_zero 1000+1 entries | 📈 view plot 🚷 view threshold | 89.07 ns(-0.86%)Baseline: 89.84 ns | 94.47 ns (94.28%) |
| coalesce_acked_from_zero 3+1 entries | 📈 view plot 🚷 view threshold | 106.31 ns(-0.28%)Baseline: 106.61 ns | 107.58 ns (98.82%) |
| decode 1048576 bytes, mask 3f | 📈 view plot 🚷 view threshold | 1,589,600.00 ns(-0.18%)Baseline: 1,592,525.99 ns | 1,599,567.65 ns (99.38%) |
| decode 1048576 bytes, mask 7f | 📈 view plot 🚷 view threshold | 5,067,400.00 ns(+0.20%)Baseline: 5,057,367.23 ns | 5,077,228.06 ns (99.81%) |
| decode 1048576 bytes, mask ff | 📈 view plot 🚷 view threshold 🚨 view alert (🔔) | 3,048,600.00 ns(+0.56%)Baseline: 3,031,712.43 ns | 3,043,907.17 ns (100.15%) |
| decode 4096 bytes, mask 3f | 📈 view plot 🚷 view threshold | 8,322.60 ns(+0.31%)Baseline: 8,296.76 ns | 8,344.71 ns (99.74%) |
| decode 4096 bytes, mask 7f | 📈 view plot 🚷 view threshold | 20,020.00 ns(+0.06%)Baseline: 20,007.73 ns | 20,086.29 ns (99.67%) |
| decode 4096 bytes, mask ff | 📈 view plot 🚷 view threshold | 11,636.00 ns(-0.82%)Baseline: 11,731.87 ns | 11,977.12 ns (97.15%) |
| sent::Packets::take_ranges | 📈 view plot 🚷 view threshold | 4,694.10 ns(-1.11%)Baseline: 4,746.66 ns | 4,988.79 ns (94.09%) |
| transfer/pacing-false/same-seed/simulated-time/run | 📈 view plot 🚷 view threshold | 25,710,000,000.00 ns(+1.83%)Baseline: 25,247,657,142.86 ns | 25,741,436,848.78 ns (99.88%) |
| transfer/pacing-false/same-seed/wallclock-time/run | 📈 view plot 🚷 view threshold | 24,897,000.00 ns(-4.32%)Baseline: 26,020,537.14 ns | 27,093,384.12 ns (91.89%) |
| transfer/pacing-false/varying-seeds/simulated-time/run | 📈 view plot 🚷 view threshold | 25,151,000,000.00 ns(-0.06%)Baseline: 25,166,611,428.57 ns | 25,211,284,446.62 ns (99.76%) |
| transfer/pacing-false/varying-seeds/wallclock-time/run | 📈 view plot 🚷 view threshold | 24,820,000.00 ns(-5.49%)Baseline: 26,260,405.71 ns | 27,622,976.93 ns (89.85%) |
| transfer/pacing-true/same-seed/simulated-time/run | 📈 view plot 🚷 view threshold | 25,675,000,000.00 ns(+0.28%)Baseline: 25,602,914,285.71 ns | 25,679,901,444.16 ns (99.98%) |
| transfer/pacing-true/same-seed/wallclock-time/run | 📈 view plot 🚷 view threshold | 25,810,000.00 ns(-5.97%)Baseline: 27,449,417.14 ns | 28,793,808.73 ns (89.64%) |
| transfer/pacing-true/varying-seeds/simulated-time/run | 📈 view plot 🚷 view threshold | 24,972,000,000.00 ns(-0.09%)Baseline: 24,993,925,714.29 ns | 25,043,552,461.10 ns (99.71%) |
| transfer/pacing-true/varying-seeds/wallclock-time/run | 📈 view plot 🚷 view threshold | 25,227,000.00 ns(-5.84%)Baseline: 26,791,857.14 ns | 28,187,846.96 ns (89.50%) |
|
| Branch | fix-2368 |
| Testbed | On-prem |
Click to view all benchmark results
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| google vs. neqo (cubic, paced) | 📈 view plot 🚷 view threshold | 274.52 ms(-1.11%)Baseline: 277.61 ms | 280.33 ms (97.93%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| msquic vs. neqo (cubic, paced) | 📈 view plot 🚷 view threshold | 190.43 ms(-2.24%)Baseline: 194.80 ms | 229.38 ms (83.02%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. google (cubic, paced) | 📈 view plot 🚷 view threshold | 753.66 ms(-0.53%)Baseline: 757.66 ms | 764.82 ms (98.54%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. msquic (cubic, paced) | 📈 view plot 🚷 view threshold | 156.37 ms(-0.37%)Baseline: 156.95 ms | 158.88 ms (98.42%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. neqo (cubic) | 📈 view plot 🚷 view threshold | 91.03 ms(+0.05%)Baseline: 90.98 ms | 94.71 ms (96.12%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. neqo (cubic, paced) | 📈 view plot 🚷 view threshold | 92.32 ms(+0.06%)Baseline: 92.27 ms | 95.73 ms (96.44%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. neqo (reno) | 📈 view plot 🚷 view threshold | 88.88 ms(-2.23%)Baseline: 90.91 ms | 94.20 ms (94.35%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. neqo (reno, paced) | 📈 view plot 🚷 view threshold | 94.30 ms(+2.23%)Baseline: 92.24 ms | 95.54 ms (98.70%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. quiche (cubic, paced) | 📈 view plot 🚷 view threshold | 195.17 ms(+0.64%)Baseline: 193.92 ms | 197.38 ms (98.88%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| neqo vs. s2n (cubic, paced) | 📈 view plot 🚷 view threshold | 221.58 ms(+0.31%)Baseline: 220.89 ms | 223.60 ms (99.09%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| quiche vs. neqo (cubic, paced) | 📈 view plot 🚷 view threshold | 152.11 ms(-0.00%)Baseline: 152.11 ms | 157.80 ms (96.39%) |
| Benchmark | Latency | Benchmark Result milliseconds (ms) (Result Δ%) | Upper Boundary milliseconds (ms) (Limit %) |
|---|---|---|---|
| s2n vs. neqo (cubic, paced) | 📈 view plot 🚷 view threshold | 174.97 ms(+0.72%)Baseline: 173.72 ms | 177.83 ms (98.39%) |
There was a problem hiding this comment.
Pull Request Overview
Copilot reviewed 1 out of 1 changed files in this pull request and generated 4 comments.
Tip: Customize your code reviews with copilot-instructions.md. Create the file or learn how to get started.
Client/server transfer resultsPerformance differences relative to 3a429ef. Transfer of 33554432 bytes over loopback, min. 100 runs. All unit-less numbers are in milliseconds.
Download data for |
Despite what I said #2368, I don't fully understand the above. Are you saying that e.g. a Without |
|
The issue is that the log init call in the |
|
Why is that? The |
|
I'm not quite sure - maybe due to how macro expansion and feature checks intersect? |
|
I think we need to get to the root of this before merging. Especially since this might interfere with Firefox's logging setup. |
|
@claude says |
There was a problem hiding this comment.
Pull Request Overview
Copilot reviewed 1 out of 1 changed files in this pull request and generated 5 comments.
Tip: Customize your code reviews with copilot-instructions.md. Create the file or learn how to get started.
Failed Interop TestsQUIC Interop Runner, client vs. server neqo-latest as client
neqo-latest as server
All resultsSucceeded Interop TestsQUIC Interop Runner, client vs. server neqo-latest as client
neqo-latest as server
Unsupported Interop TestsQUIC Interop Runner, client vs. server neqo-latest as client
neqo-latest as server
|
Benchmark resultsPerformance differences relative to 791fd40. 1-conn/1-100mb-resp/mtu-1504 (aka. Download)/client: Change within noise threshold. time: [194.11 ms 194.43 ms 194.79 ms]
thrpt: [513.37 MiB/s 514.31 MiB/s 515.18 MiB/s]
change:
time: [−0.8271% −0.5944% −0.3714%] (p = 0.00 < 0.05)
thrpt: [+0.3728% +0.5980% +0.8340%]
1-conn/10_000-parallel-1b-resp/mtu-1504 (aka. RPS)/client: No change in performance detected. time: [283.82 ms 285.47 ms 287.12 ms]
thrpt: [34.828 Kelem/s 35.030 Kelem/s 35.234 Kelem/s]
change:
time: [−0.2397% +0.6239% +1.5048%] (p = 0.16 > 0.05)
thrpt: [−1.4825% −0.6200% +0.2403%]
1-conn/1-1b-resp/mtu-1504 (aka. HPS)/client: No change in performance detected. time: [28.255 ms 28.373 ms 28.515 ms]
thrpt: [35.069 B/s 35.244 B/s 35.392 B/s]
change:
time: [−0.5035% +0.0113% +0.6117%] (p = 0.97 > 0.05)
thrpt: [−0.6080% −0.0113% +0.5061%]
1-conn/1-100mb-req/mtu-1504 (aka. Upload)/client: 💚 Performance has improved. time: [198.56 ms 198.85 ms 199.20 ms]
thrpt: [502.02 MiB/s 502.89 MiB/s 503.62 MiB/s]
change:
time: [−2.9775% −2.7104% −2.4454%] (p = 0.00 < 0.05)
thrpt: [+2.5067% +2.7859% +3.0689%]
decode 4096 bytes, mask ff: No change in performance detected. time: [11.601 µs 11.636 µs 11.678 µs]
change: [−0.8050% −0.1766% +0.4169%] (p = 0.58 > 0.05)
decode 1048576 bytes, mask ff: No change in performance detected. time: [3.0226 ms 3.0486 ms 3.0918 ms]
change: [−0.3897% +0.5957% +1.9529%] (p = 0.45 > 0.05)
decode 4096 bytes, mask 7f: No change in performance detected. time: [19.960 µs 20.020 µs 20.089 µs]
change: [−0.4468% −0.0210% +0.3800%] (p = 0.92 > 0.05)
decode 1048576 bytes, mask 7f: No change in performance detected. time: [5.0506 ms 5.0674 ms 5.0885 ms]
change: [−0.0518% +0.3531% +0.8368%] (p = 0.11 > 0.05)
decode 4096 bytes, mask 3f: No change in performance detected. time: [8.2812 µs 8.3226 µs 8.3681 µs]
change: [−0.5375% −0.0162% +0.4945%] (p = 0.95 > 0.05)
decode 1048576 bytes, mask 3f: No change in performance detected. time: [1.5854 ms 1.5896 ms 1.5952 ms]
change: [−0.6720% −0.1488% +0.3072%] (p = 0.60 > 0.05)
1-streams/each-1000-bytes/wallclock-time: Change within noise threshold. time: [580.04 µs 581.71 µs 583.67 µs]
change: [−1.1229% −0.6642% −0.2075%] (p = 0.00 < 0.05)
1000-streams/each-1-bytes/wallclock-time: 💚 Performance has improved. time: [13.432 ms 13.455 ms 13.478 ms]
change: [−2.0056% −1.7634% −1.5024%] (p = 0.00 < 0.05)
1000-streams/each-1000-bytes/wallclock-time: 💚 Performance has improved. time: [46.540 ms 46.722 ms 46.905 ms]
change: [−5.6048% −5.0731% −4.5543%] (p = 0.00 < 0.05)
1000-streams/each-1000-bytes/simulated-time: No change in performance detected. time: [18.894 s 19.081 s 19.272 s]
thrpt: [50.674 KiB/s 51.181 KiB/s 51.686 KiB/s]
change:
time: [−1.2592% +0.1315% +1.5433%] (p = 0.86 > 0.05)
thrpt: [−1.5199% −0.1313% +1.2753%]
coalesce_acked_from_zero 1+1 entries: No change in performance detected. time: [88.069 ns 88.403 ns 88.726 ns]
change: [−1.4412% −0.5234% +0.2160%] (p = 0.25 > 0.05)
coalesce_acked_from_zero 3+1 entries: No change in performance detected. time: [105.94 ns 106.31 ns 106.70 ns]
change: [−0.2554% +0.1622% +0.5749%] (p = 0.48 > 0.05)
coalesce_acked_from_zero 10+1 entries: No change in performance detected. time: [105.41 ns 105.85 ns 106.38 ns]
change: [−0.4891% +0.1632% +0.8445%] (p = 0.65 > 0.05)
coalesce_acked_from_zero 1000+1 entries: No change in performance detected. time: [88.960 ns 89.066 ns 89.187 ns]
change: [−1.1926% −0.2136% +0.7273%] (p = 0.68 > 0.05)
RxStreamOrderer::inbound_frame(): Change within noise threshold. time: [109.09 ms 109.25 ms 109.50 ms]
change: [−0.5264% −0.3450% −0.0985%] (p = 0.00 < 0.05)
sent::Packets::take_ranges: No change in performance detected. time: [4.5620 µs 4.6941 µs 4.8315 µs]
change: [−5.3235% −1.7882% +2.2839%] (p = 0.38 > 0.05)
transfer/pacing-false/varying-seeds/wallclock-time/run: Change within noise threshold. time: [24.786 ms 24.820 ms 24.854 ms]
change: [−0.5891% −0.3749% −0.1598%] (p = 0.00 < 0.05)
transfer/pacing-false/varying-seeds/simulated-time/run: Change within noise threshold. time: [25.121 s 25.151 s 25.181 s]
thrpt: [162.66 KiB/s 162.86 KiB/s 163.05 KiB/s]
change:
time: [−0.4022% −0.2135% −0.0149%] (p = 0.03 < 0.05)
thrpt: [+0.0149% +0.2139% +0.4039%]
transfer/pacing-true/varying-seeds/wallclock-time/run: Change within noise threshold. time: [25.168 ms 25.227 ms 25.287 ms]
change: [−1.2268% −0.8710% −0.5338%] (p = 0.00 < 0.05)
transfer/pacing-true/varying-seeds/simulated-time/run: Change within noise threshold. time: [24.938 s 24.972 s 25.006 s]
thrpt: [163.80 KiB/s 164.02 KiB/s 164.25 KiB/s]
change:
time: [−0.4334% −0.2327% −0.0301%] (p = 0.03 < 0.05)
thrpt: [+0.0301% +0.2333% +0.4352%]
transfer/pacing-false/same-seed/wallclock-time/run: Change within noise threshold. time: [24.864 ms 24.897 ms 24.946 ms]
change: [−2.5814% −2.3501% −2.1333%] (p = 0.00 < 0.05)
transfer/pacing-false/same-seed/simulated-time/run: No change in performance detected. time: [25.710 s 25.710 s 25.710 s]
thrpt: [159.31 KiB/s 159.31 KiB/s 159.31 KiB/s]
change:
time: [+0.0000% +0.0000% +0.0000%] (p = NaN > 0.05)
thrpt: [+0.0000% +0.0000% +0.0000%]
transfer/pacing-true/same-seed/wallclock-time/run: Change within noise threshold. time: [25.783 ms 25.810 ms 25.843 ms]
change: [−2.6839% −2.5043% −2.3424%] (p = 0.00 < 0.05)
transfer/pacing-true/same-seed/simulated-time/run: No change in performance detected. time: [25.675 s 25.675 s 25.675 s]
thrpt: [159.53 KiB/s 159.53 KiB/s 159.53 KiB/s]
change:
time: [+0.0000% +0.0000% +0.0000%] (p = NaN > 0.05)
thrpt: [+0.0000% +0.0000% +0.0000%]
Download data for |
That makes sense. That leaves us with the question whether |
|
Let's not do this. If there are tests that don't generate debug output when we want them to, they just need to call |
Turns out we cannot make the initialization conditioned on
cfg(test), because before a test uses one of the logging macros, the log init won't happen and there will no output :-(Fixes #2368