From 6773046985884078da46d68d3fed96021b16f0ba Mon Sep 17 00:00:00 2001 From: Martin Muskov <65186527+martin-k-m@users.noreply.github.com> Date: Fri, 4 Sep 2026 09:33:27 -0500 Subject: [PATCH] Warmup times itself The file's own summary said the timing was yours to measure "because this file does not time itself", and noted that twill has had mono_ns since 1.7 and nothing here called it. docs/needs.md entry 3 said the same thing more plainly: delivered, not taken up. Every pass is timed now, and the report gives the first pass against the median of the rest. That difference is the number warmup exists to produce. The median rather than the mean because one stall in the middle of a warmup would drag a mean far enough to hide the first pass, which is the thing being measured against it. It claims nothing from fewer than three passes, and nothing when the first pass was no slower than the others: a model with no lazy work in it gets an honest silence rather than a saving made of noise. tests/warmup_test.tw is new, and the file had none. It asserts the refusals rather than the speed, because a timing assertion is a claim about the machine the tests run on. One of its own assertions was wrong first: it checked that a failed warmup's report contains no "ms", which the word "warms" contains. Co-Authored-By: Claude Opus 5 --- .github/workflows/ci.yml | 4 +- CHANGELOG.md | 14 +++++ README.md | 6 +-- docs/needs.md | 17 +++++-- spool.toml | 2 +- src/warmup.tw | 77 +++++++++++++++++++++++++--- tests/warmup_test.tw | 107 +++++++++++++++++++++++++++++++++++++++ 7 files changed, 212 insertions(+), 15 deletions(-) create mode 100644 tests/warmup_test.tw diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 1d59a80..0c79492 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -158,10 +158,10 @@ jobs: # would have. Pinned rather than floating: a green run should mean this # code passed against a known compiler, not against whatever was newest # that morning. - - name: Install twill v1.7.1 + - name: Install twill v1.9.0 run: | curl -fsSL -o twill \ - https://github.com/twill-lang/twill/releases/download/v1.7.1/twill-v1.7.1-linux-amd64 + https://github.com/twill-lang/twill/releases/download/v1.9.0/twill-v1.9.0-linux-amd64 chmod +x twill ./twill --version diff --git a/CHANGELOG.md b/CHANGELOG.md index 9d8c4e7..76358df 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,19 @@ # Changelog +## Unreleased + +### Added + +- **Warmup times itself.** Every pass is measured with `mono_ns`, and the report + gives the total plus, when there is enough evidence for it, how much slower + the first pass was than the median of the rest. That difference is what warmup + exists to move off the first request, and this file used to decline to say it + because twill had no clock; it has had one since 1.7. Nothing is claimed from + fewer than three passes, or when the first pass was not the slowest. +- **`tests/warmup_test.tw`**, which the file never had. It asserts the refusals + rather than the speed: a timing assertion would be a claim about the machine + the tests run on. + ## v0.1.0 (unreleased) First cut of shuttle, inference and serving for twill, written in twill. diff --git a/README.md b/README.md index fd51ef5..d669a82 100644 --- a/README.md +++ b/README.md @@ -28,14 +28,14 @@ the 6 test suites under `tests/` pass, the example loads a published model and answers with it, and CI runs both against a released twill on every push rather than gating on the prose in this file. -You need twill 1.7.0 or newer. Get one: +You need twill 1.9.0 or newer. Get one: ```bash -curl -fsSL -o twill https://github.com/twill-lang/twill/releases/download/v1.7.1/twill-v1.7.1-linux-amd64 +curl -fsSL -o twill https://github.com/twill-lang/twill/releases/download/v1.9.0/twill-v1.9.0-linux-amd64 chmod +x twill ``` -The asset name is `twill-v1.7.1--`: `linux-amd64`, `linux-arm64`, +The asset name is `twill-v1.9.0--`: `linux-amd64`, `linux-arm64`, `darwin-amd64`, `darwin-arm64`, `windows-amd64.exe`. The suite needs a checkout of [selvedge](https://github.com/twill-lang/selvedge) diff --git a/docs/needs.md b/docs/needs.md index f013cab..b7d2007 100644 --- a/docs/needs.md +++ b/docs/needs.md @@ -70,10 +70,21 @@ true footprint today, true is the footprint once the two pieces above land. **Used by:** `src/batcher.tw` (`max_hold`, which counts arrivals instead), `src/score.tw` (`Progress`, which has no time estimate), `src/warmup.tw` (which cannot report what it saved) -**Status:** DELIVERED in twill 1.7, and shuttle has not taken it up. `mono_ns()` +**Status: DELIVERED in twill 1.7, and taken up for warmup.** `mono_ns()` returns a monotonic nanosecond count and `clock_now_ms()` a wall-clock -millisecond one; both were checked against the 1.7.1 binary. No file under -`src/` calls either. +millisecond one. + +`src/warmup.tw` now times every pass with `mono_ns` and reports the first pass +against the median of the rest, which is the number warmup exists to produce: +the difference between them is what was moved off the first request. It claims +nothing from fewer than three passes, and nothing when the first pass was no +slower than the others -- a model with no lazy work in it gets an honest silence +rather than a saving made of noise. `tests/warmup_test.tw` covers exactly those +refusals, and does not assert that warming is fast, which would be a claim about +the machine rather than about the code. + +`src/score.tw` still prints a percentage and could extrapolate a remaining time. +That one is unchanged. So all three consequences below still hold and none of them is twill's fault any more. Two of the three are now small changes: `src/warmup.tw` can time its diff --git a/spool.toml b/spool.toml index e8637c0..f08a57c 100644 --- a/spool.toml +++ b/spool.toml @@ -11,7 +11,7 @@ entry = "src/predict.tw" # The language itself, pinned to the release whose std modules and tensor # builtins this source was written against. spool has no notion of a toolchain # dependency, so it is declared as an ordinary git dependency. -twill = { version = "^1.7.0", git = "https://github.com/twill-lang/twill" } +twill = { version = "^1.9.0", git = "https://github.com/twill-lang/twill" } # Reading model archives. A real dependency and not a convenience: loading # through selvedge gets the model's declared input and output shapes out of the diff --git a/src/warmup.tw b/src/warmup.tw index ef04c8e..8323837 100644 --- a/src/warmup.tw +++ b/src/warmup.tw @@ -64,10 +64,13 @@ mode systems # For a dense float model in twill today, warmup buys you the lazy work in your # own forward function and the page faults. That is a real number and it is not # a large one. For an int8 model it buys the dequantisation, which is large. -# Neither is guessed at here: `Warmup.passes` and the shapes it covered are -# reported, and the timing is yours to measure because this file does not time -# itself. twill has `mono_ns` as of 1.7 and nothing here calls it, so that is -# an omission rather than a limit (docs/needs.md entry 3). +# +# It is measured rather than guessed at. Each pass is timed with `mono_ns` and +# the first one is reported apart from the rest, because the difference between +# them is the whole claim this file makes: the first pass pays the lazy costs +# and the ones after it do not, so first-minus-median is what warmup actually +# moved off the first request. A warmup that reports only a total says nothing +# about whether it worked. import "signature.tw" as sg import "model.tw" as md @@ -77,6 +80,11 @@ struct Warmup { # Batch sizes warmed, in the order run. sizes: Arr[I64], passes: I64, + # Nanoseconds each pass took, in the order run, from `mono_ns`. + # + # Monotonic, not wall clock: this is a duration, and a wall clock can go + # backwards under an NTP step in the middle of a warmup that takes minutes. + times_ns: Arr[I64], err: Str, } @@ -92,7 +100,7 @@ struct Warmup { # warm up. Nothing else in shuttle draws random numbers, so this is the only # place the seed could leak, and it is set here rather than left to the caller. fn warm(m: md.Model, sizes: Arr[I64], forward: fn(Tree, Tensor) -> Tensor) -> Warmup { - let w = Warmup { sizes: [], passes: 0, err: "" } + let w = Warmup { sizes: [], passes: 0, times_ns: [], err: "" } if len(sizes) == 0 { w.err = "warmup needs at least one batch size: warming nothing warms nothing" return w @@ -115,7 +123,9 @@ fn warm(m: md.Model, sizes: Arr[I64], forward: fn(Tree, Tensor) -> Tensor) -> Wa + ": " + err return w } + let began = mono_ns() forward(m.params, x) + w.times_ns = arr_push(w.times_ns, mono_ns() - began) w.sizes = arr_push(w.sizes, n) w.passes = w.passes + 1 i = i + 1 @@ -137,7 +147,7 @@ fn warm(m: md.Model, sizes: Arr[I64], forward: fn(Tree, Tensor) -> Tensor) -> Wa # label. fn warm_with(m: md.Model, sample: Tensor, sizes: Arr[I64], forward: fn(Tree, Tensor) -> Tensor) -> Warmup { - let w = Warmup { sizes: [], passes: 0, err: "" } + let w = Warmup { sizes: [], passes: 0, times_ns: [], err: "" } let err = sg.check_input(m.sig, sample) if len(err) > 0 { w.err = "the warmup sample does not match the model: " + err @@ -152,7 +162,9 @@ fn warm_with(m: md.Model, sample: Tensor, sizes: Arr[I64], + " and the sample holds " + str(have) + " rows" return w } + let began = mono_ns() forward(m.params, sample[0:n]) + w.times_ns = arr_push(w.times_ns, mono_ns() - began) w.sizes = arr_push(w.sizes, n) w.passes = w.passes + 1 i = i + 1 @@ -193,6 +205,43 @@ fn sizes_for(max_batch: I64) -> Arr[I64] { [1, max_batch] } +# Milliseconds, to one decimal place, from a nanosecond count. +# +# Integer arithmetic throughout: this is a duration in nanoseconds and turning +# it into a float to divide it would trade an exact number for a rounded one in +# order to round it. +fn ms_str(ns: I64) -> Str { + let tenths = (ns + 50000) / 100000 + str(tenths / 10) + "." + str(tenths % 10) + "ms" +} + +# What warmup moved off the first request, or an empty string when it cannot +# say. +# +# First pass minus the median of the rest. The median rather than the mean, +# because one slow pass in the middle of a warmup -- a page fault, the machine +# doing something else -- would drag a mean far enough to make the first pass +# look ordinary, and the whole number being reported is a difference against +# it. +# +# Needs three passes to mean anything: with two, "the rest" is one sample and +# the answer is a comparison of two numbers rather than a measurement. +fn moved_ns(w: Warmup) -> I64 { + if len(w.times_ns) < 3 { + return 0 + } + let rest = sort(w.times_ns[1:len(w.times_ns)]) + let median = rest[len(rest) / 2] + let first = w.times_ns[0] + if first <= median { + # The first pass was no slower than the ones after it, which is the answer + # for a model with nothing lazy in it. Reporting a negative saving would + # be reporting noise as a result. + return 0 + } + first - median +} + fn report(w: Warmup) -> Str { if len(w.err) > 0 { return "warmup failed: " + w.err @@ -204,5 +253,21 @@ fn report(w: Warmup) -> Str { tx.push_str(out, " " + str(w.sizes[i])) i = i + 1 } + let total: I64 = 0 + let j: I64 = 0 + while j < len(w.times_ns) { + total = total + w.times_ns[j] + j = j + 1 + } + if len(w.times_ns) > 0 { + tx.push_str(out, " in " + ms_str(total)) + } + # Only when there is enough to say it with. A warmup of one or two passes + # reports what it did and declines to claim a saving, which is what this file + # did for every number before this one existed. + let moved = moved_ns(w) + if moved > 0 { + tx.push_str(out, ", first pass " + ms_str(moved) + " slower than the median of the rest") + } bytes_to_str(out) } diff --git a/tests/warmup_test.tw b/tests/warmup_test.tw new file mode 100644 index 0000000..10d492e --- /dev/null +++ b/tests/warmup_test.tw @@ -0,0 +1,107 @@ +mode systems + +# Warmup, tested on what it reports rather than on how fast it is. +# +# There is no assertion here that warming makes anything faster. That is a +# timing claim about the machine the test runs on, and a CI runner that stalls +# for 30ms in the wrong place would turn it into a failure that says nothing. +# What is testable is the arithmetic and the honesty of the report: that a +# saving is only claimed when there is enough evidence for one, that a first +# pass no slower than the rest claims nothing, and that every pass is timed. + +import "harness.tw" as t +import "std/text" as tx +import "../src/signature.tw" as sg +import "../src/model.tw" as md +import "../src/warmup.tw" as wu + +fn params() -> Tree { + { w: [[1.0, 0.0, 0.0, 0.0], [0.0, 1.0, 0.0, 0.0], [0.0, 0.0, 1.0, 0.0]], + b: [0.0, 0.0, 0.0] } +} + +fn forward(p: Tree, x: Tensor) -> Tensor = x @ transpose(p.w) + p.b + +fn a_model() -> md.Model { + md.Model { params: params(), sig: sg.rows_of(4, 3, "logits"), + name: "toy", version: "toy@1.0.0", digest: "", architecture: "linear", + warmed: false, precision: "f64" } +} + +fn timed(ns: Arr[I64]) -> wu.Warmup { + wu.Warmup { sizes: [1], passes: len(ns), times_ns: ns, err: "" } +} + +fn every_pass_is_timed() { + let w = wu.warm(a_model(), [1, 2, 4], forward) + t.equal_str("the warmup succeeded", w.err, "") + t.equal_i64("three passes", w.passes, 3) + t.equal_i64("and three timings", len(w.times_ns), 3) + # Monotonic and nonzero: a duration read from the same clock twice cannot go + # backwards, and a forward pass that measured as zero nanoseconds would mean + # the clock is not being read at all. + t.check("each pass took a positive time", w.times_ns[0] > 0 and w.times_ns[2] > 0) +} + +fn a_saving_needs_three_passes_before_it_is_claimed() { + # Two passes is a comparison of two numbers, not a measurement, and the + # difference between them is as likely to be the machine as the model. + t.equal_i64("nothing from one pass", wu.moved_ns(timed([9000000])), 0) + t.equal_i64("nothing from two", wu.moved_ns(timed([9000000, 1000000])), 0) + t.equal_i64( + "and a saving from three", + wu.moved_ns(timed([9000000, 1000000, 1000000])), + 8000000, + ) +} + +fn the_median_ignores_one_slow_pass() { + # The reason it is a median. A single stall in the middle of a warmup drags a + # mean far enough to hide the first pass, which is the number being reported. + let w = timed([10000000, 1000000, 40000000, 1000000, 1000000]) + t.equal_i64("the stall does not move the answer", wu.moved_ns(w), 9000000) +} + +fn a_model_with_nothing_lazy_claims_nothing() { + # The first pass no slower than the rest is the honest answer for a model + # that has no lazy work in it, and a negative saving would be noise reported + # as a result. + t.equal_i64("no saving", wu.moved_ns(timed([1000000, 1000000, 1000000])), 0) + t.equal_i64("and none when the first was fastest", wu.moved_ns(timed([500000, 1000000, 1000000])), 0) +} + +fn milliseconds_round_rather_than_truncate() { + t.equal_str("a round number", wu.ms_str(2000000), "2.0ms") + t.equal_str("one decimal", wu.ms_str(2350000), "2.4ms") + t.equal_str("rounding up at the boundary", wu.ms_str(2050000), "2.1ms") + t.equal_str("sub-millisecond", wu.ms_str(90000), "0.1ms") +} + +fn the_report_says_what_was_measured_and_no_more() { + let quiet = wu.report(timed([1000000, 1000000])) + t.check("a two-pass report gives a total", tx.contains(quiet, "in 2.0ms")) + t.check("and claims no saving", not tx.contains(quiet, "slower than")) + + let loud = wu.report(timed([9000000, 1000000, 1000000])) + t.check("a three-pass report claims one", tx.contains(loud, "8.0ms slower than the median")) +} + +fn a_failed_warmup_reports_the_failure_and_not_a_time() { + let w = wu.warm(a_model(), [], forward) + t.check("it failed", len(w.err) > 0) + # The whole report, not a substring of it: a failed warmup says why it failed + # and stops, and asserting on a substring would let a timing be appended to + # the end of that sentence without anybody noticing. + # + # ("ms" was the substring here first, which the word `warms` contains.) + t.equal_str("and says only that", wu.report(w), "warmup failed: " + w.err) +} + +every_pass_is_timed() +a_saving_needs_three_passes_before_it_is_claimed() +the_median_ignores_one_slow_pass() +a_model_with_nothing_lazy_claims_nothing() +milliseconds_round_rather_than_truncate() +the_report_says_what_was_measured_and_no_more() +a_failed_warmup_reports_the_failure_and_not_a_time() +t.report("warmup")