Ledger

M1-04B

1,000-bot soak part B: snapshot build and hand-off on 4 cores, 10-minute soak, metrics chart

← Ledger

partialstatus · M1

9✓ 1✗tests passed / failed

0tokens · 18 min

3evidence files · 73 kB

Evidence

From logs/evidence/M1-04B/. Click a thumbnail for the full image.

Logs and data (3)

summary.txt · 2 kB · open

M1-04B (part B of M1-04) - snapshot build + hand-off on a fixed pool of 4 threads; 1,000 bots re-measured
Machine: Apple M3 (4P+4E), shared with other projects; load average read before/after each run (sysctl vm.loadavg).

Change: services/zone/src/pool.rs ShardPool (std threads, no crate): clients in stable shards (slot % 4), shard 0 on
the tick thread, shards 1-3 on zone-snap-1..3; per tick the workers get a shared read-only handle on the tick's
ZoneState, build + hand off their own clients, drop the handle and return the shard (the barrier). netcode.json
server.snapshotWorkers 4 (proposed); --snapshot-workers 1 is the single-threaded path. Bots: loadTest.botMix
fieldSpawnShare 0.5 (proposed): half the bots spawn inside a random hunting zone (in-process load server only).

Determinism / allocation: services/zone/tests/snapshot_pool.rs - 60 clients, 800 moving entities, per-client ack lags:
4 shards produce byte-identical snapshots to 1 shard for 100 compared ticks; 60 warm ticks of both pools allocate
nothing on any thread. snapshot_no_alloc still passes (task log M1-04B-01 PASS).

Run 1 (metrics-80s-4workers.json, 4 snapshot workers): 1,000 bots, 20 s ramp + 60 s hold. PASS.
  load 13.95 27.49 26.56 -> 100.01 47.00 33.85
  1000/1000 joined, 0 disconnects, 0 skipped frames, 0 dropped ticks
  loop p50 6.38  p99 12.10 (target 15)  max 82.44 ms; 8 ticks over the target
  phase means: ingest 0.25, tick 0.91, build 2.59 + hand-off 1.30 (slowest shard), pool wait 1.14 ms
  CPU per tick: tick thread 2.94 ms (p99 5.13) + workers 6.45 ms
  downstream per bot (hold) mean 3,743 p95 9,896 max 10,587 B/s (target avg <= 12,000, hard cap 32,000)
  RTT p50 45.0 p99 55.3 ms

Run 2 (metrics-80s-1worker.json, single-threaded comparison, same bots and placement): FAIL under machine load.
  load 54.78 41.94 32.60 -> 62.33 48.55 36.01
  loop p50 16.60 p99 2,611.86 ms (one stall; 160 dropped ticks, 563 skipped frames)
  phase means: build 14.52, hand-off 8.89 ms; tick-thread CPU mean 10.95 p99 16.90 ms
  The single-threaded path does ~11 ms of CPU per tick on one thread: with any load it misses 15 ms p99.

Not done here (M1-04C): --steps stepped ramp 100/250/500/1,000, the 10-minute hold, memory-drift check, per-second RSS
and RTT series, the Grafana-like PNG chart and the card's soak pass/fail.

metrics-80s-1worker.json · 35 kB · open

{
  "task": "M1-04",
  "generatedBy": "pnpm zone:bots (cargo run --release -p zoen-bots --bin bots)",
  "what": "1000 bots over WebSocket on loopback against the in-process zone server: linear connect ramp 20 s, then a 60 s hold (bandwidth per bot is measured over the hold), then a 1000 close each",
  "behaviours": {"walk": "waypoint wander steered by the own exact position in each snapshot; one input per snapshot (20/s), an ack per snapshot, a ping per second", "fight": "hunters cast every castEveryS once inside their zone and stand still castMs; the cast is a bot-side timer (counted, not sent): protocol v1 input has no action/skill bits", "chat": "not in protocol v1: a bot-side timer every chatEveryS (counted, not sent)", "mix": {"townSharePermille": 250, "townRadiusMm": 50000, "pauseMs": [0, 3000], "castMs": 800, "castEveryMs": [2000, 6000], "chatEveryMs": [15000, 45000], "source": "netcode.json loadTest (botMix proposed by M1-04)"}},
  "harness": {"bots": 1000, "workers": 4, "rampS": 20, "snapshotWorkers": 1, "fieldSpawnPermille": 500, "holdS": 60, "runS": 80.167, "threads": "bots run on 4 poll(2) worker threads, not one OS thread per bot: the in-process server already runs two threads per client plus the tick on this 8-core Mac, and a worker wakes about once per tick for all its sockets instead of 1,000 threads waking 40+ times a second"},
  "machine": {"os": "macos", "arch": "aarch64", "availableParallelism": 8, "loadAverageBefore": "54.78 41.94 32.60", "loadAverageAfter": "62.33 48.55 36.01", "loadAndRss": [{"tS": 0.0, "load": "54.78 41.94 32.60", "rssKiB": 2336}, {"tS": 10.0, "load": "49.15 41.14 32.42", "rssKiB": 155680}, {"tS": 20.0, "load": "43.83 40.26 32.21", "rssKiB": 304832}, {"tS": 30.0, "load": "80.76 48.22 35.13", "rssKiB": 304832}, {"tS": 40.0, "load": "71.00 47.21 34.92", "rssKiB": 304832}, {"tS": 50.0, "load": "80.71 49.98 36.04", "rssKiB": 304832}, {"tS": 60.0, "load": "76.63 50.12 36.25", "rssKiB": 304928}, {"tS": 70.0, "load": "67.78 49.10 36.05", "rssKiB": 304512}, {"tS": 80.0, "load": "62.33 48.55 36.01", "rssKiB": 303312}, {"tS": 80.2, "load": "62.33 48.55 36.01", "rssKiB": 273152}]},
  "thresholds": {"loopP99Ms": 15.000, "avgDownstreamBps": 12000, "hardCapBps": 32000, "source": "netcode.json tick.targetP99Ms, loadTest.avgDownstreamKBps, snapshot.hardCapKBps (KB = 1,000 B)"},
  "bots": {"requested": 1000, "joined": 1000, "connectErrors": 0, "disconnects": 0, "cleanCloses": 1000, "inField": 500, "spawnedInField": 500, "snapshots": 1234842, "fullSnapshots": 1069, "missedTicks": 563, "inputs": 1234842, "acks": 1234842, "pings": 67520, "pongs": 67043, "waypointsReached": 1909, "castsNotSent": 8363, "chatLinesNotSent": 1854},
  "downstreamBpsPerBotHold": {"mean": 3316.3, "p50": 692.7, "p95": 8683.9, "p99": 8973.6, "max": 9238.7, "samples": 1000},
  "upstreamBpsPerBotHold": {"mean": 458.6, "p50": 458.7, "p95": 459.2, "p99": 459.3, "max": 459.5, "samples": 1000},
  "rttMs": {"mean": 73.154, "p50": 40.622, "p95": 161.816, "p99": 1080.330, "max": 2216.787, "samples": 67043},
  "botSeries": [{"tS": 1.0, "joined": 48, "downBpsPerBot": 598}, {"tS": 2.0, "joined": 100, "downBpsPerBot": 1698}, {"tS": 3.0, "joined": 148, "downBpsPerBot": 2843}, {"tS": 4.0, "joined": 198, "downBpsPerBot": 3639}, {"tS": 5.0, "joined": 248, "downBpsPerBot": 4089}, {"tS": 6.0, "joined": 298, "downBpsPerBot": 4883}, {"tS": 7.0, "joined": 348, "downBpsPerBot": 5266}, {"tS": 8.0, "joined": 398, "downBpsPerBot": 5399}, {"tS": 9.0, "joined": 448, "downBpsPerBot": 5400}, {"tS": 10.0, "joined": 498, "downBpsPerBot": 5478}, {"tS": 11.0, "joined": 548, "downBpsPerBot": 5275}, {"tS": 12.0, "joined": 598, "downBpsPerBot": 5348}, {"tS": 13.0, "joined": 650, "downBpsPerBot": 5320}, {"tS": 14.0, "joined": 698, "downBpsPerBot": 5307}, {"tS": 15.0, "joined": 747, "downBpsPerBot": 5200}, {"tS": 16.0, "joined": 798, "downBpsPerBot": 5547}, {"tS": 17.0, "joined": 849, "downBpsPerBot": 5432}, {"tS": 18.0, "joined": 898, "downBpsPerBot": 5454}, {"tS": 19.0, "joined": 948, "downBpsPerBot": 5469}, {"tS": 20.0, "joined": 998, "downBpsPerBot": 5456}, {"tS": 21.0, "joined": 1000, "downBpsPerBot": 5439}, {"tS": 22.0, "joined": 1000, "downBpsPerBot": 5147}, {"tS": 23.0, "joined": 1000, "downBpsPerBot": 5045}, {"tS": 24.0, "joined": 1000, "downBpsPerBot": 5047}, {"tS": 25.0, "joined": 1000, "downBpsPerBot": 4790}, {"tS": 26.0, "joined": 1000, "downBpsPerBot": 4556}, {"tS": 27.0, "joined": 1000, "downBpsPerBot": 4406}, {"tS": 28.0, "joined": 1000, "downBpsPerBot": 4380}, {"tS": 29.0, "joined": 1000, "downBpsPerBot": 4288}, {"tS": 30.0, "joined": 1000, "downBpsPerBot": 4310}, {"tS": 31.0, "joined": 1000, "downBpsPerBot": 4247}, {"tS": 32.0, "joined": 1000, "downBpsPerBot": 4158}, {"tS": 33.0, "joined": 1000, "downBpsPerBot": 4110}, {"tS": 34.0, "joined": 1000, "downBpsPerBot": 4093}, {"tS": 35.0, "joined": 1000, "downBpsPerBot": 4004}, {"tS": 36.0, "joined": 1000, "downBpsPerBot": 3949}, {"tS": 37.0, "joined": 1000, "downBpsPerBot": 3709}, {"tS": 38.0, "joined": 1000, "downBpsPerBot": 4210}, {"tS": 39.0, "joined": 1000, "downBpsPerBot": 3870}, {"tS": 40.0, "joined": 1000, "downBpsPerBot": 3797}, {"tS": 41.0, "joined": 1000, "downBpsPerBot": 3843}, {"tS": 42.0, "joined": 1000, "downBpsPerBot": 3595}, {"tS": 43.0, "joined": 1000, "downBpsPerBot": 3886}, {"tS": 44.0, "joined": 1000, "downBpsPerBot": 3586}, {"tS": 45.0, "joined": 1000, "downBpsPerBot": 3806}, {"tS": 46.0, "joined": 1000, "downBpsPerBot": 3659}, {"tS": 47.0, "joined": 1000, "downBpsPerBot": 3651}, {"tS": 48.0, "joined": 1000, "downBpsPerBot": 3666}, {"tS": 49.0, "joined": 1000, "downBpsPerBot": 3583}, {"tS": 50.0, "joined": 1000, "downBpsPerBot": 3575}, {"tS": 51.0, "joined": 1000, "downBpsPerBot": 3471}, {"tS": 52.0, "joined": 1000, "downBpsPerBot": 3432}, {"tS": 53.0, "joined": 1000, "downBpsPerBot": 3423}, {"tS": 54.0, "joined": 1000, "downBpsPerBot": 3499}, {"tS": 55.1, "joined": 1000, "downBpsPerBot": 748}, {"tS": 56.0, "joined": 1000, "downBpsPerBot": 371}, {
…

metrics-80s-4workers.json · 35 kB · open

{
  "task": "M1-04",
  "generatedBy": "pnpm zone:bots (cargo run --release -p zoen-bots --bin bots)",
  "what": "1000 bots over WebSocket on loopback against the in-process zone server: linear connect ramp 20 s, then a 60 s hold (bandwidth per bot is measured over the hold), then a 1000 close each",
  "behaviours": {"walk": "waypoint wander steered by the own exact position in each snapshot; one input per snapshot (20/s), an ack per snapshot, a ping per second", "fight": "hunters cast every castEveryS once inside their zone and stand still castMs; the cast is a bot-side timer (counted, not sent): protocol v1 input has no action/skill bits", "chat": "not in protocol v1: a bot-side timer every chatEveryS (counted, not sent)", "mix": {"townSharePermille": 250, "townRadiusMm": 50000, "pauseMs": [0, 3000], "castMs": 800, "castEveryMs": [2000, 6000], "chatEveryMs": [15000, 45000], "source": "netcode.json loadTest (botMix proposed by M1-04)"}},
  "harness": {"bots": 1000, "workers": 4, "rampS": 20, "snapshotWorkers": 4, "fieldSpawnPermille": 500, "holdS": 60, "runS": 80.075, "threads": "bots run on 4 poll(2) worker threads, not one OS thread per bot: the in-process server already runs two threads per client plus the tick on this 8-core Mac, and a worker wakes about once per tick for all its sockets instead of 1,000 threads waking 40+ times a second"},
  "machine": {"os": "macos", "arch": "aarch64", "availableParallelism": 8, "loadAverageBefore": "13.95 27.49 26.56", "loadAverageAfter": "100.01 47.00 33.85", "loadAndRss": [{"tS": 0.0, "load": "13.95 27.49 26.56", "rssKiB": 2320}, {"tS": 10.0, "load": "12.56 26.75 26.31", "rssKiB": 156016}, {"tS": 20.0, "load": "11.66 26.09 26.08", "rssKiB": 304736}, {"tS": 30.0, "load": "66.12 37.69 30.22", "rssKiB": 304736}, {"tS": 40.0, "load": "56.10 36.48 29.88", "rssKiB": 304800}, {"tS": 50.0, "load": "47.70 35.32 29.54", "rssKiB": 304800}, {"tS": 60.0, "load": "40.75 34.24 29.23", "rssKiB": 304800}, {"tS": 70.0, "load": "34.95 33.21 28.92", "rssKiB": 304800}, {"tS": 80.0, "load": "100.01 47.00 33.85", "rssKiB": 304816}, {"tS": 80.1, "load": "100.01 47.00 33.85", "rssKiB": 273760}]},
  "thresholds": {"loopP99Ms": 15.000, "avgDownstreamBps": 12000, "hardCapBps": 32000, "source": "netcode.json tick.targetP99Ms, loadTest.avgDownstreamKBps, snapshot.hardCapKBps (KB = 1,000 B)"},
  "bots": {"requested": 1000, "joined": 1000, "connectErrors": 0, "disconnects": 0, "cleanCloses": 1000, "inField": 506, "spawnedInField": 500, "snapshots": 1400617, "fullSnapshots": 1000, "missedTicks": 0, "inputs": 1400617, "acks": 1400617, "pings": 70036, "pongs": 69990, "waypointsReached": 2190, "castsNotSent": 8470, "chatLinesNotSent": 1857},
  "downstreamBpsPerBotHold": {"mean": 3743.4, "p50": 783.9, "p95": 9896.2, "p99": 10215.7, "max": 10586.9, "samples": 1000},
  "upstreamBpsPerBotHold": {"mean": 531.2, "p50": 531.2, "p95": 531.2, "p99": 531.4, "max": 531.4, "samples": 1000},
  "rttMs": {"mean": 45.241, "p50": 45.028, "p95": 51.991, "p99": 55.342, "max": 88.574, "samples": 69990},
  "botSeries": [{"tS": 1.0, "joined": 48, "downBpsPerBot": 598}, {"tS": 2.0, "joined": 98, "downBpsPerBot": 1614}, {"tS": 3.0, "joined": 148, "downBpsPerBot": 2924}, {"tS": 4.0, "joined": 198, "downBpsPerBot": 3629}, {"tS": 5.0, "joined": 250, "downBpsPerBot": 4114}, {"tS": 6.0, "joined": 298, "downBpsPerBot": 4854}, {"tS": 7.0, "joined": 348, "downBpsPerBot": 5254}, {"tS": 8.0, "joined": 398, "downBpsPerBot": 5412}, {"tS": 9.0, "joined": 448, "downBpsPerBot": 5399}, {"tS": 10.0, "joined": 499, "downBpsPerBot": 5458}, {"tS": 11.0, "joined": 548, "downBpsPerBot": 5287}, {"tS": 12.0, "joined": 598, "downBpsPerBot": 5318}, {"tS": 13.0, "joined": 648, "downBpsPerBot": 5317}, {"tS": 14.0, "joined": 698, "downBpsPerBot": 5352}, {"tS": 15.0, "joined": 748, "downBpsPerBot": 5342}, {"tS": 16.0, "joined": 798, "downBpsPerBot": 5381}, {"tS": 17.0, "joined": 848, "downBpsPerBot": 5487}, {"tS": 18.0, "joined": 898, "downBpsPerBot": 5346}, {"tS": 19.0, "joined": 948, "downBpsPerBot": 5471}, {"tS": 20.0, "joined": 998, "downBpsPerBot": 5437}, {"tS": 21.0, "joined": 1000, "downBpsPerBot": 5427}, {"tS": 22.0, "joined": 1000, "downBpsPerBot": 5227}, {"tS": 23.0, "joined": 1000, "downBpsPerBot": 5015}, {"tS": 24.0, "joined": 1000, "downBpsPerBot": 4986}, {"tS": 25.0, "joined": 1000, "downBpsPerBot": 4790}, {"tS": 26.0, "joined": 1000, "downBpsPerBot": 4570}, {"tS": 27.0, "joined": 1000, "downBpsPerBot": 4412}, {"tS": 28.0, "joined": 1000, "downBpsPerBot": 4378}, {"tS": 29.0, "joined": 1000, "downBpsPerBot": 4274}, {"tS": 30.0, "joined": 1000, "downBpsPerBot": 4332}, {"tS": 31.0, "joined": 1000, "downBpsPerBot": 4226}, {"tS": 32.0, "joined": 1000, "downBpsPerBot": 4171}, {"tS": 33.0, "joined": 1000, "downBpsPerBot": 4117}, {"tS": 34.0, "joined": 1000, "downBpsPerBot": 4083}, {"tS": 35.0, "joined": 1000, "downBpsPerBot": 4005}, {"tS": 36.0, "joined": 1000, "downBpsPerBot": 3965}, {"tS": 37.0, "joined": 1000, "downBpsPerBot": 3957}, {"tS": 38.0, "joined": 1000, "downBpsPerBot": 3970}, {"tS": 39.0, "joined": 1000, "downBpsPerBot": 3862}, {"tS": 40.0, "joined": 1000, "downBpsPerBot": 3792}, {"tS": 41.0, "joined": 1000, "downBpsPerBot": 3827}, {"tS": 42.0, "joined": 1000, "downBpsPerBot": 3775}, {"tS": 43.0, "joined": 1000, "downBpsPerBot": 3704}, {"tS": 44.0, "joined": 1000, "downBpsPerBot": 3665}, {"tS": 45.0, "joined": 1000, "downBpsPerBot": 3710}, {"tS": 46.0, "joined": 1000, "downBpsPerBot": 3658}, {"tS": 47.0, "joined": 1000, "downBpsPerBot": 3667}, {"tS": 48.0, "joined": 1000, "downBpsPerBot": 3681}, {"tS": 49.0, "joined": 1000, "downBpsPerBot": 3589}, {"tS": 50.0, "joined": 1000, "downBpsPerBot": 3584}, {"tS": 51.0, "joined": 1000, "downBpsPerBot": 3459}, {"tS": 52.0, "joined": 1000, "downBpsPerBot": 3440}, {"tS": 53.0, "joined": 1000, "downBpsPerBot": 3446}, {"tS": 54.0, "joined": 1000, "downBpsPerBot": 3480}, {"tS": 55.0, "joined": 1000, "downBpsPerBot": 3501}, {"tS": 56.0, "joined": 1000, "downBpsPerBot": 3491}, {"
…

Tests

pass cargo test zoen-zone + zoen-bots (pool determinism, no-alloc, server e2e) · 17.2 s · raw log$ cargo test --release -q -p zoen-zone -p zoen-bots

pass zone:bots 1000 bots 20+60 s, 4 snapshot workers · 80.7 s · raw log

$ cargo run --quiet --release -p zoen-bots --bin bots -- --bots 1000 --ramp-s 20 --hold-s 60 --snapshot-workers 4 --out logs/evidence/M1-04B/metrics-80s-4workers.json --quiet

fail zone:bots 1000 bots 20+60 s, 1 snapshot worker (single-threaded comparison) · 80.4 s · raw log

$ cargo run --quiet --release -p zoen-bots --bin bots -- --bots 1000 --ramp-s 20 --hold-s 60 --snapshot-workers 1 --out logs/evidence/M1-04B/metrics-80s-1worker.json --quiet

pass data tests · 27.1 s · raw log$ pnpm data:test

pass zoen-sim cargo tests + clippy · 64.1 s · raw log$ pnpm sim:test

pass Zoen.Core dotnet build + xunit · 5.1 s · raw log$ pnpm core:test

pass docs lint + index · 0.5 s · raw log$ pnpm docs:lint

pass wiki typecheck · 13.2 s · raw log$ pnpm --filter @zoen/wiki typecheck

pass wiki production build · 22.6 s · raw log$ pnpm wiki:build

pass wiki e2e (changed specs) · 1.2 s · raw log$ pnpm --filter @zoen/wiki exec playwright test --only-changed

Notes

2026-10-10 22:14 UTC · Part B done, finishing partial; rest is M1-04C (roadmap card added). (1) services/zone/src/pool.rs ShardPool<S: Shard> (std threads, no crate; rayon rejected: scoped jobs allocate per tick): n shards, shard 0 on the tick thread, shards 1..n on zone-snap-k threads; per tick each worker gets Arc<ZoneState> (read-only), runs its shard, drops the Arc and returns the shard over a bounded channel (barrier); catch_unwind keeps a shard on panic; a gone worker's shard runs inline (fallbacks counter). Server: sessions live in SessionShard (slot s -> shard s % n, index s / n), per-shard Tally merged in shard order; zone is Arc<ZoneState>, mutated via Arc::make_mut after the barrier (never clones). Profile: 5 phases (snapshotBuild/handOff = slowest shard, new poolWait = rest of the parallel section) + worker CPU histogram and window workerCpuMeanMs. Data (proposed): netcode.json server.snapshotWorkers 4 (1 = single-threaded path, --snapshot-workers on zone:bots), loadTest.botMix.fieldSpawnShare 0.5 (NetConfig fields_mm + field_spawn_permille: the in-process load server spawns that share inside a random hunting zone; bots turn hunter on their first snapshot; town share kept over all bots). (2) Test services/zone/tests/snapshot_pool.rs: 60 clients/800 moving entities, 1-shard vs 4-shard pools byte-identical for 100 ticks, 60 warm ticks allocate nothing on any thread; snapshot_no_alloc still green (M1-04B-01 PASS, clippy clean). (3) 1,000 bots 20 s ramp + 60 s hold, 4 workers (M1-04B-02 PASS, load 13.95 -> 100.01): 0 disconnects, loop p50 6.38 p99 12.10 max 82.4 ms, CPU tick thread 2.94 + workers 6.45 ms/tick, phases ingest 0.25 tick 0.91 build 2.59 hand-off 1.30 poolWait 1.14 ms, down mean 3.7 p95 9.9 max 10.6 KB/s/bot, RTT p50 45 p99 55 ms. Single-threaded comparison (M1-04B-03 FAIL, load 54.8 -> 62.3): p99 2,612 ms stall, 160 dropped ticks, tick-thread CPU 10.95 ms/tick. Evidence logs/evidence/M1-04B/: summary.txt, metrics-80s-4workers.json, metrics-80s-1worker.json. verify --changed PASS (04-10). M1-04C: --steps stepped ramp 100/250/500/1000, 10-min hold, memory drift (loadTest.memoryDriftPercent; per-second RSS in botSeries), per-second RTT series (atomic RTT buckets in Counters), Grafana-like PNG from metrics.json, summary + server log excerpt; split because the context meter passed 150k.