Warmup times itself

.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
 

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.

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-<os>-<arch>`: `linux-amd64`, `linux-arm64`,
+The asset name is `twill-v1.9.0-<os>-<arch>`: `linux-amd64`, `linux-arm64`,
 `darwin-amd64`, `darwin-arm64`, `windows-amd64.exe`.
 
 The suite needs a checkout of [selvedge](https://github.com/twill-lang/selvedge)

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

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

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

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