EscapistsReintroduced/docs/hq-performance-measurements.md

# Runtime HQ measurements

The mod records read-only server telemetry by default. Publish this source and
run a normal multiplayer session. No AMP integration or external service is
required. Add `-errNoPerf` to the game server startup arguments to disable all
collection (useful for measuring instrumentation overhead).

Measurements go to **`rereintroduced-performance.log`** in the server's current
engine log directory (`$logs:`, alongside `console.log`). Both `ERR PERF START`
and the measurement rows are written only to this separate file. Mission restarts
append new run IDs; a new engine log directory gets its own performance file.
The file is closed after each write batch. If it cannot be opened, a single error
per mission is reported in the main log and opening is retried after 60 seconds;
measurements never fall back to the console. Pending statistics are retained across
open failures, but are lost if the final shutdown write also fails.

Each window is
60 seconds of real elapsed time, with up to 26 aggregate rows. Clean mission
shutdown also writes a partial final window. Crashes can lose the unfinished
window. Every row includes a run ID, window ID, elapsed time and start/end mission
phase. Windows may span phase transitions or changes in player/AI population.

```sh
python3 tools/parse_hq_performance.py /path/to/rereintroduced-performance.log
python3 tools/parse_hq_performance.py /path/to/rereintroduced-performance.log --csv > /tmp/hq-performance.csv
```

Identical repeated rows are deduplicated; conflicting duplicates and malformed
rows are errors. CSV retains individual windows and the `over50` / `over100`
threshold counts. The text summary combines only windows where the metric was
observed; compare matching windows in CSV for attribution rather than comparing
different stages of a mission.
Older console logs remain compatible with the parser.

## What is measured

| Metric | Meaning |
|---|---|
| `mission_tick_ms` | Whole scheduled mission tick, including early returns and terminal transitions |
| `maintenance_ms` | Command maintenance, including continuing aircraft |
| `civilians_ms` | Civilian traffic tick |
| `forces_ms` | Force-ledger snapshot and virtual-force update |
| `observers_ms` | Connected player observer/camera updates |
| `hq_tick_ms` | Whole tactical HQ tick, including all HQ scopes below |
| `listeners_ms` | Mission tick event listeners |
| `hq_prep_ms` | Belief memory, equipment and special-skill maintenance |
| `hq_hunters_ms` | Hunter fleet management |
| `hq_garrisons_ms` | Objective defence and town/object worker scheduling (before the slicing fix this also included all town/object work) |
| `garrison_work_ms` | Independent background town/object discovery, placement or creation slice; outside the mission/HQ tick |
| `performance_flush_ms` | Duration of the preceding successful non-final telemetry write batch, recorded in the following window |
| `hq_convoys_ms` | Mounted intercept, convoy management and automatic dispatch |
| `hq_bodies_ms` | Body investigation/recovery budgeting |
| `hq_radio_index_ms` | Five-second radio/inventory indexing pass, only when run |
| `hq_reports_ms` | Contact expiry, local combat updates, radio delivery and report collection |
| `hq_planner_ms` | Five-second convoy, supply, mounted-intercept and squad assignment planning pass, only when run |
| `hq_support_ms` | Mines, resupply, logistics, mortars, assault, airfield and recovery ticks |
| `hq_journal_ms` | HQ journal flushing |
| `update_interval_ms` | Wall-clock gaps between game OnUpdate callbacks |
| `engine_sim_sample_ms` | Engine-reported total simulation time sampled approximately once per second |
| `engine_frame_sample_ms`, `engine_fps_sample` | Engine-reported frame time/FPS sampled at the same cadence |
| `active_ai_sample`, `players_sample` | Native active AI and connected player counts, approximately once per second |
| `hq_groups_sample` | Registered HQ unit records, once per HQ tick; not a soldier count |

Durations use `System.GetTickCount()` with **1 ms resolution**. Rows contain count,
sum, minimum, maximum, zero-valued count and counts above 50/100 in that metric's
units. Threshold counts are intended for duration metrics, especially update
intervals. A zero duration means below the available clock resolution; it is not
proof that an operation is free. Averages can show fractions of milliseconds
because they aggregate many quantized samples. This is elapsed wall time, not
process CPU time, and synchronous native calls inside a scope contribute to it.

`mission_tick_ms` contains `hq_tick_ms`, which contains `hq_planner_ms` and the
other HQ scopes. `garrison_work_ms` is separate background work, not a child of
those ticks. The last telemetry flush cannot report its own duration if no later
window is written. **Do not sum parents and children.** Uninstrumented mission work
and collection overhead also contribute to parent scopes. The profiler uses
fixed-size accumulators, does no entity/inventory scanning, and makes no network
requests. It adds one clock read per server OnUpdate and boundary reads around
the slow scheduled scopes; reporting itself also costs time.

`update_interval_ms` includes scheduling, deliberate FPS caps and stalls; it is
not engine CPU cost. ProfileData averaging/window semantics are engine-defined;
these are sampled engine values, not raw per-frame timings or percentiles.
`SimulationTimeMs` is **not AI-only time**. Do not subtract script timings from it
to claim a native-AI cost: sampling, timing domains and asynchronous work differ.
The public API has not established an AI-only timer. Combat, pathfinding and
physics performed outside these script calls are not attributed to HQ scopes.

## Using the result for external planning

Collect comparable windows with players present, including prison, hunting and
combat. Check `hq_planner_ms` sum divided by the window's elapsed seconds:
this gives planner wall milliseconds per real second. Compare its peaks with the
whole HQ/mission tick, engine simulation samples and update stalls. Correlation
with active AI is useful evidence, not proof of causation.

If planning is consistently tiny while frame stalls grow with AI population,
moving the existing planner externally is unlikely to provide much relief. If
planning spikes are substantial, an external planner may deserve a controlled
comparison. Even then it cannot remove all measured planner work: current
planning includes local world checks and applying orders. Serialization,
validation and service latency would add costs. No speedup estimate is emitted.

Collection runs only for the current server-owned Escape game mode, including
idle/preparation periods so those can be identified. It resets on a new mode,
closes on StopServices and remains disabled on clients. There are no changes to
AI decisions, frequencies, simulation settings or ownership.

Implementation was reviewed without launching the game or automated tests, per
the user's request. Native compilation and live telemetry remain to be verified
after publication.


## Memory investigation, 11 October 2026

`ERR MEMORY` rows now share `rereintroduced-performance.log`. They record native
`System.MemoryAllocationKB()` at mode construction, once per minute, on mode
stop and when world cleanup is requested. These are engine allocation estimates,
not OS RSS. Cleanup-requested is **before** engine teardown; compare with the
next mode-created reading rather than interpreting it as memory after cleanup.
Rows include UTC Unix time, phase, players, active AI and live mission-owned root
entities. Root entities are not a world-wide entity count (children/inventory are
excluded). Collection does not query or stream terrain or walk inventories.
`-errNoPerf` disables these rows too.

For Linux RSS, use `tools/sample_server_memory.py --output /tmp/escape-memory.jsonl`
on the host. It samples all Reforger processes once per minute for 24 hours,
including PID/start identity, RSS/anonymous/file memory, available host RAM,
container limits, cache usage and OOM counters. It performs no game calls or
server changes. Output rotates at 2 MiB with one previous file. Container
`memory.current` includes file cache and must not be treated as process RSS.

RKS2 evidence: the kernel killed PID 251447 on 10 October at 15:00 UTC with
15,439,164 KiB anonymous RSS, following several scenario reloads. On 11 October
at 09:40 UTC the fresh PID 305274 had 7,520,580 KiB RSS. A second Reforger PID
246717 used 2,996,396 KiB. The host has 19,526 MiB total RAM and no swap; the
containers reported `memory.max=max`, not a private 19 GiB reservation for RKS2.
These snapshots confirm host memory pressure, **not** its precise allocation
source or a proven leak in a particular mission subsystem.

Implemented mitigations: defer distant background population until the first
connection (the prison admission scene is still built), then let admitted native
preparation finish even if players disconnect; suppress new/replacement recon
planes when no players are connected; release unfinished garrison resource
handles on stop and catalog bookkeeping at shutdown/world cleanup. Equipment
probabilities and native catalog initialization are unchanged. Native Arsenal
InitData already loads/pins resources before the lottery reads GetItemResource;
removing that getter from the lottery would not prove any memory saving.

A read-only host sampler was started on 11 October for 24 hours, writing
`/tmp/escape-memory-20261011.jsonl`. The mission changes still need publication.
Native 1.8 Workbench compilation passed; a comparable multi-round live memory
soak is required before claiming the recurring OOM is resolved.