Skip to content

refactor(transport): reuse now in qlog wherever available#2216

Merged
larseggert merged 9 commits into
mozilla:mainfrom
mxinden:now-transport
Nov 14, 2024
Merged

refactor(transport): reuse now in qlog wherever available#2216
larseggert merged 9 commits into
mozilla:mainfrom
mxinden:now-transport

Conversation

@mxinden
Copy link
Copy Markdown
Member

@mxinden mxinden commented Nov 4, 2024

Instead of using QLogStream::add_event_data_now, which internally calls std::time::Instant::now(), pass now to
QLogStream::add_event_data_with_instant wherever now is available.

Less intrusive alternative to #2212.

Fixes #2211.

@github-actions
Copy link
Copy Markdown
Contributor

github-actions Bot commented Nov 4, 2024

Failed Interop Tests

QUIC Interop Runner, client vs. server

neqo-latest as client

neqo-latest as server

All results

Succeeded Interop Tests

QUIC Interop Runner, client vs. server

neqo-latest as client

neqo-latest as server

Unsupported Interop Tests

QUIC Interop Runner, client vs. server

neqo-latest as client

neqo-latest as server

@codecov
Copy link
Copy Markdown

codecov Bot commented Nov 4, 2024

Codecov Report

Attention: Patch coverage is 95.54031% with 26 lines in your changes missing coverage. Please review.

Project coverage is 95.40%. Comparing base (f11ce06) to head (74d838f).

Files with missing lines Patch % Lines
neqo-transport/src/qlog.rs 91.40% 22 Missing ⚠️
neqo-transport/src/connection/mod.rs 97.29% 2 Missing ⚠️
neqo-transport/src/cc/classic_cc.rs 98.21% 1 Missing ⚠️
neqo-transport/src/server.rs 50.00% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main    #2216      +/-   ##
==========================================
+ Coverage   95.39%   95.40%   +0.01%     
==========================================
  Files         112      112              
  Lines       36449    36585     +136     
==========================================
+ Hits        34769    34904     +135     
- Misses       1680     1681       +1     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

Instead of using `QLogStream::add_event_data_now`, which internally calls
`std::time::Instant::now()`, pass `now to
`QLogStream::add_event_data_with_instant`.
@mxinden mxinden marked this pull request as ready for review November 4, 2024 14:32
@mxinden
Copy link
Copy Markdown
Member Author

mxinden commented Nov 4, 2024

error[E0658]: use of unstable library feature 'error_in_core'
  --> /Users/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/idna-1.0.3/src/lib.rs:78:6
   |
78 | impl core::error::Error for Errors {}
   |      ^^^^^^^^^^^^^^^^^^
   |
   = note: see issue #103765 <https://github.com/rust-lang/rust/issues/103765> for more information

https://github.com/mozilla/neqo/actions/runs/11666011987/job/32480021975?pr=2216

I don't think this failure is related. Would be prevented by #2208.

@mxinden
Copy link
Copy Markdown
Member Author

mxinden commented Nov 4, 2024

For the record, this pull request enables running the test_fixtures::Simulator with simulated time. Below, as a sample, a 100MB download on a 1 GBit/s 100ms simulated link.

image

Comment thread neqo-transport/src/recovery/mod.rs
@larseggert
Copy link
Copy Markdown
Collaborator

Can we add a comment to the remaining uses of add_event_data_now and explain why we didn't change them, and what the consequences are (= I assume incorrect timestamps during testing, if the test code hits those calls)?

@github-actions
Copy link
Copy Markdown
Contributor

github-actions Bot commented Nov 11, 2024

Benchmark results

Performance differences relative to 978aa4e.

coalesce_acked_from_zero 1+1 entries: No change in performance detected.
       time:   [98.672 ns 98.944 ns 99.219 ns]
       change: [-0.5506% -0.0565% +0.4121%] (p = 0.82 > 0.05)

Found 9 outliers among 100 measurements (9.00%)
7 (7.00%) high mild
2 (2.00%) high severe

coalesce_acked_from_zero 3+1 entries: No change in performance detected.
       time:   [117.09 ns 117.43 ns 117.80 ns]
       change: [-0.3542% +0.1538% +0.6210%] (p = 0.55 > 0.05)

Found 19 outliers among 100 measurements (19.00%)
1 (1.00%) low severe
3 (3.00%) low mild
1 (1.00%) high mild
14 (14.00%) high severe

coalesce_acked_from_zero 10+1 entries: No change in performance detected.
       time:   [116.56 ns 117.06 ns 117.71 ns]
       change: [-1.0138% -0.1902% +0.4502%] (p = 0.65 > 0.05)

Found 14 outliers among 100 measurements (14.00%)
7 (7.00%) low severe
1 (1.00%) low mild
1 (1.00%) high mild
5 (5.00%) high severe

coalesce_acked_from_zero 1000+1 entries: No change in performance detected.
       time:   [97.334 ns 97.503 ns 97.697 ns]
       change: [-0.4667% +0.5481% +1.6101%] (p = 0.34 > 0.05)

Found 8 outliers among 100 measurements (8.00%)
3 (3.00%) high mild
5 (5.00%) high severe

RxStreamOrderer::inbound_frame(): Change within noise threshold.
       time:   [111.63 ms 111.69 ms 111.74 ms]
       change: [-0.8367% -0.6430% -0.5110%] (p = 0.00 < 0.05)

Found 15 outliers among 100 measurements (15.00%)
7 (7.00%) low mild
8 (8.00%) high mild

transfer/pacing-false/varying-seeds: No change in performance detected.
       time:   [26.405 ms 27.394 ms 28.385 ms]
       change: [-6.0775% -1.0006% +4.3342%] (p = 0.72 > 0.05)

Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) low mild

transfer/pacing-true/varying-seeds: No change in performance detected.
       time:   [33.676 ms 35.369 ms 37.044 ms]
       change: [-11.499% -5.8089% +0.4386%] (p = 0.07 > 0.05)
transfer/pacing-false/same-seed: No change in performance detected.
       time:   [26.433 ms 27.340 ms 28.258 ms]
       change: [-0.0465% +4.3537% +9.3912%] (p = 0.07 > 0.05)
transfer/pacing-true/same-seed: No change in performance detected.
       time:   [41.983 ms 44.093 ms 46.232 ms]
       change: [-5.2329% +2.0660% +9.4893%] (p = 0.58 > 0.05)
1-conn/1-100mb-resp/mtu-1500 (aka. Download)/client: No change in performance detected.
       time:   [934.05 ms 943.25 ms 952.59 ms]
       thrpt:  [104.98 MiB/s 106.02 MiB/s 107.06 MiB/s]
change:
       time:   [-2.0265% -0.7219% +0.4887%] (p = 0.27 > 0.05)
       thrpt:  [-0.4863% +0.7271% +2.0684%]
1-conn/10_000-parallel-1b-resp/mtu-1500 (aka. RPS)/client: No change in performance detected.
       time:   [319.87 ms 322.68 ms 325.57 ms]
       thrpt:  [30.715 Kelem/s 30.990 Kelem/s 31.262 Kelem/s]
change:
       time:   [+0.0279% +1.3485% +2.6880%] (p = 0.05 > 0.05)
       thrpt:  [-2.6177% -1.3305% -0.0279%]

Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) high mild

1-conn/1-1b-resp/mtu-1500 (aka. HPS)/client: No change in performance detected.
       time:   [33.676 ms 33.826 ms 33.977 ms]
       thrpt:  [29.432  elem/s 29.563  elem/s 29.695  elem/s]
change:
       time:   [-0.5369% +0.2308% +1.0322%] (p = 0.57 > 0.05)
       thrpt:  [-1.0217% -0.2303% +0.5398%]

Found 14 outliers among 100 measurements (14.00%)
6 (6.00%) low mild
7 (7.00%) high mild
1 (1.00%) high severe

1-conn/1-100mb-resp/mtu-1500 (aka. Upload)/client: 💔 Performance has regressed.
       time:   [1.6683 s 1.6887 s 1.7101 s]
       thrpt:  [58.476 MiB/s 59.219 MiB/s 59.939 MiB/s]
change:
       time:   [+1.7710% +3.6461% +5.5884%] (p = 0.00 < 0.05)
       thrpt:  [-5.2926% -3.5179% -1.7402%]

Found 7 outliers among 100 measurements (7.00%)
7 (7.00%) high mild

1-conn/1-100mb-resp/mtu-65536 (aka. Download)/client: No change in performance detected.
       time:   [111.49 ms 112.01 ms 112.75 ms]
       thrpt:  [886.95 MiB/s 892.80 MiB/s 896.94 MiB/s]
change:
       time:   [-1.0833% -0.5571% +0.1328%] (p = 0.07 > 0.05)
       thrpt:  [-0.1326% +0.5602% +1.0952%]

Found 1 outliers among 100 measurements (1.00%)
1 (1.00%) high severe

1-conn/10_000-parallel-1b-resp/mtu-65536 (aka. RPS)/client: No change in performance detected.
       time:   [316.57 ms 319.60 ms 322.65 ms]
       thrpt:  [30.993 Kelem/s 31.289 Kelem/s 31.588 Kelem/s]
change:
       time:   [-2.0759% -0.6684% +0.6961%] (p = 0.35 > 0.05)
       thrpt:  [-0.6912% +0.6728% +2.1199%]
1-conn/1-1b-resp/mtu-65536 (aka. HPS)/client: Change within noise threshold.
       time:   [33.911 ms 34.125 ms 34.358 ms]
       thrpt:  [29.105  elem/s 29.304  elem/s 29.489  elem/s]
change:
       time:   [+0.0360% +0.9144% +1.8432%] (p = 0.05 < 0.05)
       thrpt:  [-1.8099% -0.9061% -0.0360%]

Found 8 outliers among 100 measurements (8.00%)
3 (3.00%) high mild
5 (5.00%) high severe

1-conn/1-100mb-resp/mtu-65536 (aka. Upload)/client: No change in performance detected.
       time:   [268.41 ms 327.82 ms 400.31 ms]
       thrpt:  [249.81 MiB/s 305.05 MiB/s 372.57 MiB/s]
change:
       time:   [-19.445% +7.7182% +41.691%] (p = 0.63 > 0.05)
       thrpt:  [-29.424% -7.1652% +24.139%]

Found 8 outliers among 100 measurements (8.00%)
3 (3.00%) high mild
5 (5.00%) high severe

Client/server transfer results

Transfer of 33554432 bytes over loopback.

Client Server CC Pacing MTU Mean [ms] Min [ms] Max [ms] Relative
msquic msquic 1504 159.7 ± 82.0 98.5 352.5 1.00
neqo msquic reno on 1504 274.9 ± 81.7 211.7 424.5 1.00
neqo msquic reno 1504 251.1 ± 66.8 214.7 456.8 1.00
neqo msquic cubic on 1504 287.5 ± 106.8 208.3 567.8 1.00
neqo msquic cubic 1504 221.2 ± 26.5 199.0 299.3 1.00
msquic neqo reno on 1504 722.1 ± 30.8 690.2 805.1 1.00
msquic neqo reno 1504 757.5 ± 52.3 723.1 902.0 1.00
msquic neqo cubic on 1504 740.2 ± 56.8 706.3 899.4 1.00
msquic neqo cubic 1504 720.0 ± 19.1 696.1 751.4 1.00
neqo neqo reno on 1504 476.8 ± 60.9 418.6 589.7 1.00
neqo neqo reno 1504 450.0 ± 47.4 414.8 577.8 1.00
neqo neqo cubic on 1504 480.8 ± 44.4 445.3 597.8 1.00
neqo neqo cubic 1504 499.0 ± 71.9 425.5 634.3 1.00
msquic msquic 65536 139.2 ± 82.7 90.7 347.5 1.00
neqo msquic reno on 65536 258.3 ± 89.4 206.4 449.2 1.00
neqo msquic reno 65536 245.5 ± 68.5 211.6 447.8 1.00
neqo msquic cubic on 65536 267.7 ± 89.2 209.8 467.2 1.00
neqo msquic cubic 65536 206.1 ± 9.5 197.4 226.4 1.00
msquic neqo reno on 65536 165.2 ± 88.2 88.3 333.5 1.00
msquic neqo reno 65536 102.2 ± 24.9 81.3 182.7 1.00
msquic neqo cubic on 65536 139.0 ± 81.0 83.4 328.7 1.00
msquic neqo cubic 65536 134.7 ± 92.0 82.8 378.1 1.00
neqo neqo reno on 65536 160.8 ± 77.0 120.0 410.4 1.00
neqo neqo reno 65536 193.5 ± 102.6 126.5 468.4 1.00
neqo neqo cubic on 65536 173.9 ± 87.2 123.2 403.2 1.00
neqo neqo cubic 65536 223.2 ± 99.7 124.7 404.3 1.00

⬇️ Download logs

Comment thread neqo-common/Cargo.toml Outdated
Comment thread neqo-common/src/qlog.rs
Comment thread neqo-transport/src/cc/tests/new_reno.rs Outdated
@mxinden
Copy link
Copy Markdown
Member Author

mxinden commented Nov 13, 2024

Can we add a comment to the remaining uses of add_event_data_now and explain why we didn't change them, and what the consequences are (= I assume incorrect timestamps during testing, if the test code hits those calls)?

Sorry, missed this earlier. Will address now.

@mxinden mxinden requested a review from larseggert November 13, 2024 14:33
@larseggert larseggert enabled auto-merge November 13, 2024 14:42
@larseggert larseggert disabled auto-merge November 14, 2024 14:18
@larseggert larseggert merged commit fe76cdc into mozilla:main Nov 14, 2024
@mxinden mxinden mentioned this pull request Nov 19, 2024
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

Successfully merging this pull request may close these issues.

test: use provided (simulated) time in qlogs

2 participants