From 828173fa49f63042a4be7904b6b2ce8b4c24d188 Mon Sep 17 00:00:00 2001 From: Leo Li Date: Wed, 23 Sep 2026 23:44:35 -0700 Subject: [PATCH 1/2] profiling: poll child processes every 0.1 s instead of every second start-cmux-profiling waits on each probe and xctrace step with a kill -0 loop that slept a whole second per check, so even an instant command like xcodebuild -version cost at least 1 s. Poll in tenths of a second instead, counting ticks so a timeout still never fires early. The 1 s grace between kill and kill -9 is unchanged. The script ships in the app and runs under macOS /bin/bash 3.2, whose external sleep takes fractional seconds. The test's fake xctrace export also slept 5 s on every run, though only the TOC-timeout case needs a slow export. That case now asks for it. In paired local runs under the same machine load, the profiling guard test went from 59 s to 29 s and from 50 s to 27 s. Co-Authored-By: Claude Opus 5.5 --- Resources/bin/start-cmux-profiling | 23 ++++++++++++++--------- tests/test_start_cmux_profiling.sh | 5 +++-- 2 files changed, 17 insertions(+), 11 deletions(-) diff --git a/Resources/bin/start-cmux-profiling b/Resources/bin/start-cmux-profiling index 5c404182464a..82f02ad3ce2e 100755 --- a/Resources/bin/start-cmux-profiling +++ b/Resources/bin/start-cmux-profiling @@ -248,14 +248,17 @@ run_output_with_timeout() { local timeout_seconds="$1" shift local output_file="${TMPDIR:-/tmp}/cmux-profile-probe.$$.$RANDOM" - local child_pid elapsed + local child_pid ticks + # Poll in tenths of a second: a whole-second poll cost every probe at least + # 1 s, even an instant one like `xcodebuild -version`. + local limit=$((timeout_seconds * 10)) "$@" > "$output_file" 2>/dev/null & child_pid="$!" - elapsed=0 + ticks=0 while kill -0 "$child_pid" >/dev/null 2>&1; do - if [ "$elapsed" -ge "$timeout_seconds" ]; then + if [ "$ticks" -ge "$limit" ]; then kill "$child_pid" >/dev/null 2>&1 || true sleep 1 kill -9 "$child_pid" >/dev/null 2>&1 || true @@ -263,8 +266,8 @@ run_output_with_timeout() { rm -f "$output_file" return 124 fi - sleep 1 - elapsed=$((elapsed + 1)) + sleep 0.1 + ticks=$((ticks + 1)) done if wait "$child_pid"; then @@ -659,10 +662,12 @@ wait_with_timeout() { local child_pid="$1" local timeout_seconds="$2" local log_file="$3" - local elapsed=0 + local ticks=0 + # Tenths of a second, like run_output_with_timeout. + local limit=$((timeout_seconds * 10)) while kill -0 "$child_pid" >/dev/null 2>&1; do - if [ "$elapsed" -ge "$timeout_seconds" ]; then + if [ "$ticks" -ge "$limit" ]; then echo "Timed out after ${timeout_seconds}s; terminating pid ${child_pid}" >> "$log_file" kill "$child_pid" >/dev/null 2>&1 || true sleep 1 @@ -670,8 +675,8 @@ wait_with_timeout() { wait "$child_pid" >/dev/null 2>&1 || true return 124 fi - sleep 1 - elapsed=$((elapsed + 1)) + sleep 0.1 + ticks=$((ticks + 1)) done wait "$child_pid" diff --git a/tests/test_start_cmux_profiling.sh b/tests/test_start_cmux_profiling.sh index 7a72e02d49c8..1ca5ea282a0d 100755 --- a/tests/test_start_cmux_profiling.sh +++ b/tests/test_start_cmux_profiling.sh @@ -182,7 +182,8 @@ if [ "${1:-}" = "xctrace" ] && [ "${2:-}" = "record" ]; then fi if [ "${1:-}" = "xctrace" ] && [ "${2:-}" = "export" ]; then - sleep 5 + # Only the TOC-timeout case asks for a slow export. + sleep "${FAKE_XCTRACE_EXPORT_SECONDS:-0}" exit 0 fi @@ -191,7 +192,7 @@ EOF chmod +x "$fake_bin/xcrun" timeout_out="$TMP_DIR/timeout-out" -HOME="$TMP_DIR" PATH="$fake_bin:$PATH" CMUX_PROFILE_TOC_TIMEOUT_SECONDS=1 "$SCRIPT" \ +HOME="$TMP_DIR" PATH="$fake_bin:$PATH" CMUX_PROFILE_TOC_TIMEOUT_SECONDS=1 FAKE_XCTRACE_EXPORT_SECONDS=5 "$SCRIPT" \ --test-ps-file "$ps_file" \ --channel dev \ --tag dog \ From 80d95c97590ce652a5134474c75d101c5ba445f1 Mon Sep 17 00:00:00 2001 From: Leo Li Date: Thu, 24 Sep 2026 00:12:54 -0700 Subject: [PATCH 2/2] profiling: refuse a timeout that is not a whole number of seconds The timeout helpers now do arithmetic on the timeout, so a value like abc or 1.5 in CMUX_PROFILE_*_TIMEOUT_SECONDS would abort the command it was meant to time; with a bad TOC timeout that abandoned the remaining templates silently. Before this branch such a value made the timeout never fire. Reject it at startup with exit 2, as --duration already is, and read the value as decimal so 010 stays ten seconds. The display-failed case now takes a 1 s export, so a child that outlives several polls and then succeeds is still covered. Co-Authored-By: Claude Opus 5.5 --- Resources/bin/start-cmux-profiling | 13 +++++++++++-- tests/test_start_cmux_profiling.sh | 16 +++++++++++++++- 2 files changed, 26 insertions(+), 3 deletions(-) diff --git a/Resources/bin/start-cmux-profiling b/Resources/bin/start-cmux-profiling index 82f02ad3ce2e..a08f1ba54105 100755 --- a/Resources/bin/start-cmux-profiling +++ b/Resources/bin/start-cmux-profiling @@ -154,6 +154,15 @@ if ! [[ "$duration" =~ ^[0-9]+$ ]] || [ "$duration" -lt 1 ]; then exit 2 fi +# The timeout helpers do arithmetic on these; a non-integer would abort the +# surrounding command instead of timing it out. +for timeout_var in CMUX_PROFILE_SYSTEM_PROFILER_TIMEOUT_SECONDS CMUX_PROFILE_TOOL_VERSION_TIMEOUT_SECONDS CMUX_PROFILE_TOC_TIMEOUT_SECONDS; do + if [ -n "${!timeout_var:-}" ] && ! [[ "${!timeout_var}" =~ ^[0-9]+$ ]]; then + echo "start-cmux-profiling: $timeout_var must be a whole number of seconds" >&2 + exit 2 + fi +done + case "$target_channel" in ""|stable|nightly|staging|dev) ;; @@ -251,7 +260,7 @@ run_output_with_timeout() { local child_pid ticks # Poll in tenths of a second: a whole-second poll cost every probe at least # 1 s, even an instant one like `xcodebuild -version`. - local limit=$((timeout_seconds * 10)) + local limit=$((10#$timeout_seconds * 10)) "$@" > "$output_file" 2>/dev/null & child_pid="$!" @@ -664,7 +673,7 @@ wait_with_timeout() { local log_file="$3" local ticks=0 # Tenths of a second, like run_output_with_timeout. - local limit=$((timeout_seconds * 10)) + local limit=$((10#$timeout_seconds * 10)) while kill -0 "$child_pid" >/dev/null 2>&1; do if [ "$ticks" -ge "$limit" ]; then diff --git a/tests/test_start_cmux_profiling.sh b/tests/test_start_cmux_profiling.sh index 1ca5ea282a0d..404123be59f2 100755 --- a/tests/test_start_cmux_profiling.sh +++ b/tests/test_start_cmux_profiling.sh @@ -239,6 +239,19 @@ if grep -Fq "$TMP_DIR/cmux DEV dog.app" "$timeout_out/summary.md" || exit 1 fi +# A timeout that is not a whole number of seconds is refused up front; inside the +# timeout helpers' arithmetic it would abort the command it was meant to time. +for bad_timeout in abc 1.5 5s; do + for timeout_var in CMUX_PROFILE_SYSTEM_PROFILER_TIMEOUT_SECONDS CMUX_PROFILE_TOOL_VERSION_TIMEOUT_SECONDS CMUX_PROFILE_TOC_TIMEOUT_SECONDS; do + rc=0 + bad_err="$(env "$timeout_var=$bad_timeout" "$SCRIPT" --list-targets --test-ps-file "$ps_file" 2>&1 >/dev/null)" || rc=$? + if [ "$rc" -ne 2 ] || [[ "$bad_err" != *"$timeout_var must be a whole number of seconds"* ]]; then + echo "FAIL: $timeout_var=$bad_timeout must be rejected with exit 2, got $rc: $bad_err" >&2 + exit 1 + fi + done +done + failing_system_profiler="$TMP_DIR/failing-system-profiler" cat > "$failing_system_profiler" <<'EOF' #!/usr/bin/env bash @@ -246,7 +259,8 @@ exit 9 EOF chmod +x "$failing_system_profiler" display_failed_out="$TMP_DIR/display-failed-out" -PATH="$fake_bin:$PATH" CMUX_PROFILE_SYSTEM_PROFILER="$failing_system_profiler" "$SCRIPT" \ +# The 1 s export outlives several 0.1 s polls, then succeeds inside the timeout. +PATH="$fake_bin:$PATH" CMUX_PROFILE_SYSTEM_PROFILER="$failing_system_profiler" FAKE_XCTRACE_EXPORT_SECONDS=1 "$SCRIPT" \ --test-ps-file "$ps_file" \ --channel dev \ --tag dog \