fix: tweak keep-alive timeout implementation

[mweberxyz]

Closes #3141

This relates to...

• Race condition at-or-near keep-alive expiration #3141

Rationale

The goal of the util/timers.js is to provide setTimeout-compatible timers with 1 second granularity, as opposed to native setTimeout's 1ms. Because the timers were scheduled, then executed in two separate "ticks" of the fast timeout, this meant timeouts are called best case 1000ms after intended, and worst case 2000ms. Combined with the previous 1000ms default for keepAliveTimeoutThreshold, the end result is an effective keepAliveTimeoutThreshold of 0 -- so unluckily timed requests would attempt to use a connection which has already been closed by the remote.

Changes

Multi-pronged approach here to prioritize safety and avoid attempting to re-use sockets that have already been closed:

1. Increase default keepAliveTimeoutThreshold from 1000 to 2000
2. Determine timeout times immediately upon timeout registration, instead of in the next tick of fast timer
3. Double fast timer tick rate
4. Timer tests added: see test file comments for approach details

Note to @ronag I went with change 2 instead of the proposed subtraction of the tick time from the duration because after writing the tests, that approach was more flaky.

Features

N/A

Bug Fixes

Some of the reports in #3133 may be resolved by this change, though it would need to be backported to 5.x, included in a Node v20 release, and then picked up by Amazon before we would see any improvement. ¯\_(ツ)_/¯

Breaking Changes and Deprecations

The more conservative default keepAliveTimeoutThreshold value should not be a breaking change.

Benchmarks

Within run-to-run variance:

PR:

┌─────────┬─────────────────────┬─────────┬────────────────────┬────────────┬─────────────────────────┐
│ (index) │ Tests               │ Samples │ Result             │ Tolerance  │ Difference with slowest │
├─────────┼─────────────────────┼─────────┼────────────────────┼────────────┼─────────────────────────┤
│ 0       │ 'undici - fetch'    │ 45      │ '16454.53 req/sec' │ '± 2.74 %' │ '-'                     │
│ 1       │ 'undici - pipeline' │ 25      │ '23976.66 req/sec' │ '± 2.61 %' │ '+ 45.71 %'             │
│ 2       │ 'undici - stream'   │ 15      │ '31539.92 req/sec' │ '± 2.94 %' │ '+ 91.68 %'             │
│ 3       │ 'undici - request'  │ 40      │ '31627.55 req/sec' │ '± 2.98 %' │ '+ 92.21 %'             │
│ 4       │ 'undici - dispatch' │ 10      │ '36186.91 req/sec' │ '± 2.54 %' │ '+ 119.92 %'            │
└─────────┴─────────────────────┴─────────┴────────────────────┴────────────┴─────────────────────────┘

main:

┌─────────┬─────────────────────┬─────────┬────────────────────┬────────────┬─────────────────────────┐
│ (index) │ Tests               │ Samples │ Result             │ Tolerance  │ Difference with slowest │
├─────────┼─────────────────────┼─────────┼────────────────────┼────────────┼─────────────────────────┤
│ 0       │ 'undici - fetch'    │ 40      │ '17433.63 req/sec' │ '± 2.88 %' │ '-'                     │
│ 1       │ 'undici - pipeline' │ 30      │ '23934.65 req/sec' │ '± 3.00 %' │ '+ 37.29 %'             │
│ 2       │ 'undici - request'  │ 101     │ '29557.97 req/sec' │ '± 3.88 %' │ '+ 69.55 %'             │
│ 3       │ 'undici - dispatch' │ 20      │ '32711.63 req/sec' │ '± 2.60 %' │ '+ 87.64 %'             │
│ 4       │ 'undici - stream'   │ 15      │ '34008.68 req/sec' │ '± 2.35 %' │ '+ 95.08 %'             │ 
└─────────┴─────────────────────┴─────────┴────────────────────┴────────────┴─────────────────────────┘

Status

• I have read and agreed to the Developer's Certificate of Origin
• Tested
• Documented
• Review ready
• In review
• Merge ready

[mweberxyz]

The results of the replication used in tracking down the issue, after this PR changes:

% node test-latency.js
target = 1000, actual = 1003
target = 1500, actual = 1520
target = 1990, actual = 2022
target = 1999, actual = 2022
target = 2000, actual = 2022
target = 2001, actual = 2022
target = 2500, actual = 2524
target = 3000, actual = 3026
target = 2990, actual = 3026
target = 2999, actual = 3028
target = 4000, actual = 4030
target = 5000, actual = 5032
10s elapsed, exiting

[ronag]

LGTM other than calling Date.now() on every registration.

[mcollina]

CI is really red.

I don't think there is literally anything we can do for #3133 without the intervention of AWS. Let's fix the race condition anyway.

undici v6 will land on v20 soonish, so let's get this done ;).

[ronag]

I think the only thing you need to change is the interval to 500 ms. Maybe the 2s default also makes sense.

[mweberxyz]

Tests should go green - that test was impacted by the change to the default.

[codecov-commenter]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 94.17%. Comparing base (b07a9d2) to head (cc2d298).
Report is 3 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #3145      +/-   ##
==========================================
- Coverage   94.17%   94.17%   -0.01%     
==========================================
  Files          90       90              
  Lines       24324    24302      -22     
==========================================
- Hits        22908    22886      -22     
  Misses       1416     1416              

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

[mcollina]

lgtm

[mweberxyz]

@ronag ptal. I tried this strategy at first, but it lead to a slight amount of non-determinism when a timer is requested that is an exact multiple of the tick rate (such as: test/request-timeout.js:31). Setting TICK_MS to 499 appears to be enough to make test runs pass consistently.

[mweberxyz]

Ah, here is an example of the loss of precision (even with the TICK_MS set to 499), two consecutive runs of the replication from the issue:

% node test-latency.js
target = 1000, actual = 1001
target = 1500, actual = 1516
target = 1990, actual = 2016
target = 1999, actual = 2017
target = 2000, actual = 2017
target = 2001, actual = 2017
target = 2500, actual = 2517
target = 3000, actual = 3017
target = 2990, actual = 3018
target = 2999, actual = 3018
target = 4000, actual = 4018
target = 5000, actual = 5019

followed by

node test-latency.js
target = 1000, actual = 1501
target = 1500, actual = 1519
target = 1990, actual = 2020
target = 1999, actual = 2020
target = 2000, actual = 2020
target = 2001, actual = 2020
target = 2500, actual = 2521
target = 3000, actual = 3021
target = 2990, actual = 3022
target = 2999, actual = 3022
target = 4000, actual = 4022
target = 5000, actual = 5022

Note the 1000ms timer fired much later the second run.

To help with very-short timeouts, I could keep the fallback to regular setTimeout at 1000ms as it was previously? Or do nothing here. Let me know :)

[mweberxyz]

@mcollina @ronag I would be more comfortable increasing the minimum timeout to use the fast timers implementation to >1000ms, okay to push that small tweak?