blockblaz / blockblaz/zeam

Investigate slow `slot_interval` / tick duration (event-loop starvation vs nominal 0.8s)

Open
#863 3 comments 0 reactions 0 assignees View on GitHub
Dominant language
Zig
Stars
97
Forks
39
PR merge metrics
No merged PRs in 30d

Description

## Summary

Under real devnet load (e.g. `zeam_0` on devnet-4), logs show **`[clock]` and `[forkchoice]` `slot_interval=… duration=…s` far above the nominal ~0.8s** (per-slot interval), including spikes of **~7s, ~10s, and ~20s+**. We need to **identify root cause(s)** and **improve performance** so slot timing stays close to spec.

## What the metric actually measures

`Clock.run()` alternates `tickInterval()` (which logs `duration`) and `events.run(.until_done)`:

```zig
// pkgs/node/src/clock.zig
pub fn run(self: *Self) !void {
while (true) {
self.tickInterval();
try self.events.run(.until_done);
}
}
```

`duration` is **wall time since the previous `tickInterval()` call**, not “time spent inside fork choice only.” Large values therefore indicate **the xev loop did not return to the top of `Clock.run` for that long** — typically because **`events.run(.until_done)` drained a large backlog** and/or **one or more completions ran for a long time** without yielding.

`[forkchoice]` uses the same pattern (`forkchoice.zig` — `tickIntervalUnlocked` logs elapsed since last fork-choice tick).

## Observed behaviour (evidence)

- **Correlated spikes:** e.g. at the same wall time, **`[forkchoice] slot_interval=2 duration=21.387s`** and **`[clock] slot_interval=0 duration=22.200s`**, implying the **slot driver and fork-choice tick logging stall together** — consistent with **one busy event loop**, not independent subsystems drifting.
- **Logs still appear during a long gap** (`[node]`, `[network]` / rust-bridge), so the process is not globally frozen; work is **queued or running elsewhere** while **clock/forkchoice ticks are delayed**.
- **Prometheus (example scrape on `zeam_0`):**
- `lean_tick_interval_duration_seconds` and `zeam_fork_choice_tick_interval_duration_seconds` show **non-trivial mass past nominal buckets** (tail / `+Inf` worth watching over longer windows).
- `zeam_chain_onblock_duration_seconds`: histogram shows **at least one `onBlock` in the multi-second range** (buckets suggest work **>5s** for at least one block in the sample window), which is a **prime suspect** if that path still runs on the hot loop or blocks completion scheduling.
- `lean_gossip_mesh_peers` (separate from this issue, but useful context): mesh count **< connected peer count** — expected for GossipSub.

## Likely root-cause class

**Event-loop / slot-driver starvation:** long-running or bursty completions (chain `onBlock`, gossip handlers, reqresp, DB, etc.) **delay the next `tickInterval()`**, which shows up as **`duration` ≫ 0.8s** and contributes to **head lagging “current slot”** (`Behind = current_slot - head_slot` in `chain.zig`).

Exact contributors need **profiling / tracing** (per-completion timings, attribution to `onBlock`, attestation batch, rust-bridge callbacks, etc.).

## Suggested investigation

1. **Instrument or sample** longest xev completions (or add a “slow completion” log when a single `events.run` iteration exceeds e.g. 500ms / 1s).
2. **Break down `zeam_chain_onblock_duration_seconds` p99** vs wall-clock spikes on the same host.
3. **Confirm chain-worker path** (`--chain-worker on`) is actually taking producer-side load off the loop under this deployment; check `lean_chain_queue_*` metrics during spikes.
4. **Host / infra:** CPU steal, disk latency, concurrent containers (`prometheus`, `cadvisor`, …) on the same VM — rule out before deep Zig changes.

## Suggested improvements (after attribution)

- Move or bound any remaining **long synchronous work** off the slot-driver path.
- **Back-pressure / batching** for gossip or reqresp if they flood completions.
- **Docs / ops:** document that `slot_interval duration` is a **loop-health** signal, not fork-choice algorithm latency alone.

## References in tree

- `pkgs/node/src/clock.zig` — `run` / `tickInterval` / `duration` logging
- `pkgs/node/src/forkchoice.zig` — `tickIntervalUnlocked` logging
- `pkgs/node/src/chain.zig` — `Behind` / `printSlot`
- `pkgs/metrics` — `lean_tick_interval_duration_seconds`, `zeam_fork_choice_tick_interval_duration_seconds`, `zeam_chain_onblock_duration_seconds`, `lean_gossip_mesh_peers`

---

*Opened from devnet-4 observation; happy to attach longer metric snapshots or log excerpts if useful.*

Contributor guide

No contributing guide indexed for this repository

Research direction

Start with pkgs/node/src/clock.zig and forkchoice.zig to trace tick timing and inspect how events.run(.until_done) delays the next tick. Compare slow xev completions and zeam_chain_onblock_duration_seconds with the tick-interval metrics, and check chain-worker and queue metrics during spikes. Done means the dominant contributor is identified and slot intervals remain close to the nominal value under comparable load.

Written by the indexing model from the issue text.

Assessment

Tech stack
zig
Domain
distributed-systems, observability, performance
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Quiet
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.