Skip to content

Don't sleep on IO.select once every pipe has closed - #284

Open
tas50 wants to merge 1 commit into
chef:mainfrom
tas50:perf/no-idle-select-stall
Open

Don't sleep on IO.select once every pipe has closed#284
tas50 wants to merge 1 commit into
chef:mainfrom
tas50:perf/no-idle-select-stall

Conversation

@tas50

@tas50 tas50 commented Aug 28, 2026

Copy link
Copy Markdown
Contributor

Description

Once stdout and stderr have both hit EOF, open_pipes is empty and attempt_buffer_read calls:

IO.select([], nil, nil, 0.01)

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 waitpid succeeding), 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 at REAP_WAIT_TIME for the entire timeout.

@execution_time accumulates 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.

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%

Isolating the stall itself:

runs >8ms above median total excess time
before 79 / 3600 (2.19%) 1009 ms
after 26 / 3600 (0.72%) 267 ms

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.

  • that it still times outexecution_time lands at 1.00s for a timeout: 1, byte-identical to main
  • that the poll backs off — fails without the backoff, at 1984 reap attempts against a cap of 200

One 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's STDOUT.close does not close the underlying descriptor, so the pipe never sees EOF and the test silently exercises the ordinary IO.select path 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: same CommandTimeout, same accounted execution_time (2.00s for timeout: 2), same parent CPU burn (0.002s user + 0.003s sys).

  • bundle exec cookstyle --chefstyle -c .rubocop.yml — no offenses

Note

cspell.json is the same spellcheck fix as in #282 and #283 — the spellcheck job only scans files a PR touches, so any change to unix.rb fails on identifiers that have been in the file for years. Whichever of the three lands first, the others need a trivial rebase.

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>
@tas50
tas50 requested review from a team and jaymzh as code owners August 28, 2026 04:36
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.

1 participant