diff --git a/docs/BRINGUP.md b/docs/BRINGUP.md index c77d5f3..2f464af 100644 --- a/docs/BRINGUP.md +++ b/docs/BRINGUP.md @@ -1004,18 +1004,27 @@ is committed. share off. With the pump on, a heater slug reaches the upstream sensor within seconds and inflates the instant reading by a degree; the warm-up release therefore judges a one-minute rolling minimum of that reading. -- **Coolant-ADC readings depend on the read pattern.** What the PIC returns - for a thermistor depends on how soon the read follows the previous PIC - transaction (measured 2026-09-02 on the two coolant channels): the second - of a pair issued within 0.1 ms comes back 6 to 8 counts high with a wide - spread, either sensor, either order; a pair 0.5 to 10 ms apart reads tight - and a steady 3 counts (about 0.2 C) above sparse reads. The module paces - every PIC transaction (`pic_gap_us`, 1000 by default, a runtime-writable - parameter), so no reader lands a disturbed pair whatever the others do; - the `aa-offset-calibrate` diagnostic still reads its two sensors 31 ms - apart and reduces each window to an interquartile mean, which takes the - steady bias out of its edges. `kernel.pic-pacing` measures the pairs with - the pacing off and on. +- **Coolant-ADC readings depend on the SoC's load at conversion time.** The + sensor PIC (a PIC16F1713, its firmware read from the part) converts its + inputs in a free-running loop, about 25 µs a channel (10 µs acquisition, + 11.5 µs conversion at FOSC/32, the ADC switched off between), and a read + returns the last conversion of that channel, at most one loop (about + 0.35 ms) old; a read never starts a conversion and the SPI interrupt + never touches the ADC. The ADC references the PIC's own supply (ADPREF + at reset) while the sensor dividers hang on the board's reference, so the + count follows the SoC's load at the moment of conversion: on the coolant + thermistors a value converted while the CPU idled reads 6 counts (about + 0.35 C) below one converted under load, both regimes tight + (interquartile 2 over 200 reads; measured 2026-09-03, sleep 3 ms then + read against spin 3 ms then read). A reader that wakes and reads at once + gets the idle value and its next read, a fraction of a millisecond later, + the busy one, which is the pair bias the diagnostic saw on 2026-09-02. + The module keeps the CPU busy for `pic_settle_us` (500 by default, a + runtime-writable parameter) before every transaction, longer than one PIC + loop, so every reader gets the busy-regime value whatever it was doing. + Rare excursions of 10 to 20 counts appear in every regime at a few + samples per hundred; the diagnostic's interquartile means drop them. + `kernel.pic-soc-load` measures both regimes with the settle off and on. - **Coolant-ADC offsets around a lit tube.** The air-assist fan's return current rides a ground path the thermistor reference shares, so both coolant sensors read about 1.2 C low at the run duty (proportional to the fan's @@ -1391,14 +1400,18 @@ feature requests, enhancements) will eventually be tracked as GitHub issues. live-fire drill is gone; a coolant sensor unreadable for two ticks is the SENSOR verdict. -10. **PIC read pacing, done and waiting for the image.** The module paces - every PIC transaction at least `pic_gap_us` (1000, a runtime-writable - parameter) after the last one ended, so every reader, the engine, - `/status`, the diagnostics and a bench sampler, sees the same value - whatever the others do (facts bank, "Coolant-ADC readings depend on the - read pattern"). Host-proven by the module's -Werror cross-build; on the - bench, the new `kernel.pic-pacing` drill (300 back-to-back pairs with the - pacing off, then on) and the coolant-reading tests +10. **PIC readings under one SoC load, done and waiting for the image.** The + module keeps the CPU busy for `pic_settle_us` (500, a runtime-writable + parameter) before every PIC transaction, longer than one loop of the + PIC's free-running sampler, so the value a reader gets was converted + under the same load whoever reads and whatever it was doing (facts bank, + "Coolant-ADC readings depend on the SoC's load at conversion time"): the + engine, `/status`, the diagnostics and a bench sampler read the same + value, the busy-regime one, about 0.35 C above the idle one. Host-proven + by the module's -Werror cross-build and, for the mechanism, by the + userspace measurement; on the bench, the new `kernel.pic-soc-load` drill + (200 reads after 3 ms of sleep and after 3 ms of spinning, with the + settle off and on) and the coolant-reading tests (`cooling.aa-offset-calibrate`, `cooling.flow-verify`). Rides item 9's image; the item closes with the campaign. diff --git a/docs/CAMPAIGN-LOG.md b/docs/CAMPAIGN-LOG.md index 58ce4be..266fbc2 100644 --- a/docs/CAMPAIGN-LOG.md +++ b/docs/CAMPAIGN-LOG.md @@ -7464,6 +7464,104 @@ ctypes in the release image; no QA warnings. Owed: the operator flashes the dev image, takes a fresh-boot baseline, and runs the full campaign; then the push in CI order and the pin bumps. +## 2026-09-03: the campaign on image 20260903003213, first pass, and the PIC read regimes + +The board booted the image (kernel `6.12.20-fslc-fslc-g08aa91b3b59f`, the +module's probe clean, the SDMA channel claimed through dmaengine, forgectrl +in GRBL mode with motion verified). `image.health` found the first harness +defect of the image: it asserted the watchdog's sysfs `state` reads +`active`, but that attribute says whether a process holds the device, and +none does; the kernel's core feeds the boot-armed hardware. The check now +reads WDOG1's own control register through /dev/mem (WCR 0x771f: enabled, +a 60 s period) and expects `inactive`; PASS, and the fresh-boot baseline +with it. Campaign c-20260903004540-2ef4 opened with the fixture up. + +The unattended queue (44 tests) ran seven and stopped at the eighth: +`kernel.latch-locked-idle`, `kernel.k1-k2`, `kernel.deadman-close`, +`kernel.backtrack-bounds`, `kernel.fire-line` and `kernel.resume-lead` PASS, +so the script's end-of-data mailbox and its laser inhibit (K-4, K-8) are +bench-proven on the first try; `kernel.pic-pacing` FAIL: its paced pairs +spread 5 counts (interquartile) where the drill allowed 3, and its control +pairs were the tight ones (interquartile 2). + +The drill's model was wrong, and a study of the PIC's readings on the +idle machine (the module's pacing switched at runtime, pairs read through +pre-opened descriptors, 200 pairs per regime, both coolant sensors) says +what the PIC does: + +- A read that follows the previous transaction within about 0.1 ms + returns the same held sample (a same-sensor pair differs by 0 with an + interquartile range of 0), so such a pair cannot show a disturbance. +- A read issued at least a millisecond after the previous transaction + (the paced regime, whether the module or the caller spaces it) is the + tight one: interquartile 2 on 200 reads, at about 659 to 660 counts. +- A read after 5 to 50 ms of quiet is wide (interquartile 11 to 13) at + about 661 to 664 counts, and the second of a 0.1 ms pair after such a + quiet reads 3.6 to 4.3 counts higher still, wider yet (this is the pair + bias the 2026-09-02 diagnostic saw). +- The sparse reference (single reads 100 ms apart) reads about 668, so the + quiet-then-read regime and the sparse regime sit 5 to 8 counts (0.3 to + 0.5 C) above the tight regime. Excursions of 10 to 25 counts appear in + every regime at a small share of samples. + +So a fixed gap between transactions does not give every reader the same +value: a reader's first read after a quiet tick lands in the wide regime +and its next read, a millisecond later, in the tight one, 5 counts lower, +which splits the two coolant sensors by their position in the read order +the way the 0.1 ms pair did, in the other direction. The value every reader +would share needs the PIC kept in one regime for every read (a warm-up +transaction ahead of a read after quiet, or a fixed-cadence sampler that +every reader takes its values from), and that regime's level is 0.3 to +0.5 C below the one the machine's gates and calibration were set under. +That is a design decision, recorded here for item 10; the numbers are +what the bench measured. + +## 2026-09-03: the PIC worked backward from its firmware; item 10 redone + +The operator's direction: understand the PIC's ADC from its code and its +datasheet, then design from the mechanism, not from sampling. The PIC is a +PIC16F1713 (the firmware read from the part, annotated). Its main loop +converts the analog inputs one after another with no delay between them, +about 25 µs a channel (the channel selected and the ADC enabled together, +a 10 µs acquisition loop, an 11.5 µs conversion at FOSC/32, the ADC switched +off after each), and stores each result in a slot with interrupts masked; +the SPI interrupt handler answers a read with the slot's current contents +and never touches the ADC. So a read returns the last conversion of that +channel, at most one loop (about 0.35 ms) old, and no spacing of SPI +transactions can change what it converts. The ADC references the PIC's own +supply (ADPREF left at its reset value) while the sensor dividers hang on +the board's reference net, so a conversion's count follows whatever moves +the PIC's supply at that moment. + +The experiment that follows from that, on the idle machine with no kernel +pacing: 200 reads of a coolant thermistor taken right after 3 ms of sleep +(the value converted while the CPU idled) against 200 taken after 3 ms of +spinning (converted under load), twice each, then 200 after a sleep +followed by a 1 ms spin. Idle: median 659, interquartile 2. Busy: median +665, interquartile 2. Sleep then spin: 665. The count depends on the SoC's +load at conversion time, by 6 counts (about 0.35 C), and both regimes are +tight; the wide spreads seen earlier were mixtures across the transition. +The 2026-09-02 pair bias (the second read of a back-to-back pair 6 to 8 +counts high) is this: the first read comes right after the reader woke, the +second after the ARM had been up for a fraction of a millisecond. The +pacing as built (a kernel sleep before each transaction) forced the idle +regime onto every second read, which is why its drill failed, and why the +two coolant sensors would have split by read order. + +Item 10 redone from the mechanism: before every PIC transaction the module +keeps the CPU busy for `pic_settle_us` (500 µs, a runtime-writable +parameter, 0 to turn it off), longer than one PIC loop, so the value read +was converted under the same load whoever reads and whatever it was doing; +the sleep-based gap is gone. The drill is `kernel.pic-soc-load`: 200 reads +after 3 ms of sleep and 200 after 3 ms of spinning, with the settle off +(the control: the split, reported) and on (the claim: the two agree within +2 counts, each tight, and the settled idle reader reads the busy regime's +value). Host proof: the -Werror cross-build; the mechanism's proof is the +measurement above. The bench proof is the drill, on the next image, with +the coolant-reading tests. Rare excursions of 10 to 20 counts appear in +every regime at a few samples per hundred and are a separate matter the +diagnostic's interquartile means already drop. + ## Reference notes ### Head-IRQ source validation — the beam-emission hypothesis diff --git a/forgetest/forgetest/suite/kernel.py b/forgetest/forgetest/suite/kernel.py index 5b96cb9..ffbc015 100644 --- a/forgetest/forgetest/suite/kernel.py +++ b/forgetest/forgetest/suite/kernel.py @@ -808,9 +808,9 @@ def resume_lead(ctx): ctx.log("safe state restored: state=%s latch=LOCKED", rd("cnc/state")) -# ---------------------------------------------------------------- PIC pacing +# ---------------------------------------------------------------- PIC and the SoC's load -PIC_GAP_PARAM = "/sys/module/glowforge/parameters/pic_gap_us" +PIC_SETTLE_PARAM = "/sys/module/glowforge/parameters/pic_settle_us" def _param_read(path): @@ -826,62 +826,79 @@ def _param_write(path, value): f.write("%s\n" % value) -def _pair_stats(diffs): - s = sorted(diffs) +def _level_stats(xs): + s = sorted(xs) n = len(s) - return {"n": n, "mean": round(sum(s) / float(n), 2), "iqr": s[(3 * n) // 4] - s[n // 4], - "min": s[0], "max": s[-1]} + return {"n": n, "mean": round(sum(s) / float(n), 2), "med": s[n // 2], + "iqr": s[(3 * n) // 4] - s[n // 4], "min": s[0], "max": s[-1]} -@test("kernel.pic-pacing", title="PIC transactions are paced a millisecond apart", +def _spin(sec): + t0 = time.perf_counter() + x = 1.0 + while time.perf_counter() - t0 < sec: + x = x * 1.000001 + 0.5 + return x + + +@test("kernel.pic-soc-load", title="A PIC reading does not depend on what the reader was doing", subsystem="kernel", kind="auto", est_min=1, covers=_KERNEL_COVERS + [("forgectrl", "src/diag.c")], - description="What the PIC returns for a thermistor depends on how soon the read follows " - "the previous transaction: the second of a pair issued within a fraction of a " - "millisecond comes back high and wide. The module paces every transaction at " - "least pic_gap_us after the last one ended, so every reader sees the same value " - "whatever the others do. The drill reads a coolant thermistor twice back to back, " - "300 pairs, with the pacing off (the control, reported) and on (the claim): " - "paced, the second read agrees with the first.") -def pic_pacing(ctx): + description="The PIC converts its sensors in a free-running loop and a read returns the " + "last conversion of that channel; the count depends on the SoC's load when the " + "conversion was made (the PIC converts against its own supply, the dividers hang " + "on the board's reference), about 6 counts between an idle and a busy CPU on the " + "coolant thermistors. The module keeps the CPU busy for pic_settle_us before every " + "transaction, longer than one PIC loop, so the value read was converted under the " + "same load whoever reads. The drill reads a coolant thermistor 200 times each after " + "3 ms of sleep and after 3 ms of spinning, with the settle off (the control, " + "reported) and on (the claim): settled, the two agree.") +def pic_soc_load(ctx): ev = ctx.evidence - saved = _param_read(PIC_GAP_PARAM) - ctx.check(saved is not None, "the module has no pic_gap_us parameter (%s)", PIC_GAP_PARAM) - ev["pic_gap_us_before"] = saved + saved = _param_read(PIC_SETTLE_PARAM) + ctx.check(saved is not None, "the module has no pic_settle_us parameter (%s)", PIC_SETTLE_PARAM) + ev["pic_settle_us_before"] = saved + fd = os.open(hw.sysfs_root() + "pic/water_temp_1", os.O_RDONLY) - def pairs(n): - diffs = [] + def reads(regime, n=200): + xs = [] for i in range(n): - a = int(rd("pic/water_temp_1")) - b = int(rd("pic/water_temp_1")) - diffs.append(b - a) + if regime == "idle": + time.sleep(0.003) + else: + _spin(0.003) + xs.append(int(os.pread(fd, 32, 0).strip())) if i % 100 == 99: ctx.checkpoint() - return diffs + return _level_stats(xs) try: - _param_write(PIC_GAP_PARAM, 0) + _param_write(PIC_SETTLE_PARAM, 0) ctx.sleep(0.05) - control = _pair_stats(pairs(300)) - _param_write(PIC_GAP_PARAM, 1000) + control = {"idle": reads("idle"), "busy": reads("busy")} + _param_write(PIC_SETTLE_PARAM, 500) ctx.sleep(0.05) - paced = _pair_stats(pairs(300)) + settled = {"idle": reads("idle"), "busy": reads("busy")} finally: - _param_write(PIC_GAP_PARAM, saved if saved not in (None, "0") else 1000) + os.close(fd) + _param_write(PIC_SETTLE_PARAM, saved if saved not in (None, "0") else 500) ev["control"] = control - ev["paced"] = paced - ev["pic_gap_us_after"] = _param_read(PIC_GAP_PARAM) - ctx.log("control (no pacing): second minus first over %d pairs: mean %+.2f, interquartile %d, " - "range %+d..%+d", control["n"], control["mean"], control["iqr"], control["min"], control["max"]) - ctx.log("paced (1000 us): second minus first over %d pairs: mean %+.2f, interquartile %d, " - "range %+d..%+d", paced["n"], paced["mean"], paced["iqr"], paced["min"], paced["max"]) - ctx.check(abs(paced["mean"]) <= 2.0, - "paced pairs still differ by %+.2f counts on average", paced["mean"]) - ctx.check(paced["iqr"] <= 3, - "paced pairs still spread %d counts (interquartile)", paced["iqr"]) - ctx.check(paced["iqr"] <= control["iqr"] + 1 and abs(paced["mean"]) <= abs(control["mean"]) + 0.5, - "pacing did not tighten the pairs: control mean %+.2f iqr %d, paced mean %+.2f iqr %d", - control["mean"], control["iqr"], paced["mean"], paced["iqr"]) - ctx.check(ev["pic_gap_us_after"] == "1000", "pic_gap_us left at %s", ev["pic_gap_us_after"]) - ctx.log("PASS: paced pairs agree (mean %+.2f, interquartile %d); control mean %+.2f, interquartile %d", - paced["mean"], paced["iqr"], control["mean"], control["iqr"]) + ev["settled"] = settled + ev["pic_settle_us_after"] = _param_read(PIC_SETTLE_PARAM) + for name, r in (("control (settle off)", control), ("settled (500 us)", settled)): + ctx.log("%s: after sleep median %d (iqr %d, %d..%d); after spin median %d (iqr %d, %d..%d)", + name, r["idle"]["med"], r["idle"]["iqr"], r["idle"]["min"], r["idle"]["max"], + r["busy"]["med"], r["busy"]["iqr"], r["busy"]["min"], r["busy"]["max"]) + ev["control_split"] = control["busy"]["med"] - control["idle"]["med"] + ev["settled_split"] = settled["busy"]["med"] - settled["idle"]["med"] + ctx.log("split busy minus idle: control %+d, settled %+d", ev["control_split"], ev["settled_split"]) + ctx.check(abs(ev["settled_split"]) <= 2, + "settled reads still split by %+d counts between an idle and a busy reader", ev["settled_split"]) + ctx.check(settled["idle"]["iqr"] <= 4 and settled["busy"]["iqr"] <= 4, + "settled reads spread %d / %d counts (interquartile)", settled["idle"]["iqr"], settled["busy"]["iqr"]) + ctx.check(abs(settled["idle"]["med"] - control["busy"]["med"]) <= 3, + "a settled idle reader reads %d, the busy regime reads %d: the settle did not land the " + "conversion under load", settled["idle"]["med"], control["busy"]["med"]) + ctx.check(ev["pic_settle_us_after"] == "500", "pic_settle_us left at %s", ev["pic_settle_us_after"]) + ctx.log("PASS: settled, an idle reader and a busy reader read the same (split %+d); control split %+d", + ev["settled_split"], ev["control_split"])