Don't sleep on IO.select once every pipe has closed - #284
Open
tas50 wants to merge 1 commit into
Open
Conversation
When both stdout and stderr have hit EOF, open_pipes is empty and
attempt_buffer_read calls IO.select([], nil, nil, 0.01) -- which is just
a 10ms sleep. Nothing can arrive on an empty read set. All we are
actually waiting for at that point is to reap the child, and it has
already closed every descriptor, so it is on its way out.
That window is short but it is hit often enough to matter: measured over
3600 paired runs of `/bin/echo hi`, 2.19% of runs stalled more than 8ms
past the median. So poll for the exit status finely instead, backing off
toward READ_WAIT_TIME so a child that closes its descriptors and keeps
running settles back to the old rate rather than spinning.
@execution_time still accumulates the time actually waited, so the
timeout behaves exactly as before.
/bin/echo hi, 3600 runs each, 6 alternating rounds, ruby 4.0.6
median p90 p95 p98 p99 mean
before 6.78 9.25 10.74 15.78 18.85 7.29
after 6.49 8.68 9.79 11.75 13.56 6.86
delta -4.3% -6.2% -8.8% -25.5% -28.1% -5.9%
runs >8ms above median 79/3600 (2.19%) -> 26/3600 (0.72%)
total excess time 1009 ms -> 267 ms
This is a tail-latency fix, not a throughput one -- the median barely
moves, but the stalls mostly go away.
Two specs cover the case the fast poll introduces, a child that closes
stdout and stderr but keeps running: that it still times out, and that
the poll backs off. The second fails without the backoff, at 1984 reap
attempts against a cap of 200.
Signed-off-by: Tim Smith <tsmith84@proton.me>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Description
Once stdout and stderr have both hit EOF,
open_pipesis empty andattempt_buffer_readcalls:Nothing can ever arrive on an empty read set, so that's just a 10 ms sleep. The only thing actually being waited for is reaping the child — and the child has already closed every descriptor, so it's on its way out.
The window is short (it's the race between the last EOF and
waitpidsucceeding), but it's hit often enough to show up in the tail. Measured over 3600 paired runs of/bin/echo hi, 2.19% of runs stalled more than 8 ms past the median.This polls for the exit status finely instead, backing off toward
READ_WAIT_TIME. The backoff is the important half: without it, a child that closes its descriptors and keeps running would spin atREAP_WAIT_TIMEfor the entire timeout.@execution_timeaccumulates the time actually waited in both branches, so timeout behaviour is unchanged.Benchmark
/bin/echo hi, 3600 runs per variant, collected as 6 alternating rounds of 600 so machine drift cancels out. ruby 4.0.6, arm64-darwin.Isolating the stall itself:
To be clear about what this is: a tail-latency fix, not a throughput one. The median barely moves. I originally measured a much larger median win, but that didn't survive alternating the runs — it was machine drift, and the numbers above are the honest version.
Verification
bundle exec rspec— 149 examples, 0 failures (147 existing, unchanged, plus 2 new).The new specs cover the case the fast poll introduces: a child that closes stdout and stderr but keeps running, which is the state where the new branch runs for a long time.
execution_timelands at 1.00s for atimeout: 1, byte-identical tomainOne note worth recording, since it cost me a wrong first attempt: the spec has to close the descriptors from the shell (
sh -c 'exec 1>&- 2>&-; sleep 30'). Ruby'sSTDOUT.closedoes not close the underlying descriptor, so the pipe never sees EOF and the test silently exercises the ordinaryIO.selectpath instead — my first version of this spec passed against both the fixed and unfixed code because of that.Also confirmed by hand against
main, for a child that closes its descriptors and keeps running: sameCommandTimeout, same accountedexecution_time(2.00s fortimeout: 2), same parent CPU burn (0.002s user + 0.003s sys).bundle exec cookstyle --chefstyle -c .rubocop.yml— no offensesNote
cspell.jsonis the same spellcheck fix as in #282 and #283 — thespellcheckjob only scans files a PR touches, so any change tounix.rbfails on identifiers that have been in the file for years. Whichever of the three lands first, the others need a trivial rebase.