Standard login benchmark: new terminal to shell started (D229, D231)

kayg commented

2026-10-11 06:13:24 +00:00

Owner

Standard benchmark for new terminal to shell started under D229 and D231.

Build one harness at scripts/bench/login covering the current production session-shim path, prototype PAM login/session reuse variants, and reference login tools. Report stage timings and machine/load metadata in human and JSON forms. Document root-run prerequisites and verify stage boundaries with an injected delay. Measurement only; no product behavior changes.

Standard benchmark for new terminal to shell started under D229 and D231. Build one harness at scripts/bench/login covering the current production session-shim path, prototype PAM login/session reuse variants, and reference login tools. Report stage timings and machine/load metadata in human and JSON forms. Document root-run prerequisites and verify stage boundaries with an injected delay. Measurement only; no product behavior changes.

kayg commented

2026-10-11 06:15:05 +00:00

Author

Owner

Started on bench-login at base prod-batch SHA ebcc73a0ec22f8498a0466b2d8641ac569f87e77. Issue #159 is new and has no comments or parent issue; D229/D231 were read from origin/dev.

Started on `bench-login` at base `prod-batch` SHA `ebcc73a0ec22f8498a0466b2d8641ac569f87e77`. Issue #159 is new and has no comments or parent issue; D229/D231 were read from `origin/dev`.

kayg commented

2026-10-11 06:52:26 +00:00

Author

Owner

Finding on infraternal-dev: the real kayg zsh startup did not reach the prompt marker within 20 s in the shell-only --shell-mode real_rc --runs 1 probe. It ran in a systemd scope with CPUWeight=10000, IPAddressDeny=any, and IPAddressAllow=localhost; load average was 48.41/31.68/25.03 at start and 52.95/33.85/25.89 at finish. The harness retained no terminal output. A controlled generated zsh fixture reached its prompt marker in 14.360 ms.

Finding on infraternal-dev: the real `kayg` zsh startup did not reach the prompt marker within 20 s in the shell-only `--shell-mode real_rc --runs 1` probe. It ran in a systemd scope with `CPUWeight=10000`, `IPAddressDeny=any`, and `IPAddressAllow=localhost`; load average was 48.41/31.68/25.03 at start and 52.95/33.85/25.89 at finish. The harness retained no terminal output. A controlled generated zsh fixture reached its prompt marker in 14.360 ms.

kayg commented

2026-10-11 09:06:40 +00:00

Author

Owner

Real-rc probe finding: shell-startup --shell-mode real_rc --runs 1 stayed active beyond 90 s; the 20 s prompt deadline reached cleanup, but the shell process did not exit after SIGTERM. I stopped only the two benchmark scopes (run-p1469064-i47560672.scope and run-p1481754-i47573362.scope); the output file remained empty. Updated cleanup to bound the wait and escalate the shell process group to SIGKILL. Rechecking before the full run.

Real-rc probe finding: `shell-startup --shell-mode real_rc --runs 1` stayed active beyond 90 s; the 20 s prompt deadline reached cleanup, but the shell process did not exit after SIGTERM. I stopped only the two benchmark scopes (`run-p1469064-i47560672.scope` and `run-p1481754-i47573362.scope`); the output file remained empty. Updated cleanup to bound the wait and escalate the shell process group to SIGKILL. Rechecking before the full run.

kayg commented

2026-10-11 09:08:20 +00:00

Author

Owner

Real-rc probe after bounded cleanup: scripts/bench/login --variant shell-startup --runs 1 --shell-mode real_rc --json completed with shell real-rc startup timed out before prompt after the 20 s sample deadline. Report path: /home/kayg/.cache/codex-scratch/bench-login/real-rc-probe.json. Host infraternal-dev, Linux 6.12.111+deb13-amd64, 8 logical CPUs; load average 16.483/15.178/15.094 before and 17.639/15.484/15.193 after. The report correctly emits no timing for this unobserved prompt.

Real-rc probe after bounded cleanup: `scripts/bench/login --variant shell-startup --runs 1 --shell-mode real_rc --json` completed with `shell real-rc startup timed out before prompt` after the 20 s sample deadline. Report path: `/home/kayg/.cache/codex-scratch/bench-login/real-rc-probe.json`. Host `infraternal-dev`, Linux `6.12.111+deb13-amd64`, 8 logical CPUs; load average 16.483/15.178/15.094 before and 17.639/15.484/15.193 after. The report correctly emits no timing for this unobserved prompt.

kayg commented

2026-10-11 09:22:13 +00:00

Author

Owner

Default local report completed on infraternal-dev (8 cores, Linux 6.12.111+deb13-amd64), under CPUWeight=10000 and loopback-only networking; report: /home/kayg/.cache/codex-scratch/bench-login/local-login-bench-all.json. Load average was 9.931/16.403/16.141 before and 8.139/13.862/15.246 after. With 200 cold and 200 warm norc samples, current-production end-to-prompt was cold p50/p95/p99/max 43.820/56.731/63.404/66.906 ms and warm 43.021/55.490/62.016/70.780 ms. Shell-only zsh was cold 5.380/7.293/7.723/9.407 ms and warm 5.364/6.541/7.013/7.367 ms. Real-rc current-production and shell-only samples timed out without a prompt. Root PAM variants were skipped as requested; su -l timed out before prompt, machinectl/runuser are absent, and ssh localhost closed the PTY before prompt under strict host-key checking.

Default local report completed on infraternal-dev (8 cores, Linux 6.12.111+deb13-amd64), under CPUWeight=10000 and loopback-only networking; report: `/home/kayg/.cache/codex-scratch/bench-login/local-login-bench-all.json`. Load average was 9.931/16.403/16.141 before and 8.139/13.862/15.246 after. With 200 cold and 200 warm `norc` samples, current-production end-to-prompt was cold p50/p95/p99/max 43.820/56.731/63.404/66.906 ms and warm 43.021/55.490/62.016/70.780 ms. Shell-only zsh was cold 5.380/7.293/7.723/9.407 ms and warm 5.364/6.541/7.013/7.367 ms. Real-rc current-production and shell-only samples timed out without a prompt. Root PAM variants were skipped as requested; `su -l` timed out before prompt, `machinectl`/`runuser` are absent, and `ssh localhost` closed the PTY before prompt under strict host-key checking.

kayg commented

2026-10-11 09:31:05 +00:00

Author

Owner

Final-instrumentation default run completed (scripts/bench/login --all --json, 200 samples, norc and real_rc) on infraternal-dev, 8 cores, Linux 6.12.111+deb13-amd64. Load was 28.989/23.652/18.992 before and 32.742/27.343/20.896 after. Current-production norc end-to-prompt p50/p95/p99/max: cold 65.425/91.102/97.870/99.813 ms; warm 67.417/93.940/106.025/119.474 ms. Shell-only zsh norc: cold 9.117/22.296/31.036/46.368 ms; warm 9.769/23.430/37.471/66.564 ms. Full report: /home/kayg/.cache/codex-scratch/bench-login/local-login-bench-final.json. Final .zlogin marker correction changes the earlier exploratory no-rc numbers. Real-rc current-production and shell-only did not reach a prompt; PAM skipped as root-only; su -l timed out, machinectl/runuser unavailable, SSH localhost closed before prompt with strict host-key checking.

Final-instrumentation default run completed (`scripts/bench/login --all --json`, 200 samples, `norc` and `real_rc`) on infraternal-dev, 8 cores, Linux 6.12.111+deb13-amd64. Load was 28.989/23.652/18.992 before and 32.742/27.343/20.896 after. Current-production `norc` end-to-prompt p50/p95/p99/max: cold 65.425/91.102/97.870/99.813 ms; warm 67.417/93.940/106.025/119.474 ms. Shell-only zsh `norc`: cold 9.117/22.296/31.036/46.368 ms; warm 9.769/23.430/37.471/66.564 ms. Full report: `/home/kayg/.cache/codex-scratch/bench-login/local-login-bench-final.json`. Final `.zlogin` marker correction changes the earlier exploratory no-rc numbers. Real-rc current-production and shell-only did not reach a prompt; PAM skipped as root-only; `su -l` timed out, `machinectl`/`runuser` unavailable, SSH localhost closed before prompt with strict host-key checking.

kayg commented

2026-10-11 09:41:52 +00:00

Author

Owner

Harness-test finding: scripts/bench/test_login.py hit its 5 s subprocess timeout on infraternal-dev (the test process itself took 5.491 s before timing out under shared-host load). Raised only the test's process-start timeout to 30 s; the same test now passes in 0.361 s and the stage self-test reports the injected 40.000 ms in the intended interval.

Harness-test finding: `scripts/bench/test_login.py` hit its 5 s subprocess timeout on infraternal-dev (the test process itself took 5.491 s before timing out under shared-host load). Raised only the test's process-start timeout to 30 s; the same test now passes in 0.361 s and the stage self-test reports the injected 40.000 ms in the intended interval.

kayg commented

2026-10-11 09:46:45 +00:00

Author

Owner

Cleaned-up final default run completed (scripts/bench/login --all --json, 200 samples, norc and real_rc) on infraternal-dev, 8 cores, Linux 6.12.111+deb13-amd64. Load was 16.189/20.520/21.301 before and 28.603/22.928/22.030 after. Current-production norc end-to-prompt p50/p95/p99/max: cold 62.457/80.173/85.956/88.797 ms; warm 64.048/82.825/104.717/181.318 ms. Shell-only zsh norc: cold 11.779/21.248/36.244/38.603 ms; warm 9.241/18.302/23.273/24.618 ms. Full report: /home/kayg/.cache/codex-scratch/bench-login/local-login-bench-cleanup-final.json. Real-rc samples did not reach a prompt; root PAM was skipped on this host, su -l timed out, machinectl/runuser are unavailable, and SSH localhost closed before prompt under strict host-key checking. After cleanup, no benchmark scope remained active.

Cleaned-up final default run completed (`scripts/bench/login --all --json`, 200 samples, `norc` and `real_rc`) on infraternal-dev, 8 cores, Linux 6.12.111+deb13-amd64. Load was 16.189/20.520/21.301 before and 28.603/22.928/22.030 after. Current-production `norc` end-to-prompt p50/p95/p99/max: cold 62.457/80.173/85.956/88.797 ms; warm 64.048/82.825/104.717/181.318 ms. Shell-only zsh `norc`: cold 11.779/21.248/36.244/38.603 ms; warm 9.241/18.302/23.273/24.618 ms. Full report: `/home/kayg/.cache/codex-scratch/bench-login/local-login-bench-cleanup-final.json`. Real-rc samples did not reach a prompt; root PAM was skipped on this host, `su -l` timed out, `machinectl`/`runuser` are unavailable, and SSH localhost closed before prompt under strict host-key checking. After cleanup, no benchmark scope remained active.

kayg commented

2026-10-11 10:02:19 +00:00

Author

Owner

Finding: first scripts/verify fast attempt stopped at the latency proxy self-test. Output: latency proxy: configured 300 ms RTT did not arrive: p50=307.81 ms p99=370.83 ms. Host load at inspection was 14.85/23.90/24.83 (1/5/15m). The proxy gate allows p99 up to 360 ms; retrying after the transient shared-host load changes.

kayg commented

2026-10-11 10:04:04 +00:00

Author

Owner

Retry of scripts/verify fast stopped at the same latency proxy self-test. Output: latency proxy: configured 300 ms RTT did not arrive: p50=356.30 ms p99=505.72 ms. Host load at 12:03 UTC was 29.33/27.41/26.06 (1/5/15m). I will run the gate in a CPUWeight=10000 user scope and preserve the default RTT settings.

kayg commented

2026-10-11 10:29:46 +00:00

Author

Owner

Finding: weighted scripts/verify fast reached Rust tests; 35/36 infraternal binary tests passed. One failure: restart::tests::closed_reply_and_missing_reload_target_do_not_end_restart_control at crates/infraternal/src/restart_tests.rs:216; assertion output: EPIPE must be handled in the request loop, without ending serve. This is outside the benchmark files. I will rerun the focused test under CPUWeight=10000 and record whether it reproduces.

Finding: weighted scripts/verify fast reached Rust tests; 35/36 infraternal binary tests passed. One failure: restart::tests::closed_reply_and_missing_reload_target_do_not_end_restart_control at crates/infraternal/src/restart_tests.rs:216; assertion output: `EPIPE must be handled in the request loop, without ending serve`. This is outside the benchmark files. I will rerun the focused test under CPUWeight=10000 and record whether it reproduces.

kayg commented

2026-10-11 10:52:09 +00:00

Author

Owner

Finding: CPUWeight=10000 scripts/verify fast completed with exit 1. Summary rows: fmt PASS; VT native fmt PASS; clippy PASS; test FAIL (101); cargo-deny PASS; static builds FAIL (1). The only unit failure was restart::tests::closed_reply_and_missing_reload_target_do_not_end_restart_control (assertion at crates/infraternal/src/restart_tests.rs:216). Static binary check: 20,064,912 bytes versus 16,404,816-byte maximum (baseline 16,142,672 + 262,144 allowance); PT_INTERP absent. These are outside the benchmark files. I am checking whether the branch base moved and will rerun the focused restart test.

kayg commented

2026-10-11 11:03:46 +00:00

Author

Owner

Finding: bench-login HEAD ebcc73a0 is an ancestor 17 commits behind origin/prod-batch (707a4572). I will fast-forward the uncommitted worktree to current prod-batch before committing. The recorded current-base gate log at evidence/prod-batch/fast-complete.log shows test PASS and the same static-size failure: 20,064,944 bytes versus 16,404,816 maximum. The focused restart test passed alone: 1 passed in 0.21 s.

Finding: bench-login HEAD ebcc73a0 is an ancestor 17 commits behind origin/prod-batch (707a4572). I will fast-forward the uncommitted worktree to current prod-batch before committing. The recorded current-base gate log at evidence/prod-batch/fast-complete.log shows test PASS and the same static-size failure: 20,064,944 bytes versus 16,404,816 maximum. The focused restart test passed alone: 1 passed in 0.21 s.

kayg commented

2026-10-11 11:04:57 +00:00

Author

Owner

Completed base update: bench-login fast-forwarded from ebcc73a0 to current origin/prod-batch 707a4572 before any task commits. The three task paths remain untracked and there were no overlapping files.

Completed base update: bench-login fast-forwarded from ebcc73a0 to current origin/prod-batch 707a4572 before any task commits. The three task paths remain untracked and there were no overlapping files.

kayg commented

2026-10-11 11:12:05 +00:00

Author

Owner

Finding: current-base fast retry passed 36/36 main-binary tests, but agent_review had 7/8 pass; initial_attach_requires_explicit_credit_before_replay failed before the scenario ran. The captured traceback is FileNotFoundError for target/ac2565353 in scripts/verify-agent-attach-credit.py:17 because this test helper hard-codes a repository-relative target directory while CARGO_TARGET_DIR is under job scratch. I will provide a temporary target symlink into job scratch for the rerun so test state remains outside the repository.

Finding: current-base fast retry passed 36/36 main-binary tests, but agent_review had 7/8 pass; initial_attach_requires_explicit_credit_before_replay failed before the scenario ran. The captured traceback is FileNotFoundError for `target/ac2565353` in scripts/verify-agent-attach-credit.py:17 because this test helper hard-codes a repository-relative target directory while CARGO_TARGET_DIR is under job scratch. I will provide a temporary `target` symlink into job scratch for the rerun so test state remains outside the repository.

kayg commented

2026-10-11 11:24:54 +00:00

Author

Owner

Current-base scripts/verify fast result (log: $HOME/.cache/codex-scratch/bench-login/verify-fast-scratch-fix.log):

| Rust gate                 | Result       |
| fmt                       | PASS         |
| VT native fmt             | PASS         |
| clippy                    | PASS         |
| test                      | PASS         |
| cargo-deny                | PASS         |
| static builds             | FAIL (1)     |

The only remaining gate failure is the inherited x86_64 static-binary size check: 20,064,976 bytes versus the 16,404,816-byte limit. The current prod-batch baseline evidence records the same failure at 20,064,944 bytes. The gate test row now passes with the test helper state parent linked into job scratch.

kayg commented

2026-10-11 15:08:09 +00:00

Author

Owner

Current-base local --all --json run completed with N=200 per condition on infraternal-dev (8 CPUs, Linux 6.12.111+deb13-amd64), CPUWeight=10000, loopback-only. Load averages 1/5/15m were 8.847/13.865/19.498 before and 10.726/12.953/18.611 after. End-to-prompt p50/p95/p99/max ms: current-production norc cold 49.779/71.190/91.659/96.641, warm 46.120/55.675/66.935/77.707; shell-startup norc cold 6.908/8.454/9.379/13.496, warm 6.952/10.224/11.854/14.672. Real-rc timed out before prompt; root PAM unavailable by design on this host. Report: evidence/login-bench/infraternal-dev.md. No benchmark scope remained active.

Current-base local `--all --json` run completed with N=200 per condition on infraternal-dev (8 CPUs, Linux 6.12.111+deb13-amd64), CPUWeight=10000, loopback-only. Load averages 1/5/15m were 8.847/13.865/19.498 before and 10.726/12.953/18.611 after. End-to-prompt p50/p95/p99/max ms: current-production norc cold 49.779/71.190/91.659/96.641, warm 46.120/55.675/66.935/77.707; shell-startup norc cold 6.908/8.454/9.379/13.496, warm 6.952/10.224/11.854/14.672. Real-rc timed out before prompt; root PAM unavailable by design on this host. Report: evidence/login-bench/infraternal-dev.md. No benchmark scope remained active.

kayg referenced this issue from a commit

2026-10-11 15:20:53 +00:00

bench: add staged terminal login benchmark (D229, D231)

kayg commented

2026-10-11 15:22:11 +00:00

Author

Owner

Completed and pushed harness commit d32dca6af6. It adds the standard production/PAM/reference benchmark and staged JSON/human report. Stage self-test: PASS, injected setup delay 40.000 ms observed in setup only; benchmark unittest: PASS. Current-base N=200 p50/p95/p99/max ms: production norc cold 49.779/71.190/91.659/96.641, warm 46.120/55.675/66.935/77.707; shell-only norc cold 6.908/8.454/9.379/13.496, warm 6.952/10.224/11.854/14.672.

Completed and pushed harness commit d32dca6af6d9d60e9f7131c374d79b56178c25ed. It adds the standard production/PAM/reference benchmark and staged JSON/human report. Stage self-test: PASS, injected setup delay 40.000 ms observed in setup only; benchmark unittest: PASS. Current-base N=200 p50/p95/p99/max ms: production norc cold 49.779/71.190/91.659/96.641, warm 46.120/55.675/66.935/77.707; shell-only norc cold 6.908/8.454/9.379/13.496, warm 6.952/10.224/11.854/14.672.

kayg referenced this issue from a commit

2026-10-11 15:24:10 +00:00

test: verify login benchmark timing stages (D229, D231)

kayg commented

2026-10-11 15:25:08 +00:00

Author

Owner

Completed and pushed test commit 3f593be8e4. python3 -B scripts/bench/test_login.py passed: 1 test in 0.288 s. The test verifies the injected 40 ms setup interval and unchanged 1/2/3 ms neighboring stages.

Completed and pushed test commit 3f593be8e46caf4cd70b668f8257814d2a66a11f. `python3 -B scripts/bench/test_login.py` passed: 1 test in 0.288 s. The test verifies the injected 40 ms setup interval and unchanged 1/2/3 ms neighboring stages.

kayg referenced this issue from a commit

2026-10-11 15:28:29 +00:00

docs: record terminal login benchmark and baseline (D229, D231)

kayg commented

2026-10-11 15:29:21 +00:00

Author

Owner

Completed and pushed documentation/evidence commit f567fb5a60. Added the root/rootless run guide, full current-base JSON report, local p50/p95/p99/max table, unavailable-path notes, and author checklist. The embedded JSON and all local links validate.

Completed and pushed documentation/evidence commit f567fb5a60077df425560d1cf43c346ded33e4f1. Added the root/rootless run guide, full current-base JSON report, local p50/p95/p99/max table, unavailable-path notes, and author checklist. The embedded JSON and all local links validate.

kayg commented

2026-10-11 15:45:22 +00:00

Author

Owner

Finished. Pushed head SHA: f567fb5a60.

Local measurement: infraternal-dev, Linux 6.12.111+deb13-amd64, 8 CPUs, CPUWeight=10000, loopback-only; N=200. Load averages 1/5/15m were 8.847/13.865/19.498 before and 10.726/12.953/18.611 after. End-to-prompt p50/p95/p99/max ms: current-production norc cold 49.779/71.190/91.659/96.641, warm 46.120/55.675/66.935/77.707; shell-startup norc cold 6.908/8.454/9.379/13.496, warm 6.952/10.224/11.854/14.672. Full stages and unavailable paths are in evidence/login-bench/infraternal-dev.md.

Root-capable run command: sudo scripts/bench/login --all --json > out.json

Final scripts/verify fast summary (verbatim):

+---------------------------+--------------+
| Rust gate                 | Result       |
+---------------------------+--------------+
| fmt                       | PASS         |
| VT native fmt             | PASS         |
| clippy                    | PASS         |
| test                      | PASS         |
| cargo-deny                | PASS         |
| static builds             | FAIL (1)     |
+---------------------------+--------------+

The remaining failure is the inherited static binary-size check: 20,064,976 bytes against 16,404,816 maximum; evidence/prod-batch/fast-complete.log records the same base failure at 20,064,944 bytes. No product behavior was changed. Root PAM variants were documented for the orchestrator and not run on infraternal-dev.

Finished. Pushed head SHA: f567fb5a60077df425560d1cf43c346ded33e4f1. Local measurement: infraternal-dev, Linux 6.12.111+deb13-amd64, 8 CPUs, CPUWeight=10000, loopback-only; N=200. Load averages 1/5/15m were 8.847/13.865/19.498 before and 10.726/12.953/18.611 after. End-to-prompt p50/p95/p99/max ms: current-production norc cold 49.779/71.190/91.659/96.641, warm 46.120/55.675/66.935/77.707; shell-startup norc cold 6.908/8.454/9.379/13.496, warm 6.952/10.224/11.854/14.672. Full stages and unavailable paths are in evidence/login-bench/infraternal-dev.md. Root-capable run command: `sudo scripts/bench/login --all --json > out.json` Final `scripts/verify fast` summary (verbatim): ``` +---------------------------+--------------+ | Rust gate | Result | +---------------------------+--------------+ | fmt | PASS | | VT native fmt | PASS | | clippy | PASS | | test | PASS | | cargo-deny | PASS | | static builds | FAIL (1) | +---------------------------+--------------+ ``` The remaining failure is the inherited static binary-size check: 20,064,976 bytes against 16,404,816 maximum; evidence/prod-batch/fast-complete.log records the same base failure at 20,064,944 bytes. No product behavior was changed. Root PAM variants were documented for the orchestrator and not run on infraternal-dev.

kayg commented

2026-10-11 15:57:48 +00:00

Author

Owner

Orchestrator, perf VM (infraternal-perf-test, 4 vCPU, load 0.0): harness finding: under root with SUDO_USER, scratch_root() creates ~USER/.cache/codex-scratch/bench-login as root 0700, so the user's shell cannot read the fixtures and every variant times out (first run: all "timed out"). Workaround: pre-create the directory owned by the user. Needs a harness fix (chown to the measured user). Quick production sample after the workaround (n=5, norc): end-to-prompt p50 41.5 ms cold / 46.9 ms warm, of which request→process-started 37.2 / 42.4 ms (the systemd-run scope creation); process→Hello 0.6 ms, Hello→exec 1.9 ms, exec→prompt 1.9 ms. Full --all run in progress.

kayg referenced this issue from a commit

2026-10-11 16:00:57 +00:00

evidence(login-bench): root run on the perf VM with PAM variants (#159)

kayg referenced this issue from a commit

2026-10-11 16:09:39 +00:00

decisions: D240 real PAM logins, one per person per account per host, reused by terminals

kayg referenced this issue

2026-10-11 17:25:55 +00:00

Real logins and the preferred user (D240, D229, D231) #172

kayg referenced this issue

2026-10-11 17:27:04 +00:00

Real logins and the preferred user (D240, D229, D231) #172