M1-04

# M1-04 part A: server + bot status lines from the 1,000-bot run (logs/test-output/M1-04-03.log); per-connection lines trimmed
[bots] 1000 bots -> ws://127.0.0.1:58989 on 4 workers: ramp 20 s, hold 60 s (load average 3.51 9.19 30.07)
[zone] t=  5.0s tick=101 clients=251 tick p50=2.43 ms p99=5.03 ms max=5.17 ms sent=13540 skipped=0 KB/s/client≈13.02
[zone] t= 10.0s tick=201 clients=500 tick p50=4.63 ms p99=19.46 ms max=21.61 ms sent=53326 skipped=0 KB/s/client≈13.40
[bots] t= 10.0s joined=498 down≈12268 B/s/bot disconnects=0
[zone] t= 15.0s tick=301 clients=750 tick p50=8.70 ms p99=21.67 ms max=41.33 ms sent=119365 skipped=0 KB/s/client≈13.15
[bots] t= 20.0s joined=999 down≈11890 B/s/bot disconnects=0
[zone] t= 20.0s tick=401 clients=1000 tick p50=10.48 ms p99=25.38 ms max=41.33 ms sent=211649 skipped=0 KB/s/client≈12.97
[zone] t= 25.0s tick=501 clients=1000 tick p50=12.44 ms p99=29.32 ms max=41.33 ms sent=316649 skipped=0 KB/s/client≈12.43
[bots] t= 30.0s joined=1000 down≈10086 B/s/bot disconnects=0
[zone] t= 30.0s tick=601 clients=1000 tick p50=15.21 ms p99=30.16 ms max=41.33 ms sent=421654 skipped=0 KB/s/client≈11.91
[zone] t= 35.0s tick=701 clients=1000 tick p50=16.96 ms p99=30.33 ms max=41.33 ms sent=526652 skipped=0 KB/s/client≈11.45
[bots] t= 40.0s joined=1000 down≈8942 B/s/bot disconnects=0
[zone] t= 40.0s tick=801 clients=1000 tick p50=17.54 ms p99=30.33 ms max=41.33 ms sent=631646 skipped=0 KB/s/client≈11.04
[zone] t= 45.0s tick=901 clients=1000 tick p50=17.46 ms p99=30.16 ms max=41.33 ms sent=736646 skipped=0 KB/s/client≈10.71
[bots] t= 50.0s joined=1000 down≈8192 B/s/bot disconnects=0
[zone] t= 50.0s tick=1001 clients=1000 tick p50=17.42 ms p99=30.16 ms max=41.33 ms sent=841650 skipped=0 KB/s/client≈10.41
[zone] t= 55.0s tick=1101 clients=1000 tick p50=17.35 ms p99=29.52 ms max=41.33 ms sent=946652 skipped=0 KB/s/client≈10.14
[bots] t= 60.0s joined=1000 down≈7507 B/s/bot disconnects=0
[zone] t= 60.0s tick=1201 clients=1000 tick p50=17.67 ms p99=32.90 ms max=61.86 ms sent=1051655 skipped=0 KB/s/client≈9.89
[zone] t= 65.0s tick=1301 clients=1000 tick p50=17.89 ms p99=33.15 ms max=61.86 ms sent=1156660 skipped=0 KB/s/client≈9.66
[bots] t= 70.0s joined=1000 down≈7140 B/s/bot disconnects=0
[zone] t= 70.0s tick=1401 clients=1000 tick p50=18.02 ms p99=32.90 ms max=61.86 ms sent=1261649 skipped=0 KB/s/client≈9.46
[zone] t= 75.0s tick=1501 clients=1000 tick p50=18.17 ms p99=32.68 ms max=61.86 ms sent=1366650 skipped=0 KB/s/client≈9.26
[zone] t= 80.0s tick=1601 clients=1000 tick p50=17.93 ms p99=32.00 ms max=61.86 ms sent=1471650 skipped=0 KB/s/client≈9.09
[bots] t= 80.0s joined=1000 down≈6662 B/s/bot disconnects=0
# first and last connection lines
[zone] 127.0.0.1:58990 joined (slot 0)
[zone] 127.0.0.1:58991 joined (slot 1)
[zone] 127.0.0.1:59684 left (slot 686): closed
[zone] 127.0.0.1:59372 left (slot 374): closed
# connection lines: 1000 joined, 1000 left (all 'closed')
bots FAIL: 1000/1000 joined, 0 disconnects, loop p50 17.93 p99 32.00 max 61.86 ms (cpu/tick mean 15.07 p99 21.67 ms; phase means ingest 0.36 tick 2.74 build 11.74 hand-off 2.56 ms; slow ticks 1237), skipped 0 dropped ticks 0, down mean 8509 p95 10211 max 10646 B/s/bot, rtt p50 39.3 p99 52.5 ms, load 3.51 9.19 30.07 -> 24.87 12.91 29.51
  failed: loopP99WithinTarget

M1-04 part A (2026-10-11) - bot client + 60 s 1,000-bot run + loop profile. Mac: 8 cores (4P+4E), load average recorded per run.

1) 200-client load check re-run (pnpm zone:loadcheck, M1-03D harness) -> loadcheck-200.json
   - load 11.3: FAIL only loop p99 21.4 ms (p50 3.5, CPU 3.73 ms/tick)       [logs/test-output/M1-04-01.log]
   - load 3.4:  PASS loop p50 3.97 p99 5.53 max 5.78 ms, CPU 3.86 ms/tick, down mean 12.7 KB/s, 0 skipped [M1-04-02.log]
   => the M1-03D 84.7 ms p99 was machine load; at 200 clients the loop fits the 15 ms target.

2) pnpm zone:bots (services/bots, new crate zoen-bots, no external crates)
   - 1,000 bots on 4 poll(2) worker threads + 1 connector thread (linear ramp), in-process server (tick thread CPU clock, 1 s windows).
   - walk: waypoint wander (25% crowd the town within 50 m of the start centre, 75% walk to a random hunting zone and wander in it).
   - fight: hunters cast every 2-6 s inside their zone (stand still 800 ms); the cast is NOT sent: protocol v1 input has no action bits.
   - chat: NOT in protocol v1; bot-side timer every 15-45 s, counted only. -> protocol owner task: action bits + chat message.

3) 1,000 bots, 20 s ramp + 60 s hold, load 3.5 -> 24.9 during the run -> metrics.json  [M1-04-03.log, FAIL on loop p99 only]
   - 1000/1000 joined, 0 disconnects, 1000 clean closes, 0 missed ticks, 0 skipped frames, 0 dropped ticks, 0 stale/dropped inputs
   - downstream per bot over the hold: mean 8.5 KB/s, p95 10.2, max 10.6 (target avg <= 12, cap 32) - PASS
   - RTT p50 39.3 ms, p99 52.5 ms (tick answers pings: ~1 tick period is server queueing)
   - loop wall p50 17.9, p99 32.0, max 61.9 ms (target p99 15) - FAIL; 1,237 of 1,602 loops over target
   - tick-thread CPU per loop: mean 15.1, p99 21.7 ms -> the loop is CPU-bound, not just machine load
   - phase means (wall): ingest 0.36, tick (sim+hash+interest) 2.74, snapshot build 11.74 (p99 20.8), hand-off 2.56 (p99 8.4) ms
   - slow loops: build 13.5 + hand-off 3.0 + tick 3.0 + ingest 0.4 ms mean
   - process RSS flat at ~305 MB during the hold (bots + server in one process)
   - only 12 hunters reached their zone in 80 s (zones are 400 m+ from the spawn at 6.2 m/s), so most bots were still walking out
     of town: a crowded scene; a 10-minute soak spreads them out.

Next (M1-04B): build snapshots + hand-off on 4 cores (per-client work is independent; no per-tick allocation),
re-measure, then the 10-minute soak with a stepped ramp and the Grafana-like PNG.

{
  "task": "M1-03D",
  "generatedBy": "pnpm zone:loadcheck (cargo run --release -p zoen-zone --bin loadcheck)",
  "what": "200 headless WebSocket clients on loopback against the in-process zone server for 10 s: random walk (new heading every 0.5-2 s), one input per tick, an ack per snapshot, a ping per second; then a 1000 close each",
  "machine": {"os": "macos", "arch": "aarch64", "availableParallelism": 8, "loadAverageBefore": "3.43 9.47 30.54", "loadAverageAfter": "3.21 9.22 30.20", "note": "clients, server tick and connection threads share this machine"},
  "thresholds": {"loopP99Ms": 15.000, "loopP99Source": "netcode.json tick.targetP99Ms", "downstreamMaxBps": 32000, "downstreamSource": "netcode.json snapshot.hardCapKBps (KB = 1,000 B)", "skippedMaxPercent": 1},
  "clients": {"requested": 200, "joined": 200, "cleanCloses": 200, "serverCloses": 0, "errors": 0, "activeSecondsMean": 10.046, "runSeconds": 10.051},
  "loop": {"what": "server loop iteration: ingest + tick + all snapshots + hand-off (10 us histogram)", "seconds": 11.155, "ticks": 224, "p50Ms": 3.970, "p99Ms": 5.530, "maxMs": 5.775, "meanMs": 3.974, "tickThreadCpuMsPerTick": 3.864, "cpuShareOfLoopWall": 0.972, "overTarget": 0, "overBudget": 0, "catchUpTicks": 0, "droppedTicks": 0, "stalls": 0, "maxLatenessMs": 10.036},
  "frames": {"sent": 44671, "skipped": 0, "snapshotErrors": 0, "clientSnapshots": 42461, "clientFullSnapshots": 2280, "clientMissedTicks": 0, "serverMaxSnapshotPayloadBytes": 1448},
  "downstreamBpsPerClient": {"mean": 12684.4, "p50": 12734.9, "p95": 13668.6, "p99": 13743.7, "max": 13773.7, "samples": 200},
  "downstreamServerCount": {"meanBps": 12006.8, "maxBps": 12683.2, "note": "server-side bytes handed to each writer, join to leave"},
  "upstreamBpsPerClient": {"mean": 534.3, "p50": 533.4, "p95": 544.4, "p99": 546.1, "max": 547.6, "samples": 200},
  "upstreamTarget": {"bps": 300, "source": "netcode.json snapshot.upstreamTargetKBps (NETCODE_1000.md: 20 inputs/s x ~14 B)", "within": false, "note": "recorded, not a check: the target counts inputs only; acks (one per snapshot) and pings are separate messages"},
  "snapshotFrameBytes": {"mean": 599.6, "p50": 580.0, "p95": 775.0, "p99": 1452.0, "max": 1452.0, "samples": 42461},
  "rttMs": {"mean": 47.313, "p50": 47.283, "p95": 54.190, "p99": 55.756, "max": 58.759, "samples": 2000},
  "rttNote": "application RTT on loopback: the tick answers pings, and each client sends right after a snapshot arrives, so about one tick period (50 ms) is server queueing, not network",
  "messagesPerClientPerSecond": {"snapshots": 21.13, "inputs": 19.34, "acks": 21.13, "pings": 1.00, "pongs": 1.00},
  "inputs": {"applied": 38854, "stale": 0, "dropped": 0},
  "server": {"accepted": 200, "joins": 200, "leaves": 200, "peakClients": 200, "refusedHandshakes": 0, "versionMismatches": 0, "full": 0, "idleTimeouts": 0, "badMessages": 0, "threadsLeft": 0},
  "errors": [],
  "checks": {"allJoined": true, "allClosedCleanly": true, "noClientErrors": true, "serverSawEveryLeave": true, "noStaleOrDroppedInputs": true, "framesSkippedUnder1Percent": true, "ticksDroppedUnder1Percent": true, "loopP99WithinTarget": true, "downstreamWithinHardCap": true, "noSnapshotErrors": true, "noThreadsLeft": true},
  "pass": true
}

{
  "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, "holdS": 60, "runS": 80.045, "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": "3.51 9.19 30.07", "loadAverageAfter": "24.87 12.91 29.51", "loadAndRss": [{"tS": 0.0, "load": "3.51 9.19 30.07", "rssKiB": 2256}, {"tS": 10.0, "load": "3.36 8.96 29.74", "rssKiB": 155968}, {"tS": 20.0, "load": "3.99 8.92 29.48", "rssKiB": 304832}, {"tS": 30.0, "load": "3.60 8.67 29.16", "rssKiB": 304832}, {"tS": 40.0, "load": "3.50 8.48 28.85", "rssKiB": 304832}, {"tS": 50.0, "load": "4.86 8.60 28.65", "rssKiB": 304832}, {"tS": 60.0, "load": "8.63 9.26 28.65", "rssKiB": 304832}, {"tS": 70.0, "load": "11.97 9.97 28.68", "rssKiB": 304848}, {"tS": 80.0, "load": "24.87 12.91 29.51", "rssKiB": 304848}, {"tS": 80.1, "load": "24.87 12.91 29.51", "rssKiB": 273568}]},
  "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": 12, "snapshots": 1400639, "fullSnapshots": 1000, "missedTicks": 0, "inputs": 1400639, "acks": 1400639, "pings": 70040, "pongs": 69994, "waypointsReached": 1829, "castsNotSent": 3, "chatLinesNotSent": 1873},
  "downstreamBpsPerBotHold": {"mean": 8508.5, "p50": 8801.9, "p95": 10210.9, "p99": 10467.9, "max": 10646.3, "samples": 1000},
  "upstreamBpsPerBotHold": {"mean": 531.3, "p50": 531.3, "p95": 531.3, "p99": 531.5, "max": 531.5, "samples": 1000},
  "rttMs": {"mean": 38.906, "p50": 39.347, "p95": 49.871, "p99": 52.539, "max": 59.605, "samples": 69994},
  "botSeries": [{"tS": 1.0, "joined": 48, "downBpsPerBot": 1917}, {"tS": 2.0, "joined": 98, "downBpsPerBot": 5731}, {"tS": 3.0, "joined": 148, "downBpsPerBot": 9707}, {"tS": 4.0, "joined": 198, "downBpsPerBot": 12042}, {"tS": 5.0, "joined": 248, "downBpsPerBot": 12248}, {"tS": 6.0, "joined": 300, "downBpsPerBot": 12576}, {"tS": 7.0, "joined": 347, "downBpsPerBot": 11971}, {"tS": 8.0, "joined": 400, "downBpsPerBot": 12195}, {"tS": 9.0, "joined": 448, "downBpsPerBot": 12219}, {"tS": 10.0, "joined": 498, "downBpsPerBot": 12268}, {"tS": 11.0, "joined": 548, "downBpsPerBot": 12182}, {"tS": 12.0, "joined": 598, "downBpsPerBot": 12083}, {"tS": 13.0, "joined": 648, "downBpsPerBot": 12295}, {"tS": 14.0, "joined": 700, "downBpsPerBot": 12201}, {"tS": 15.0, "joined": 748, "downBpsPerBot": 11909}, {"tS": 16.0, "joined": 798, "downBpsPerBot": 12058}, {"tS": 17.0, "joined": 848, "downBpsPerBot": 12176}, {"tS": 18.0, "joined": 900, "downBpsPerBot": 11926}, {"tS": 19.0, "joined": 948, "downBpsPerBot": 12019}, {"tS": 20.0, "joined": 999, "downBpsPerBot": 11890}, {"tS": 21.0, "joined": 1000, "downBpsPerBot": 11990}, {"tS": 22.0, "joined": 1000, "downBpsPerBot": 11731}, {"tS": 23.0, "joined": 1000, "downBpsPerBot": 11642}, {"tS": 24.0, "joined": 1000, "downBpsPerBot": 11475}, {"tS": 25.0, "joined": 1000, "downBpsPerBot": 11209}, {"tS": 26.0, "joined": 1000, "downBpsPerBot": 10883}, {"tS": 27.0, "joined": 1000, "downBpsPerBot": 10718}, {"tS": 28.0, "joined": 1000, "downBpsPerBot": 10446}, {"tS": 29.0, "joined": 1000, "downBpsPerBot": 10272}, {"tS": 30.0, "joined": 1000, "downBpsPerBot": 10086}, {"tS": 31.0, "joined": 1000, "downBpsPerBot": 10040}, {"tS": 32.0, "joined": 1000, "downBpsPerBot": 9891}, {"tS": 33.0, "joined": 1000, "downBpsPerBot": 9631}, {"tS": 34.0, "joined": 1000, "downBpsPerBot": 9577}, {"tS": 35.0, "joined": 1000, "downBpsPerBot": 9305}, {"tS": 36.0, "joined": 1000, "downBpsPerBot": 9211}, {"tS": 37.0, "joined": 1000, "downBpsPerBot": 9308}, {"tS": 38.0, "joined": 1000, "downBpsPerBot": 9065}, {"tS": 39.0, "joined": 1000, "downBpsPerBot": 8954}, {"tS": 40.0, "joined": 1000, "downBpsPerBot": 8942}, {"tS": 41.0, "joined": 1000, "downBpsPerBot": 8900}, {"tS": 42.0, "joined": 1000, "downBpsPerBot": 8742}, {"tS": 43.0, "joined": 1000, "downBpsPerBot": 8824}, {"tS": 44.0, "joined": 1000, "downBpsPerBot": 8671}, {"tS": 45.0, "joined": 1000, "downBpsPerBot": 8618}, {"tS": 46.0, "joined": 1000, "downBpsPerBot": 8578}, {"tS": 47.0, "joined": 1000, "downBpsPerBot": 8561}, {"tS": 48.0, "joined": 1000, "downBpsPerBot": 8446}, {"tS": 49.0, "joined": 1000, "downBpsPerBot": 8277}, {"tS": 50.0, "joined": 1000, "downBpsPerBot": 8192}, {"tS": 51.0, "joined": 1000, "downBpsPerBot": 8062}, {"tS": 52.0, "joined": 1000, "downBpsPerBot": 8100}, {"tS": 53.0, "joined": 1000, "downBpsPerBot": 7906}, {"tS": 54.0, "joined": 1000, "downBpsPerBot": 8062}, {"tS": 55.0, "joined": 1000, "downBpsPerBot": 7960}, {"tS": 56.0, "joined": 1000, "downBpsPerBot": 7830}, {"tS": 57.0, "joined": 1000, "downBpsPerBot": 7523}, {"tS": 58.0, "
…