Time the install from CI, without changing the installers - #9153
Conversation
Install Unsloth (--local, --no-torch) is the largest step in every Windows job: 260s of Windows API CI's 374s, 291s of Windows UI CI's 715s, 281s of Windows Update CI's 794s. The same install on Linux is 88s. Across the ~11 Windows cells a commit triggers that is roughly 50 minutes of Windows runner time per commit spent installing the same thing. Which phase spends it could not be answered from a CI log. Neither setup.ps1 nor setup.sh emits a timestamp anywhere, and the one Stopwatch in setup.ps1 is inside the llama.cpp source-build branch that CI never takes. Guessing would have been misleading: unsloth studio update over an already-complete install costs 297s, more than the 281s full install it follows, which is the opposite of what a download-bound install does. That number is the reason this lands before any caching work rather than after it. UNSLOTH_INSTALL_TIMING=1 prefixes every step/substep line with seconds since the script started, in both the PowerShell and bash installers, so one run of any install turns into a phase breakdown. Off by default and output is then byte-identical, which the tests check by running the bash helper rather than reading it: PowerShell treats every non-empty string as true, so a bare [bool]:... would have made UNSLOTH_INSTALL_TIMING=0 mean on. Enabled on the five Windows install steps, so the breakdown is in the logs from now on rather than needing another PR the next time this is asked.
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
for more information, see https://pre-commit.ci
tests/python/test_windows_setup_output_encoding.py dot-sources Get-StudioAnsi, Write-StudioLine, Write-StudioStdoutMirror, step and substep on their own and runs them, so a call out of step to a helper defined elsewhere in setup.ps1 is a hard failure rather than a warning. Inline the elapsed-time prefix in both installers and drop the helper. The PowerShell side reads its state through Test-Path so an unset script variable is empty rather than fatal under a caller's Set-StrictMode, and the guard test now asserts the two print helpers call nothing the probe does not dot-source alongside them.
for more information, see https://pre-commit.ci
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
The cross-platform parity job runs this file on windows-latest, where `bash` resolves to the WSL stub: it ignores the script, prints a UTF-16 "no distributions installed" notice and exits 1. That is not a finding about setup.sh, which is not the installer Windows uses. Probed rather than keyed off sys.platform, so a Windows box with a working git-bash still runs them, plus a sentinel test that fails on any platform that does ship bash. Without it a probe that quietly started returning False would skip both tests everywhere and stay green.
Two gaps the instrumentation left, both of which kept the numbers it was added to explain out of reach. install.ps1 is what the Windows jobs actually run, and it does the uv bootstrap and the whole Unsloth dependency install itself before handing off to studio/setup.ps1. Only the child was instrumented, so the larger half of the 260-291s stayed untimed and the child's clock restarted at the handoff. install.ps1 now carries the same opt-in prefix and publishes its start as UTC ticks; setup.ps1 continues from that instead of counting from its own zero, and falls back to a local start when the value is absent or unparseable. The prefix is inlined and Test-Path guarded in install.ps1 for the same reason as in setup.ps1: tests/python/test_windows_setup_output_encoding.py slices those helpers out of this file as well and runs them alone. UNSLOTH_INSTALL_TIMING was also scoped to the install step, while the two `unsloth studio update --local` steps declare their own env. Those runs are the sharpest anomaly on record, a 297s no-op update after a 281s full install, and they were producing no breakdown at all. Set at job scope so both are covered, along with anything added later.
for more information, see https://pre-commit.ci
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
…ller too Three follow-ups on the phase timing. The tick handoff was parsed with TryParse alone, which accepts -1 and 9223372036854775807. Both are outside DateTime's range, so the constructor threw, and under $ErrorActionPreference = "Stop" that made inherited junk a fatal installer startup error rather than the documented fall back to a local clock. It also ran when timing was disabled. Now gated on the switch and bounds-checked against DateTime.MinValue.Ticks and MaxValue.Ticks; -1, near-long-max, non-numeric and empty all fall back. The origin was exported and never restored. The documented `irm ... | iex` entry point runs in the caller's process, so it outlived the install: the next run in that session kept the old origin and a later `unsloth studio update` inherited it, both then reporting time since the first install. Saved and restored in the existing finally, like every other handoff variable in this script, and removed when there was no previous value. install.sh had the same gap install.ps1 did. It bootstraps uv and installs the dependencies before launching studio/setup.sh, and its own step/substep were untimed, so a Linux or macOS run had the same unattributed first half. Both POSIX halves now carry the prefix and share one origin, off by default and identical in shape to the Windows pair.
for more information, see https://pre-commit.ci
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
Restoring the origin in a finally was not enough. Install-UnslothStudio has several early returns above that block, including the install-lock failure and the "another install is already running" path, and they exit before any try begins, so a run that hit one still left UNSLOTH_INSTALL_TIMING_T0 behind in the caller's process. That matters because the documented irm | iex entry point runs there. The variable is no longer written at the top of the function at all. The origin is computed there, and exported only beside the other handoff variables immediately before the child launch, then restored in the finally that already covers them. That is the one region an early return cannot skip, so nothing between entry and handoff can leak. On POSIX the inherited value landed inside an arithmetic expansion, and $(( )) evaluates a bare word as a variable name: with set -u, UNSLOTH_INSTALL_TIMING_T0=junk aborted the installer with "junk: unbound variable", and "1;rm" was an arithmetic syntax error, so an unrelated outer process could stop an install that merely asked for timing. Both halves now accept only a plain non-negative integer and fall back to the local clock otherwise, including when the arithmetic yields a negative elapsed. Same reasoning as the tick bounds check already on the PowerShell side, which this had fallen a platform behind.
|
@codex review |
for more information, see https://pre-commit.ci
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 900b12518b
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
| case "${UNSLOTH_INSTALL_TIMING_T0:-}" in | ||
| "" | *[!0-9]* ) UNSLOTH_INSTALL_TIMING_T0="$(date +%s)" ;; |
There was a problem hiding this comment.
When timing is enabled and an inherited UNSLOTH_INSTALL_TIMING_T0 contains only digits but exceeds the shell's integer range, this validation preserves it. Because install.sh runs under /bin/sh, Ubuntu's dash then exits with Illegal number when step evaluates the value in $((...)), aborting the installation instead of falling back to a fresh origin. Reject values outside a representable epoch range before exporting them.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Correct, and it applies to dash specifically: the digits-only check accepted a value that $(( )) then refuses as out of range, which aborts the install rather than falling back.
That whole handoff is gone. The timing no longer lives in install.sh at all: it is a pipeline stage in .github/actions/install-unsloth-local, downstream of the tee that writes logs/install.log. There is no UNSLOTH_INSTALL_TIMING, no _T0, and no arithmetic on an inherited value, so there is nothing left to bound. tests/studio/test_install_phase_timing.py asserts that all four installer scripts stay free of it, so this cannot come back without the test going red.
| if ($script:StudioTimingEnabled) { | ||
| $env:UNSLOTH_INSTALL_TIMING_T0 = $script:StudioTimingT0 |
There was a problem hiding this comment.
When timing is enabled and --with-llama-cpp-dir names a missing or invalid path, this process-wide environment assignment is followed by an early return at the path check before the later try/finally begins. For an in-process PowerShell invocation, UNSLOTH_INSTALL_TIMING_T0 therefore remains in the caller's session, causing subsequent installs or updates to report elapsed time from the failed run; move the export inside a cleanup region that also covers validation.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Correct. The export was outside the try, so the early return on an invalid --with-llama-cpp-dir left UNSLOTH_INSTALL_TIMING_T0 in an in-process caller session, and the next install would have measured from the failed one.
Rather than move the export into the cleanup region, the export is gone. install.ps1 and studio/setup.ps1 now have a zero-line diff on this PR: the elapsed prefix is a ForEach-Object stage in the five Windows install pipelines, downstream of Tee-Object, so nothing is written to the process environment and there is no state to restore on any exit path.
The previous approach put the clock inside install.sh, install.ps1 and
studio/setup.*. That is a lot of surface for a log detail: it needed a
UNSLOTH_INSTALL_TIMING switch with a different off-by-default rule per shell
(PowerShell treats every non-empty string as true, so "0" enabled it), plus a
UNSLOTH_INSTALL_TIMING_T0 epoch handed from the outer installer to the inner
one, which then had to be bounds-checked in both dialects and unset again on
every early return. Two of those hazards were reported on this PR.
None of it is needed. Every step that runs an installer already pipes its
output, so CI can prefix elapsed seconds as a pipeline stage and the installers
stay exactly as they were.
* POSIX: one stage in .github/actions/install-unsloth-local, which is the
single definition behind 40 jobs.
* Windows: the five install.ps1 pipelines, plus the two
`unsloth studio update --local` steps in the update workflow. That update
is the number worth explaining: a no-op update over a complete install
costs 297s, more than the 281s full install it follows.
The filter sits downstream of the log write, so logs/install.log keeps
byte-for-byte what the installer produced and the ~30 steps that read that
artifact are unaffected. interrupted-install-ci.yml matches ^\[TAURI:STEP\]
anchored at line start against one of them, which is the reader that a prefix
in the file would break silently rather than loudly.
tests/studio/test_install_phase_timing.py asserts both halves: that the four
installer scripts carry no timing machinery, and that in every prefixing step
the log write comes first. Nine mutations were checked red, including two
that were green on the first cut of the tests: an ordering check that read
Tee-Object out of the explanatory comment above the pipeline, and a
$LASTEXITCODE check that stayed green when deleted because the same name
appears inside the child command string.
danielhanchen
changed the title
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: c670077902
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| def test_the_filter_is_actually_wired_somewhere(): | ||
| """A scan that found nothing would pass every check below on an empty set.""" | ||
| bodies = list(_prefixing_bodies()) | ||
| assert len(bodies) >= 7, ( |
There was a problem hiding this comment.
Raise this threshold to eight, or explicitly assert both update steps: the stated set contains one composite action, five Windows install pipelines, and two update pipelines. With >= 7, removing the timing filter from either update step still passes this test, and the other tests only require the composite action and Windows install pipelines, so the regression this new suite is intended to prevent goes undetected.
Useful? React with 👍 / 👎.
for more information, see https://pre-commit.ci
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: ccd5d2e55d
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
| yield path, jid, name, run | ||
|
|
||
|
|
||
| def test_the_filter_is_actually_wired_somewhere(): |
There was a problem hiding this comment.
When a later PR changes only one of the workflows or the composite action inspected here, this test module is never collected: the reviewed studio-backend-ci.yml:27-41 paths include tests/** but not .github/actions/** or these workflows, while the always-running workflow-trigger-lint.yml:83-120 invokes several individual workflow guard modules but not this one. Consequently, the ordering and coverage regressions these tests are intended to prevent can merge and only be detected by Backend CI's post-merge push run; invoke this module from the unfiltered workflow-trigger job or add all guarded paths to a PR workflow that runs it.
Useful? React with 👍 / 👎.
|
@codex review |
|
You have reached your Codex usage limits for code reviews. You can see your limits in the Codex usage dashboard. |
|
Validated on a real Windows runner (staging, not the org queue). The install step passed and produced 146 prefixed lines, with the box-drawing and emoji output unchanged, so the added pipeline stage does not disturb the encoding work in The breakdown it exists to produce, from that run (304s total):
The frontend build is 30 percent of the install on its own and is the largest single phase by a factor of three. That was not knowable from a CI log before this, and it is a different answer from the one I would have guessed: the install reads as download-bound and is not. Also worth recording, since it was a stated hypothesis rather than a measurement: the two transformers sidecar pre-installs cost 22s combined, not the much larger figure I had assumed when suggesting they be made conditional. Worth doing, but it is not where the time is. |
|
@codex review |
|
You have reached your Codex usage limits for code reviews. You can see your limits in the Codex usage dashboard. |
* Stop 13 jobs rebuilding the same frontend on every commit The uv download cache in this action works: it hits exactly (`Cache hit for: uv-Linux-<hash>`) with one 31 kB straggler still fetched. So what is left in `Install Unsloth (--local, --no-torch)` is not download, it is compute, and the elapsed-second prefix added in #9153 says where it goes: 2s venv 5s overlaying local repo (editable) 13s unsloth installed 16s node 20s bun installed 58s frontend built <- 38s in one phase 75s whisper.cpp prebuilt Measured across 13 distinct Linux jobs on main: the frontend build is a median 36s of a 74s install, 49% of it, and 468s per commit producing byte-identical output. The spread is 31 to 42s, so it is a deterministic compute cost rather than variance. The key, and why it is sound ------------------------------------------------------------------------ studio/setup.sh already decides whether to rebuild, by mtime: it looks for anything under frontend/ (maxdepth 1, minus bun.lock), frontend/src or frontend/public NEWER than frontend/dist, and skips the build when it finds nothing. The cache key hashes exactly those three path groups, so a hit means the build inputs are byte-identical. That is a strictly stronger statement than the mtime test it rides on, and it is what makes a restored dist correct by construction rather than by luck. bun.lock is IN the key even though the staleness check excludes it. The check has to exclude it because the install regenerates it and it would self-trigger every run; the cache has no such problem, and a lockfile change means different dependencies and so a different bundle. Deliberate, and it makes the cache safer than the check it rides on. Three ways this could have looked like it worked ------------------------------------------------------------------------ Each is handled, and each is pinned by tests/studio/test_frontend_dist_cache.py, because all three are silent. 1. restore-keys. The uv cache above wants them: a near-miss download still supplies most of the wheels. A near-miss dist is a bundle built from different source, which is wrong rather than partial, so this cache has none. 2. mtimes. actions/cache restores through tar, which preserves the ORIGINAL mtimes. A dist restored that way is older than the checkout that just wrote every source file, so setup.sh's `find -newer dist` would see the whole tree as newer and rebuild anyway: a download paid for, nothing saved, and a cache hit reported. One `touch` of the directory is what makes the hit count, and it is honest because the key already proved the inputs identical. 3. an empty hashFiles. It returns "" when a glob matches nothing, which collapses every commit onto one key and serves an arbitrary dist, with the restore succeeding and the build skipped. A step refuses that outright. The guard ------------------------------------------------------------------------ The failure that matters is not the cache breaking, it is the cache and setup.sh drifting apart: the key stops covering an input, the cache keeps hitting, and every job downstream tests a stale bundle that passes. So the guard reads setup.sh's own staleness block and asserts the key covers the paths found there, rather than comparing against a list written down in the test. Mutation-tested, each failing exactly one test: drop src from the key; add restore-keys; remove the touch; save off main; and add a directory to setup.sh's check without adding it to the key. A test I had to change rather than route around ------------------------------------------------------------------------ test_the_cache_holds_uvs_downloads_and_not_the_venv asserted every cache step in this action points at .uv-cache, and this is the second cache. Its argument is worth keeping: uv's cache is content-addressed, so a stale entry cannot serve wrong content, and that property is the whole justification. A built frontend does not get that argument and needs its own. It is a directory of static assets with no absolute paths, no interpreter coupling and no console scripts, which is precisely what makes a venv unsafe to cache and this safe. So the test now allows exactly two named paths, each with its reasoning recorded at the list, and keeps the forbidden-install-paths check applying to every cache step regardless. Verified it still has teeth: pointing the new cache at ~/.unsloth/studio/venv fails it. Verification ------------------------------------------------------------------------ 72 passed across test_uv_cache_discipline, test_frontend_dist_cache, test_workflow_guards_run_unfiltered and test_cache_budget_discipline. scripts/lint_workflow_triggers.py: OK across 41 workflow files. The action still parses; step order is restore, touch, key check, install, save. Expected effect: about 36s off each of 13 jobs per commit. Cache size is one built frontend per distinct source state, saved on main only, which is the rule every other cache here follows. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --------- Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
1 participant
What this does
Prefixes installer output with elapsed seconds in CI, so a log finally says which phase spends the time.
Install Unsloth (--local, --no-torch)is the largest step in most jobs that run it: 260-291s on Windows, roughly 90s median on Linux across 40 jobs. Neitherinstall.shnorstudio/setup.ps1emits a timestamp anywhere, so the breakdown was unavailable. Guessing has been actively misleading:unsloth studio update --localover an already-complete install costs 297s, more than the 281s full install it follows, which is the opposite of what a download-bound install does.How, and what changed since the first version
The first version put the clock inside
install.sh,install.ps1andstudio/setup.*. That was a lot of surface for a log detail. It needed aUNSLOTH_INSTALL_TIMINGswitch with a different off-by-default rule per shell (PowerShell treats every non-empty string as true, so0enabled it), plus aUNSLOTH_INSTALL_TIMING_T0epoch handed from the outer installer to the inner one, which then had to be bounds-checked in both dialects and unset again on every early return. Two of those hazards were reported on this PR and both were real.None of it is necessary. Every step that runs an installer already pipes its output, so the elapsed prefix can be a pipeline stage and the installers stay exactly as they are.
.github/actions/install-unsloth-local, the single definition behind 40 jobs.install.ps1pipelines, plus the twounsloth studio update --localsteps in the update workflow.The four installer scripts now have a zero-line diff. No switch, no environment variable, no cross-process handoff, and no way for a real user's install to behave differently from a CI one.
Why the filter is downstream of the log write
logs/install.logis written bytee/Tee-Objectbefore the prefix stage, so the artifact keeps byte-for-byte what the installer produced and the roughly 30 steps that read it are unaffected. That ordering is not cosmetic:interrupted-install-ci.yml:185matches^\[TAURI:STEP\]anchored at line start against one of those logs. A prefix in the file would make that grep match nothing, and the step asserts on what it found, so it would go green having checked nothing.Tests
tests/studio/test_install_phase_timing.pyasserts both halves: that the four installer scripts carry no timing machinery, and that in every prefixing step the log write comes first. Three tests execute the shipped pipeline rather than reading it, withinstall.shswapped for a fake, and check that the log is byte-identical, that a non-zero exit still propagates through the added stages, and that the prefix advances across a real 2s gap rather than printing a constant.Nine mutations were verified red. Two were green on the first cut of the tests and are worth naming, since both are the same "the check passes on something other than what it claims to read" shape:
Tee-Objectout of the explanatory comment above the pipeline, so it reported correct order no matter how the pipeline was written;$LASTEXITCODEcheck stayed green when the outer guard was deleted, because$childalready ends withexit $LASTEXITCODEand the substring was still present.Verification
Local: 4018 passed, 4 skipped.
actionlintclean on the four edited workflows apart from a pre-existing unknown-custom-runner-label warning. All five edited PowerShell step bodies parse under the PowerShell language parser. Both filters were run end to end for log fidelity, exit-code propagation and live streaming.The elapsed value is arrival time at the filter rather than emission time inside the installer. Phase boundaries are printed by shell builtins, which are unbuffered, so phase attribution is unaffected; a child process that block-buffers its own progress output could shift a line within a phase.