Skip to content

Event-loop watchdog is phase-locked to the 60 s park cycle (10 s sampler, 10 | 60): effective threshold is 16.60 s not 15 s, 45 % of ≥15 s stalls are unlogged, and the 540× WARN step on 07-28 is a sawtooth wrap #3795

Description

@tomerweller

Summary

The event-loop watchdog samples on a rigid 10 s grid while the peer_maintenance /
peer_refresh park cycle is exactly 60 s. 10 divides 60, so the sampler visits every
park at the same phase forever. The consequence is that the coded threshold
(stale_secs >= 15) is not the threshold that operates:

  • The effective detection threshold on this node right now is 16.60 s, and it is a
    knife edge — a 16.545 s stall is invisible, a 16.646 s stall is logged. Measured over
    40 consecutive parks: perfectly separable, 0/40 misclassified.
  • 45 % of stalls that exceeded the coded 15 s threshold were not logged in the current
    window (18 of 40), because the single sensitive sample lands at a fixed 16.59 s
    (spread 76 ms over 22 detections).
  • That effective threshold drifts +0.574 s/day and wraps every ~17 days, sawtoothing
    between ~15 s and ~25 s. Two wraps are in the corpus.
  • The 540× step in the WARN count on 07-28 (1/day → 538/day) is one of those wraps.
    It is not a regression: park p50 moved 13.7 → 14.7 s that day, a 7 % change.
  • In the 10 days before the wrap (07-18 → 07-27) the threshold sat at 19.7–24.6 s. On
    07-27 the loop spent 87.5 minutes in states where it had been continuously
    un-ticked for ≥15 s. The watchdog logged one line.

Deployed 0ac84d42, PID 1512116, uptime 28 d 23 h 20 m, 0 log rotations —
so every number below comes from one process and one binary.

1. Mechanism (deployed source)

crates/app/src/app/lifecycle.rs:531 — the freshness stamp is bumped once per loop
iteration
, at the top, immediately before the select! whose duration becomes
elapsed_ms:

loop {
    select_iteration += 1;
    self.tick_event_loop();          // <-- the only call site in the tree
    self.set_phase(0);let phase_dispatch_start = std::time::Instant::now();
    tokio::select! {}

So stale_secs and the park WARN's elapsed_ms measure the same interval from the
same anchor
— one sampled mid-flight by the watchdog thread, one recorded by the loop
on resume. That makes the comparison below exact rather than approximate.

crates/app/src/app/mod.rs:3620-3653 — the sampler:

let (lock, cvar) = &*condvar_thread;
let guard = lock.lock().unwrap_or_else(|e| e.into_inner());
let _ = cvar.wait_timeout(guard, Duration::from_secs(10));   // <-- 10 s, fixedlet stale_secs = now_ms.saturating_sub(last_tick) / 1000;

and mod.rs:4075-4079 routes >=30 → ERROR, >=15 → WARN. There is no dedup and no
cooldown
: every sample in [15, 30) emits a line.

The grid is rigid, not approximate. On 07-30, 647 of 647 inter-arrival gaps between
WARN lines are exact multiples of 10 s.

2. The effective threshold, measured deterministically

Current window 20:25:50 → 21:06:05Z (2,415.9 s), 40 parks, all 40 above the coded 15 s
threshold
(min 15,944 ms). 22 detected, 18 missed:

detected  elapsed_ms:  16,646 … 26,796      n=22
MISSED    elapsed_ms:  15,944 … 16,545      n=18   (45.0 % miss rate)

best single cutoff C = 16,545 ms   ->   misclassified 0/40
max(missed) 16,545  <  min(detected) 16,646     PERFECTLY SEPARABLE

Detection is not probabilistic — it is a step function of stall duration at a cutoff the
code never states. The reason is visible in the offset of the detecting sample into its
park:

n=22   min 16.524 s   p50 16.589 s   max 16.600 s   spread 76 ms

Park onsets are pinned at (t mod 60) = 5.80 / 15.80 s; the grid fires at 22.4 /
32.4. Both differences are 16.6 s. Of the six 10 s slots available per minute, only
one is ever inside the sensitive band.

3. The threshold is a 17-day sawtooth, and 07-28 is a wrap

Effective threshold per day = (grid phase − park onset phase) lifted into [15, 30),
both measured from the log. parks>thr is the resulting prediction; observed is the
actual WARN count:

day parks onset (mod 60) grid (mod 60) eff. threshold parks > thr observed
07-02 5 5.79 46.09 20.30 0 1
07-04 638 5.80 47.39 21.60 0 1
07-06 681 5.80 38.31 22.51 0 2
07-08 659 5.80 59.85 24.06 0 1
— wrap A —
07-12 675 5.80 11.68 15.89 1 1
07-14 1,147 5.80 52.91 17.11 0 1
07-16 1,440 15.80 54.13 18.33 0 1
07-19 1,440 15.80 25.46 19.67 0 1
07-20 1,444 15.80 26.40 20.61 2 3
07-22 1,462 15.80 27.74 21.95 37 41
07-23 1,458 15.79 27.82 22.02 23 24
07-25 1,440 15.80 48.99 23.19 1 2
07-26 1,440 15.79 29.94 24.15 1 1
07-27 1,440 15.79 30.42 24.63 1 1
— wrap B —
07-28 1,458 15.79 21.13 15.33 687 538
07-29 1,442 15.80 21.56 15.77 671 673
07-30 1,289 15.80 22.20 16.40 644 648

The prediction tracks the observation on 19 of 21 days, including the two intermediate
cases (07-22: 37 vs 41; 07-23: 23 vs 24) and the plateau (07-29: 671 vs 673; 07-30: 644
vs 648). Only 07-28 is loose (687 vs 538) — that is the transition day, so a single daily
modal phase does not describe it.

Drift, fit per segment:

segment 1  07-02..07-08   n=7    +0.6118 s/day   R2=0.99217
segment 2  07-12..07-27   n=11   +0.5763 s/day   R2=0.99603
segment 3  07-28..07-30   n=3    +0.5350 s/day   R2=0.98960
mean +0.5743 s/day  ->  wrap period = 10 s / 0.574 = 17.4 days

Observed wraps: between 07-08 (24.06 s) and 07-12 (15.89 s), and between 07-27 (24.63 s)
and 07-28 (15.33 s) — 16 days apart.

4. What was lost during the blind phase

Because elapsed_ms and stale_secs share an anchor (§1), the log records what the
watchdog should have seen. Continuous ≥15 s un-ticked time per day, against what was
reported:

day eff. threshold ≥15 s un-ticked time WARN lines
07-24 ~22.6 s 3,630 s (60.5 min) 0
07-25 23.19 s 4,220 s (70.3 min) 2
07-26 24.15 s 4,963 s (82.7 min) 1
07-27 24.63 s 5,251 s (87.5 min) 1

On 07-27 the event loop was in a ≥15 s stall for 87.5 minutes of the day and the
watchdog emitted one line. Any consumer keying on this signal — a dashboard, an alarm, a
monitor tick — was dark for ten days and then saw a 540× step change with no underlying
regression.

5. What this does not change

Stating this explicitly so the finding is not over-read:

  1. Watchdog auto-abort is armed at 120s on the mainnet validator; the 07-12 freeze already reached 101.3s (84%) and #3702 makes the abort unrecoverable #3767's abort risk stands. For a 120 s freeze, ≥12 samples land inside it, so
    phase-lock cannot defeat should_abort(). The phase-lock only matters when
    stall − 15 s < 10 s, i.e. exactly the current park population.
  2. Event loop parked 13-29s once per minute (28% duty-cycle loss): peer_refresh arm awaits inline, 69k-row peers table — recurrence of #3582 #3756's duty-cycle numbers stand. They are computed from loop-side elapsed_ms,
    not from watchdog samples. This window: 40 parks, sum 841.47 s, merged union
    841.47 s (6th consecutive sum == union disjointness check), duty cycle 34.8 %.
  3. Event-loop freeze ~90s in broadcast phase (phase=3, fetch_channel_depth_max=1054) — self-recovered, 2026-07-12 #3723's ERROR-tier freezes were caught fairly. Per #3723 comment
    5125155721
    ,
    broadcast (phase=3) parks are aperiodic — they do not land on the pinned
    :05.80 / :15.80 onsets, so they sample uniformly and are not phase-locked. That is
    why the 101.3 s and 60.1 s freezes produced full stale_secs ladders.
  4. One refinement to Watchdog auto-abort is armed at 120s on the mainnet validator; the 07-12 freeze already reached 101.3s (84%) and #3702 makes the abort unrecoverable #3767. Its headline "101.3 s = 84 % of 120 s" mixes scales: the
    101.3 s is elapsed_ms, but should_abort() trips on stale_secs, whose last sample
    read 93. On the scale the abort actually uses, that freeze reached 77.5 %, and a
    true freeze must reach ~120–130 s to trip. Watchdog auto-abort is armed at 120s on the mainnet validator; the 07-12 freeze already reached 101.3s (84%) and #3702 makes the abort unrecoverable #3767 already notes the truncation; this
    just puts the number on the right axis.

6. Prediction (falsifiable)

The threshold reaches the top of the sawtooth (~25 s) in 15.0 days → wrap ~2026-08-14.
By then #3756's ramp puts park p50 near 29.8 s, well above the post-wrap 15.3 s. So
detection should stay near 100 % across this wrap rather than collapsing as it did on
07-08. If instead the count drops back to ~1/day around 08-14, the ramp has flattened —
either outcome is informative, and both are checkable from the WARN count alone.

7. Asks

  1. Break the 10 s / 60 s commensurability. Any sample period coprime with 60
    (7 s, 11 s, 13 s) makes the sampler walk the park phase instead of standing still, so
    the effective threshold converges on the coded one. One-line change; removes the whole
    class.
  2. Better: don't sample at all. The loop already computes the exact stall duration
    (phase_dispatch_start.elapsed()) and already emits a WARN at ≥2,000 ms. Bump a
    counter / histogram there, gated at 15 s, and the measurement becomes exact and
    complete. Sampling an interval the measured party can report directly is the root
    defect.
  3. Do not use the WARN-line count as a rate or health signal until (1) or (2) lands.
    Its 07-28 step would read as a regression to anyone who did not measure the grid phase.
  4. Emit the effective sample period and armed abort threshold at boot — this composes
    with Watchdog auto-abort is armed at 120s on the mainnet validator; the 07-12 freeze already reached 101.3s (84%) and #3702 makes the abort unrecoverable #3767 ask 3. Neither is readable from a running node today; I had to derive both
    from source plus the absence of a [diagnostics] section.

Asks 1 and 3 are independent of 2 and small.

Reproduce

cd ~/data/$MONITOR_SESSION_ID/logs
# the grid is rigid: every gap an exact multiple of 10 s
grep -a 'WATCHDOG: Event loop slow' monitor.log | grep -a '^2026-07-30' \
  | cut -c1-23 > /tmp/wd.txt
python3 - <<'PY'
import datetime as dt
t=[dt.datetime.fromisoformat(l.strip()) for l in open('/tmp/wd.txt')]
g=[(t[i+1]-t[i]).total_seconds() for i in range(len(t)-1)]
print(sum(1 for x in g if x%10<0.05 or x%10>9.95), "/", len(g), "gaps are 10s multiples")
PY

# only one of six slots ever fires
grep -a 'WATCHDOG: Event loop slow' monitor.log | grep -a '^2026-07-29' \
  | cut -c18-19 | sort | uniq -c | sort -rn

# the perfectly-separable cutoff: pair each park [ts-elapsed, ts] against the grid
grep -a 'Slow event-loop phase' monitor.log | grep -a '^2026-07-30T2[01]'

Node state

Validating at L63,723,711, age 3 s, protocol 27, build henyey-v27.0.0-alpha.1,
deployed 0ac84d42, PID 1512116, uptime 28 d 23 h 20 m, 0 log rotations.
33 authenticated (14 in / 19 out) / 1 pending. Quorum phase=EXTERNALIZE hash=66d2e0 fail_at=1 validated=true agree=18 disagree=0 missing=3 delayed=0 lag_ms=445, transitive
intersection=true node_count=25 critical=[]. Window 20:25:50 → 21:06:05Z, coverage
100.0 %: 851/851 WARN in 16 shapes, 0 ERROR / FATAL / panic / hash mismatch /
database is locked / Lost sync / Consensus stuck in-window. Close band :30-:33
= 170/431 = 39.4 %, :12-:29 = 0/431. Nine ≥30 s close gaps, 9/9 paired,
gap − park mean +4.80 s (5th replication; prior means +5.40 / +5.18 / +5.14 /
+5.16). Disk free 2.4 GiB / 100 % (#3749). Deploys held on #3702.

Not filed urgent. This is an observability defect, not a node defect — the validator
is Validating with agree=18 disagree=0, and the stalls themselves are already tracked
on #3756 / #3723 / #3767 with correct loop-side measurements. urgent on this repo is
reserved for validator-blocking symptoms. The reason to fix it anyway is that the signal
was dark for ten days and its recovery looked exactly like a regression.

Related: #3756 (the parks), #3723 (the aperiodic broadcast arm, unaffected), #3767 (the
120 s abort, unaffected), #3689 / #3765 (arm offloads, neither deployed), #3702 (why the
abort would be unrecoverable).

/monitor-tick 2861

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingcrate:apphenyey-app cratehighHigh severity

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions