9a3c7535
fix(wan): the authoritative clock was timing the wrong thing
a73x 2026-08-08 17:49
Commit message
docs/decisions.md
| Old | New | ||
|---|---|---|---|
| @@ -958,17 +958,40 @@ printed beside the result). | |||
| 958 | 958 | ||
| 959 | | | min | med | max | n | | 959 | | | min | med | max | n | |
| 960 | |---|---|---|---|---| | 960 | |---|---|---|---|---| |
| 961 | | baseline (the path) | 150.4 | 150.5 | 150.5 | 10 | | 961 | | baseline (the path) | 150.4 | 150.5 | 150.7 | 10 | |
| 962 | | predicted paint | 0.1 | **0.1** | 0.3 | 20 | | 962 | | predicted paint | 0.1 | **0.1** | 0.2 | 20 | |
| 963 | | unpredicted input | 153.8 | **154.2** | 154.8 | 10 | | 963 | | unpredicted input | 154.0 | **154.3** | 154.7 | 10 | |
| 964 | | same keystroke's authoritative echo | 0.3 | 154.2 | 154.6 | 20 | | 964 | | same keystroke's authoritative echo | 154.0 | 154.2 | 154.6 | 19 | |
| 965 | | burst convergence | 233.4 | 233.8 | 234.2 | 10 | | 965 | | burst convergence | 233.3 | 233.8 | 234.7 | 10 | |
| 966 | |||
| 967 | Reps are not all defaults: this run set `MUX_WAN_REPS_BASE=10` (default 20) | ||
| 968 | and cut the M6/M7 phases to 1 rep each, since it was measuring M9 and not | ||
| 969 | re-certifying them. That is where the baseline's n=10 comes from, and it is | ||
| 970 | recorded because an `n` that follows from neither the defaults nor the text | ||
| 971 | is an invitation to distrust the rest of the table. `predictauth`'s n=19 for | ||
| 972 | 20 keystrokes is explained below. | ||
| 973 | |||
| 974 | **An artefact was found in review and is gone from these numbers.** The | ||
| 975 | first published table gave `predictauth` a min of 0.3ms, which is not a | ||
| 976 | measurement of anything: that clock searched the whole capture buffer, so | ||
| 977 | rep 0's one-character needle matched the shell's echo of the `cat` command | ||
| 978 | typed during setup and stopped the clock at once. Two things were wrong and | ||
| 979 | both are fixed — the search now starts from the keystroke, and rep 0 | ||
| 980 | contributes no authoritative sample at all, because a one-character needle | ||
| 981 | is a substring of the prediction's own `ESC[4mX` paint and would time the | ||
| 982 | prediction instead of the echo. Hence 19 samples for 20 keystrokes. The | ||
| 983 | corrected min is 154.0ms, which agrees with the independent `predictoff` | ||
| 984 | control measuring the same physical quantity — the agreement is the check | ||
| 985 | that the fix is right and the old number was not. | ||
| 966 | 986 | ||
| 967 | - **Leg 1 (latency) — cleared.** 0.1ms median against a 30ms threshold, at a | 987 | - **Leg 1 (latency) — cleared.** 0.1ms median against a 30ms threshold, at a |
| 968 | round trip three orders of magnitude larger. | 988 | round trip three orders of magnitude larger. |
| 969 | - **Leg 2 (convergence) — cleared, in the narrowed form below.** Ten | 989 | - **Leg 2 (convergence) — cleared, in the narrowed form below.** Ten |
| 970 | adversarial bursts: `made=54 confirmed=54 contradicted=0 expired=0 | 990 | adversarial bursts: `made=55 confirmed=54 contradicted=0 expired=0 |
| 971 | abandoned=0 pending=0`, last burst present in the daemon's grid. | 991 | abandoned=1 pending=0`, last burst present in the daemon's grid. The one |
| 992 | abandoned prediction is a flush, not a wrong guess — the mode transition | ||
| 993 | as `cat` starts takes the queue with it, which is the churn policy doing | ||
| 994 | exactly what it is for. | ||
| 972 | - **Leg 3 (safety) — cleared by the e2e suite**, not by the WAN harness. A | 995 | - **Leg 3 (safety) — cleared by the e2e suite**, not by the WAN harness. A |
| 973 | session that is canonical with echo off from its first instruction makes | 996 | session that is canonical with echo off from its first instruction makes |
| 974 | **nothing**: `made=0 displayed=0`, the typed secret appears nowhere in the | 997 | **nothing**: `made=0 displayed=0`, the typed secret appears nowhere in the |
| @@ -982,13 +1005,20 @@ printed beside the result). | |||
| 982 | ### The control is the measurement | 1005 | ### The control is the measurement |
| 983 | 1006 | ||
| 984 | Leg 1's number means nothing on its own — a fast local paint is what a | 1007 | Leg 1's number means nothing on its own — a fast local paint is what a |
| 985 | terminal does anyway. What makes it evidence is that the **unpredicted** | 1008 | terminal does anyway. It takes **two** controls to make it evidence, and |
| 986 | control was taken on the same connection in the same run, from the same | 1009 | they answer different objections: |
| 987 | kind of keystroke, and came back at 154.2ms. One keystroke, two clocks: no | 1010 | |
| 988 | argument about warm caches, differing conditions or hardware can be made | 1011 | - **The unpredicted control** (`predictoff`, 154.3ms). Input prediction |
| 989 | about the gap between them. | 1012 | refuses, typed on the same connection in the same run. This is what rules |
| 990 | 1013 | out the fast number being an artefact of the machine or the harness: if | |
| 991 | Two things about that control are worth keeping. | 1014 | prediction were not doing the work, this would be fast too. |
| 1015 | - **The authoritative echo** (`predictauth`, 154.2ms). *One keystroke, two | ||
| 1016 | clocks* — this number and the predicted one are taken from the same | ||
| 1017 | keypress, so no argument about warm caches, differing conditions or | ||
| 1018 | scheduling can be made about the gap between them. That property belongs | ||
| 1019 | here and nowhere else: it is the only pair that shares a keystroke. | ||
| 1020 | |||
| 1021 | Two things about the unpredicted control are worth keeping. | ||
| 992 | 1022 | ||
| 993 | - **The criterion's wording was unmeasurable as written.** It asked for an | 1023 | - **The criterion's wording was unmeasurable as written.** It asked for an |
| 994 | "echo-off context" as the control. With echo off *nothing is painted*, so | 1024 | "echo-off context" as the control. With echo off *nothing is painted*, so |
test/wan.sh
| Old | New | ||
|---|---|---|---|
| @@ -945,12 +945,26 @@ def cmd_predict(argv): | |||
| 945 | timeout=10.0) is None: | 945 | timeout=10.0) is None: |
| 946 | fail("predict: rep %d was never predicted" % i) | 946 | fail("predict: rep %d was never predicted" % i) |
| 947 | pred.append((now() - t0) * 1000.0) | 947 | pred.append((now() - t0) * 1000.0) |
| 948 | # The authoritative echo of the same keystroke. The run only | 948 | # The authoritative echo of the same keystroke. Two conditions |
| 949 | # grows and predictions paint one cell at a time, so the run as | 949 | # make a plain substring search a valid clock here, and BOTH |
| 950 | # a contiguous string appears only in a daemon row paint. | 950 | # were got wrong first time round: |
| 951 | if c.wait_for(lambda b, w=run: w in b, timeout=20.0) is None: | 951 | # |
| 952 | # - Search from `start`, not the whole buffer. Searching | ||
| 953 | # everything let rep 0's needle match the shell's echo of | ||
| 954 | # the `cat` command typed during setup, stopping the clock | ||
| 955 | # at ~0 and putting an artifact in the record. | ||
| 956 | # - Needle of at least two characters. Predictions paint one | ||
| 957 | # cell at a time with a cursor move between them, so a run | ||
| 958 | # of two or more appears contiguously ONLY in a daemon row | ||
| 959 | # paint — but a one-character needle is a substring of the | ||
| 960 | # prediction's own `ESC[4mX` and would time that instead. | ||
| 961 | # So rep 0 contributes no authoritative sample; it cannot, | ||
| 962 | # and inventing one is how the first artifact got in. | ||
| 963 | if c.wait_for(lambda b, w=run, s=start: w in b[s:], | ||
| 964 | timeout=20.0) is None: | ||
| 952 | fail("predict: rep %d never echoed authoritatively" % i) | 965 | fail("predict: rep %d never echoed authoritatively" % i) |
| 953 | auth.append((now() - t0) * 1000.0) | 966 | if len(run) >= 2: |
| 967 | auth.append((now() - t0) * 1000.0) | ||
| 954 | # The control the criterion asks for: input prediction does NOT | 968 | # The control the criterion asks for: input prediction does NOT |
| 955 | # apply to, timed on the same connection in the same run. | 969 | # apply to, timed on the same connection in the same run. |
| 956 | # | 970 | # |
| @@ -1462,18 +1476,29 @@ if [ -n "$(val predict predict med)" ]; then | |||
| 1462 | echo " leg 1: NOT EXERCISED — round trip $P_RTT ms is below the 50ms floor" | 1476 | echo " leg 1: NOT EXERCISED — round trip $P_RTT ms is below the 50ms floor" |
| 1463 | elif awk -v m="$P_MED" 'BEGIN{exit !(m <= 30)}'; then | 1477 | elif awk -v m="$P_MED" 'BEGIN{exit !(m <= 30)}'; then |
| 1464 | P_OFF="$(val predict predictoff med)" | 1478 | P_OFF="$(val predict predictoff med)" |
| 1465 | echo " leg 1: predicted paint med $P_MED <= 30ms -> PASS (round trip $P_RTT ms)" | 1479 | echo " leg 1: predicted paint med $P_MED <= 30ms (round trip $P_RTT ms)" |
| 1466 | echo " control, unpredicted input (refused as multi-byte): med $P_OFF ms" | 1480 | echo " control, unpredicted input (refused as multi-byte): med ${P_OFF:-ABSENT} ms" |
| 1467 | echo " control, same keystroke's authoritative echo: med $P_AUTH ms" | 1481 | echo " control, same keystroke's authoritative echo: med ${P_AUTH:-ABSENT} ms" |
| 1468 | echo " Both track the measured round trip while the predicted number does" | 1482 | echo " Both track the measured round trip while the predicted number does" |
| 1469 | echo " not, which is what rules out the harness having timed the hardware." | 1483 | echo " not, which is what rules out the harness having timed the hardware." |
| 1470 | # A control that came back fast would mean the "unpredicted" input was | 1484 | # A missing control is a FAILED leg, not a quiet one. Skipping the |
| 1485 | # check when the number is absent is the same mistake as accepting a | ||
| 1486 | # control that cannot fail: leg 1 would pass on the strength of a | ||
| 1487 | # comparison nothing had made. | ||
| 1488 | if [ -z "$P_OFF" ] || [ -z "$P_AUTH" ]; then | ||
| 1489 | echo " leg 1 CONTROL MISSING: predictoff='${P_OFF:-}' predictauth='${P_AUTH:-}'." | ||
| 1490 | echo " Leg 1 cannot pass without both — the predicted number alone says" | ||
| 1491 | echo " nothing about the path it was measured over." | ||
| 1492 | FAILED=1 | ||
| 1493 | # A control that came back fast means the "unpredicted" input was | ||
| 1471 | # being predicted after all, and leg 1's number would be meaningless. | 1494 | # being predicted after all, and leg 1's number would be meaningless. |
| 1472 | if [ -n "$P_OFF" ] && awk -v o="$P_OFF" -v r="$P_RTT" 'BEGIN{exit !(o < r/2)}'; then | 1495 | elif awk -v o="$P_OFF" -v r="$P_RTT" 'BEGIN{exit !(o < r/2)}'; then |
| 1473 | echo " leg 1 CONTROL FAILED: unpredicted input came back in $P_OFF ms, well" | 1496 | echo " leg 1 CONTROL FAILED: unpredicted input came back in $P_OFF ms, well" |
| 1474 | echo " under the $P_RTT ms path — it cannot have waited for the daemon," | 1497 | echo " under the $P_RTT ms path — it cannot have waited for the daemon," |
| 1475 | echo " so the comparison above proves nothing." | 1498 | echo " so the comparison above proves nothing." |
| 1476 | FAILED=1 | 1499 | FAILED=1 |
| 1500 | else | ||
| 1501 | echo " leg 1: PASS (threshold met, both controls present and slow)" | ||
| 1477 | fi | 1502 | fi |
| 1478 | else | 1503 | else |
| 1479 | echo " leg 1: predicted paint med $P_MED > 30ms -> FAIL (round trip $P_RTT ms)" | 1504 | echo " leg 1: predicted paint med $P_MED > 30ms -> FAIL (round trip $P_RTT ms)" |