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")