From 2a839afa1411e6c5bd4cdbfb8d7454f2cce510ce Mon Sep 17 00:00:00 2001 From: Tim Smith Date: Thu, 27 Aug 2026 21:36:24 -0700 Subject: [PATCH] Don't sleep on IO.select once every pipe has closed 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 --- cspell.json | 10 ++++++++++ lib/mixlib/shellout.rb | 4 ++++ lib/mixlib/shellout/unix.rb | 27 +++++++++++++++++++++++---- spec/mixlib/shellout_spec.rb | 30 ++++++++++++++++++++++++++++++ 4 files changed, 67 insertions(+), 4 deletions(-) diff --git a/cspell.json b/cspell.json index d4bbb9d..e52f6db 100644 --- a/cspell.json +++ b/cspell.json @@ -152,6 +152,7 @@ "certstore", "CFPREFERENCES", "cfprefsd", + "cgroupv", "chaput", "chardev", "chatops", @@ -333,6 +334,7 @@ "dscacheutil", "dscresource", "dslocal", + "ducktype", "DUPEUX", "DWORDLONG", "DYNALINK", @@ -358,6 +360,7 @@ "encap", "Encryptor", "encryptor", + "endgrent", "endlocal", "entriesread", "envdata", @@ -451,6 +454,7 @@ "GETFD", "GETFL", "getgr", + "getgrent", "getgrgid", "getgrnam", "gethostbyname", @@ -704,6 +708,7 @@ "loginclass", "loginwindow", "LOGLOCATION", + "LOGNAME", "logopts", "logstring", "LONGLONG", @@ -1017,6 +1022,7 @@ "PFILETIME", "PFLOAT", "PGENERICMAPPING", + "pgid", "phabricator", "PHALF", "PHANDLE", @@ -1245,6 +1251,8 @@ "Scriptable", "SCROLLBAR", "SCROLLBARS", + "secondarygroups", + "seconderies", "secontext", "secoption", "secopts", @@ -1291,6 +1299,7 @@ "SETTINGCHANGE", "setuid", "SETX", + "sgids", "SHARENAME", "SHAs", "shas", @@ -1626,6 +1635,7 @@ "WINVER", "WKSTA", "WMIGUID", + "WNOHANG", "woot", "workdir", "WPARAM", diff --git a/lib/mixlib/shellout.rb b/lib/mixlib/shellout.rb index 9676302..b1d9e54 100644 --- a/lib/mixlib/shellout.rb +++ b/lib/mixlib/shellout.rb @@ -26,6 +26,10 @@ module Mixlib class ShellOut READ_WAIT_TIME = 0.01 + # Initial interval for polling the child's exit status once every pipe has + # hit EOF and there is nothing left to select on. Backs off toward + # READ_WAIT_TIME. See Unix#run_command. + REAP_WAIT_TIME = 0.0005 READ_SIZE = 4096 DEFAULT_READ_TIMEOUT = 600 diff --git a/lib/mixlib/shellout/unix.rb b/lib/mixlib/shellout/unix.rb index a2b918b..60d963a 100644 --- a/lib/mixlib/shellout/unix.rb +++ b/lib/mixlib/shellout/unix.rb @@ -107,12 +107,31 @@ def run_command write_to_child_stdin + reap_wait = REAP_WAIT_TIME + until @status - ready_buffers = attempt_buffer_read - unless ready_buffers - @execution_time += READ_WAIT_TIME + if open_pipes.empty? + # Every pipe has hit EOF, so IO.select has nothing left to wait on + # and would just sleep away a whole READ_WAIT_TIME. The only thing + # left to do is reap the child, and a child that has closed all of + # its descriptors is normally already on its way out, so poll for + # it much more finely than that. + # + # Back off toward READ_WAIT_TIME as we go, so a child that closed + # its descriptors but kept running -- one that detaches itself, say -- + # settles back to the old polling rate instead of spinning the CPU + # for the rest of the timeout. + sleep reap_wait + waited = reap_wait + reap_wait = [reap_wait * 2, READ_WAIT_TIME].min + else + waited = attempt_buffer_read ? nil : READ_WAIT_TIME + end + + if waited + @execution_time += waited if @execution_time >= timeout && !@result - # kill the bad proccess + # kill the bad process reap_errant_child # read anything it wrote when we killed it attempt_buffer_read diff --git a/spec/mixlib/shellout_spec.rb b/spec/mixlib/shellout_spec.rb index 08a12f1..7f037bb 100644 --- a/spec/mixlib/shellout_spec.rb +++ b/spec/mixlib/shellout_spec.rb @@ -1334,6 +1334,36 @@ def ruby_wo_shell(code) end + # Closing both descriptors leaves open_pipes empty, so run_command + # has nothing left to select on and is only waiting to reap. Note + # this has to be done by the shell -- Ruby's STDOUT.close does not + # close the underlying descriptor, so the pipe never sees EOF. + context "and the child closes stdout and stderr but keeps running" do + let(:cmd) { [ "sh", "-c", "exec 1>&- 2>&-; sleep 30" ] } + + it "should still time out" do + # note: let blocks don't correctly memoize if an exception is raised, + # so can't use executed_cmd + expect { shell_cmd.run_command }.to raise_error(Mixlib::ShellOut::CommandTimeout) + expect(shell_cmd.execution_time).to be >= 1 + end + + it "should back off rather than spin while waiting to reap it" do + # With nothing to select on we poll for the child's exit status, + # and that poll has to back off -- otherwise a child which never + # exits spins at REAP_WAIT_TIME for the whole timeout. One reap + # attempt per loop, so cap them near the pre-existing rate. + reaps = 0 + allow(shell_cmd).to receive(:attempt_reap).and_wrap_original do |original| + reaps += 1 + original.call + end + + expect { shell_cmd.run_command }.to raise_error(Mixlib::ShellOut::CommandTimeout) + expect(reaps).to be < 2 * (1 / Mixlib::ShellOut::READ_WAIT_TIME) + end + end + end end