138 lines
14 KiB
Markdown
138 lines
14 KiB
Markdown
# SotS1 battle-load slowdown — dynamic profile, session 2026-09-07 (time-boxed, combat NOT reached)
|
||
|
||
Status: **tactical combat was not reached** within the coordinator's time-box (see §1 for exactly why and how to
|
||
resume in one step). Everything below is what *was* measured on the live game (VM140, 16 vCPU, DXVK+lavapipe) plus
|
||
static facts pulled from the exe to rate hypotheses (a)/(b)/(c). Raw data and tooling sit next to this file.
|
||
|
||
## 0. TL;DR
|
||
|
||
| Question | Answer (evidence) |
|
||
|---|---|
|
||
| 16-core vs 1-core battle load time | **not measured** — no battle reachable (no starting fleet, nearest star out of range, 23 turns of 100 % random encounters produced none) |
|
||
| Main-thread state on the strategy map (16 cores) | 77–84 % **waiting** in DXVK `SleepConditionVariableSRW` (`Wait/WrAlertByThreadId`) under `DemoApp::OnRender` → renderer `sub_00720050`/`sub_0072b9e0` → `d3d9.dll`; 13 % running. This is lavapipe being the bottleneck, i.e. an artefact of the GPU-less VM |
|
||
| Main-thread state during End Turn | ~40 ms of real server work, then **0.85 s of `Sleep(computed ms)`** at `0x00838da9` (`sub_00838c60` ← `StrategyClient::Update+0xfc` ← `DemoApp::OnTick+0x139`) with the *whole process at 0 % CPU* (no render either). A deliberate delay, not contention |
|
||
| Audio thread (`StreamingUpdateThreadProc`, pri 15) | **inert**: 100 % `WaitForMultipleObjects` at `0x008ef226`, 0 ms CPU over 50 s — DirectSound failed to init on this VM (no audio device), so hypothesis (a) is *untestable here as-is* |
|
||
| Net watchdog / mesh worker | `Sleep(10)`+`EnterCriticalSection(g_netCS)` poll loop, 0 CPU; mesh worker (`BackgroundWorker::ThreadProc`, pri BELOW_NORMAL) `Sleep(10)` loop, woke ~80 ms after a turn |
|
||
| Timer resolution | **15.625 ms default** (`NtQueryTimerResolution` cur=156250), no `timeBeginPeriod` import → every `Sleep(≤15)` costs 15.6 ms |
|
||
| `Sleep(0)`/`Sleep(1)` spin-yield loops | **none exist**: the exe has only 10 `Sleep` call sites, args 10/20/100/1000/computed |
|
||
| Most suspicious primitive found | `0x0071ea60`: `TryEnterCriticalSection` → check done-flag → else **`Sleep(1000)`** poll (1 s granularity, and a *failed try-lock also costs 1 s*); used as a job-completion predicate by `StarMapBlobs::BuildBlobMesh_Job` (`push 0x71ea60` at `0x732cbc`/`0x732ce8` into job submit `0x8fc160`/`0x8fa5b0`). Strategy-map path; whether the combat loader uses the same Mars job/wait helpers is the next Ghidra question |
|
||
|
||
## 1. What blocked reaching combat, and the one-step resume
|
||
|
||
Chronology (all UI driven through `C:\SOTS\ui\click_helper.ps1` / task `SOTSUI`; screenshots via `qm screendump`):
|
||
|
||
1. Custom game (Morrigi, 28 stars, 2 players, random encounters 100 %) starts with **no ships at all** (system view:
|
||
`DE 00 CR 00 DN 00`, fleet panel empty). Built 5× `DE Armor` (Build screen, ETA 2 turns; treasury is huge).
|
||
2. Turn 4: "Alpha Fleet" exists. **Move** to the two nearest stars fails: *"Alpha Fleet does not have the range to reach
|
||
Junction/Markab using nodes. Do you want to plot a sublight course?"* — fleet range 9.0 ly, sublight ETA to Markab
|
||
**85 turns** (0.2 ly/turn ⇒ ~17 ly). The map's 7 ly "distance" setting evidently is not the nearest-neighbour distance.
|
||
Order cancelled by re-targeting the fleet to Gamma Cephei (`Ctrl+S`/Special had no Stop entry pre-departure).
|
||
3. Fallback: let encounters come to the homeworld. Automated **23 End Turns (turn 4 → 27)** with screen-change detection
|
||
(`tools/turnloop.sh`, ~20 s per turn incl. helper latency). **No encounter query ever appeared**; the fleet now has 6 DE.
|
||
4. Coordinator time-box hit → stopped, game left running on **turn 27**, strategy map, Alpha Fleet (6× DE Armor) at Gamma Cephei.
|
||
Autosaves: `C:\SOTS\SavedGames\(Autosave).sav` = turn-27 state (`(Autosave EndTurn).sav` = pre-turn).
|
||
|
||
**Resume in one step** (pick one):
|
||
- *Range fix (same game)*: Build screen → queue 2× `Tanker` + 3× `Extended Range` → End Turn ×2 → `F` (Fleet Manager) to merge
|
||
into one fleet → Move → Junction (was the dashed-line neighbour, ~(523,327) at the zoom of `screens/zoomout.png`) or
|
||
Markab (650,287). If the range dialog still appears, research a drive tech first. Then End Turn until arrival (encounter odds 100 % at unexplored systems).
|
||
- *Scenario (fresh game)*: main-menu → Scenario (strings-and-config F10 list: Tourney Space / Land Grab (S) / Upstart Apes start with contact) — untested.
|
||
- **Before either, add an audio device to the VM** so hypothesis (a) becomes testable: `qm set 140 -audio0 device=ich9-intel-hda,driver=none`
|
||
(needs a full stop/start; Win10 has an inbox HDA driver; then `session.log` must no longer say "Failed to initialize DirectSound manager").
|
||
- Then run `tools/battle-run.sh <tag> <affinity|0> <FightX> <FightY>` when the encounter query (C1 screen) is up: it starts the
|
||
32-bit stack sampler + a 1 Hz screendump burst, clicks Fight, and produces `samp_<tag>.txt` + `framediff.txt` for wall-clock
|
||
load time. Affinity A/B on the live process: `(Get-Process 'Sword of the Stars').ProcessorAffinity = 1` (same effect as
|
||
`Process_PinAffinity` 0x0089ee70 → `SetProcessAffinityMask`). Caveat: on this VM the renderer is CPU (lavapipe), so a
|
||
1-core pin will also throttle rendering — compare main-thread *wait sites*, not just wall clock, or use `ProcessorAffinity = 3`/`15` as intermediate points.
|
||
|
||
Note on `ForceSingleCore`: `C:\SOTS\sots.ini` currently only holds `[Locale] CurrentProfile=…`; the key is read via the Win32
|
||
profile API (section not confirmed — community says `[CPU]`). The live-affinity flip above sidesteps that.
|
||
|
||
## 2. Environment / tooling (all in `tools/`)
|
||
|
||
- Process `Sword of the Stars.exe` pid 7892, **52 threads**, affinity mask 0xFFFF. Exe is **ASLR-relocated to base `0x00e80000`**
|
||
(`d3dx9_31.dll` grabbed 0x400000): runtime = Ghidra + 0xA80000. All addresses below are Ghidra (0x400000-based).
|
||
- `sampler.ps1` (run under `SysWOW64\powershell.exe`): 32-bit stack sampler — enumerates threads (`Win32StartAddress`), resolves
|
||
exports, samples EIP/EBP-chain (+ stack scan) every 20 ms for threads whose start address is in the exe, records
|
||
`NtQuerySystemInformation` thread state/wait-reason per sample, and per-thread CPU (GetThreadTimes) per 500 ms bucket.
|
||
`parse.py` (+`funcs.txt` from `funcs.py` prologue/call-target scan of the exe, 31 850 starts; `names.txt` from the findings)
|
||
turns that into timelines and histograms. No ETW was needed; `wpr.exe` and `tracerpt.exe` exist on the VM if wanted.
|
||
- `timerres.ps1`: `NtQueryTimerResolution` + `powercfg /energy`.
|
||
|
||
Thread inventory (start address → role):
|
||
|
||
| tid | start | role | pri | notes |
|
||
|---|---|---|---|---|
|
||
| 3568 | exe `0x00925794` (CRT) | **main** (sim, UI, render, server) | 0 | see §3 |
|
||
| 4004 | exe `0x008ef1d0` `SoundSystem::StreamingUpdateThreadProc` | audio streaming | **15 (TIME_CRITICAL)** | parked in `WaitForMultipleObjects` @`0x8ef226`; loop also has `Sleep(100)` @`0x8ef231` |
|
||
| 2192 | exe `0x00901f40` `NetworkManager::WatchdogThreadProc` | net watchdog | 0 | `Sleep(10)` @`0x901f72` then `EnterCriticalSection(g_netCS 0xb2e5f8)` @`0x901f7f`, forever |
|
||
| 2320 | exe `0x00735bb0` `BackgroundWorker::ThreadProc` | star-map mesh worker | **-1 (BELOW_NORMAL)** | `Sleep(10)` @`0x735bc0` + `EnterCriticalSection` @`0x735bcb` loop |
|
||
| 1124 + 16× | `vulkan_lvp.dll+0x1b2b71e` | lavapipe (CPU Vulkan) workers | 0 | 1124 is the busiest thread in the process (12:52 CPU at attach); 17 lvp threads had ~5:30 each |
|
||
| 1376, 5348, 7852, 6436 + 8× pri -2 | `d3d9.dll+0x290e60` (DXVK 3.1) | DXVK CS/present/shader-compiler threads | 0 / -2 | |
|
||
| 5508 | `ucrtbase` | CRT | | |
|
||
| 5216, 5132 | `ntdll!TpCallbackIndependent` | thread pool | | |
|
||
|
||
## 3. Measurements
|
||
|
||
### 3.1 Idle strategy map, 16 cores (`samp_idle.txt`, 5 s, 50 ms)
|
||
- CPU per 5 s: lavapipe 20.7 s (≈4 cores), main 0.47 s (9 %), DXVK 0.46 s, everything else 0.
|
||
- Main thread: `Wait/WrAlertByThreadId` 84 %, `Running` 16 %. Top wait: `ntdll!NtWaitForAlertByThreadId` ← `KERNELBASE!SleepConditionVariableSRW`
|
||
← `d3d9.dll` (DXVK) ← `sub_00720050@0x720267` (renderer flush/present) ← … ← `DemoApp::OnRender@0x899266` ← `sub_0090ea20` ← `Application::Run`.
|
||
|
||
### 3.2 End Turn, 16 cores (`samp_endturn1.txt`, 45 s, 20 ms, 1440 samples/thread; End Turn clicked ≈ t+12 s)
|
||
- CPU per 45 s: lavapipe 293 s (6.5 cores), main 6.3 s (14 %), DXVK 3.0 s, mesh 0.08 s, audio 0, net 0.
|
||
- Main thread over the run: `Wait/WrAlertByThreadId` 76 % (DXVK, as above), `Running` 19 %, `Wait/DelayExecution` 4 %.
|
||
Wait sites: 67 % DXVK ← `sub_00720050@0x720267`; 4.9 % DXVK ← `sub_0072b9e0@0x72bc4c`; 4.6 % DXVK ← `sub_008df3a0@0x8df3e0`;
|
||
2.5 % `Sleep(20)` ← `Application::Run@0x89f5fc` (the `ShouldSleepWhenInactive` path: `push 0x14; call Sleep` @`0x89f5f4`); 1.9 % `Sleep` ← `sub_00838c60@0x838daf`.
|
||
- **Turn-processing window t = 11.9–13.3 s** (`endturn1.window.parsed.txt`): only **1 of 45 samples** is inside server/client turn code
|
||
(`StrategyServer`/`ProcessTurn` frames → real work ≲ 40 ms for a 28-star, 2-player map); **60 % `Wait/DelayExecution`** = 27 consecutive
|
||
samples (t = 12.00–12.83 s) in `Sleep` called from `0x00838da9` (`sub_00838c60`, arg = `(int)(double × ds:0x9e22f8)`, i.e. a computed
|
||
remaining-time in ms) ← `StrategyClient::Update@0x7843ac` ← `DemoApp::OnTick@0x89a779`. During that window the CPU bucket at 12.6 s
|
||
is **0 ms for every thread** (no rendering either) — a fixed end-turn delay (`EndTurnDelay`, cf. `0x0076ab90`), not a contention wait.
|
||
Mesh worker ran 47+31 ms right after (star-map rebuild). Wall clock per End Turn incl. UI-helper latency ≈ 20 s; game-side ≈ 1 s.
|
||
|
||
### 3.3 Timer resolution / sleep granularity (hypothesis (c) inputs)
|
||
- `NtQueryTimerResolution`: min 156250, max 5000, **current 156250 (15.625 ms)**; `powercfg /energy` shows no outstanding timer request.
|
||
The exe imports `Sleep` and `SetProcessAffinityMask` but **not** `timeBeginPeriod`, `SwitchToThread`, `SetThreadAffinityMask`.
|
||
- All 10 `Sleep` call sites in the exe (`objdump`, IAT slot `0x9dd048`):
|
||
|
||
| site | arg | function |
|
||
|---|---|---|
|
||
| `0x00735bc0` | 10 | `BackgroundWorker::ThreadProc` loop |
|
||
| `0x00901f72`, `0x00901820` | 10 | `NetworkManager::WatchdogThreadProc` loop / sibling |
|
||
| `0x0071eb26` | 10 | thread join helper `0x71eac0` (see below) |
|
||
| `0x0089f5f4` | 20 | `Application::Run` when inactive |
|
||
| `0x008ef231` | 100 | `SoundSystem::StreamingUpdateThreadProc` loop |
|
||
| `0x0071eaa2` | **1000** | wait-for-job helper `0x71ea60` |
|
||
| `0x0092555c` | 1000 | CRT/startup area |
|
||
| `0x00838da9` | computed | end-turn delay (`sub_00838c60`) |
|
||
| `0x0040a766` | computed (eax) | early low-address engine code, not yet identified |
|
||
|
||
⇒ there is **no `Sleep(0)`/`Sleep(1)` yield-spin anywhere**, so the "spin loop starves on many cores" variant of (c) is out.
|
||
- Helpers (static, from the exe):
|
||
- `0x0071ea60(obj)`: `loop { if (TryEnterCriticalSection(obj)) { done=[obj+0x5a]; failed=[obj+0x58]; LeaveCriticalSection } ; if (!done && !failed) { Sleep(1000); continue } ; return done }`.
|
||
Poll granularity **1 s**, and a *failed try-lock* (worker holding the CS on another core at that instant) also costs a full second.
|
||
Referenced only by `StarMapBlobs::BuildBlobMesh_Job` (`push 0x71ea60` at `0x732cbc` and `0x732ce8`, alongside callback `0x722010`, into `0x8fc160` / `0x8fa5b0`).
|
||
- `0x0071eac0(this)`: `EnterCriticalSection; [+0x5b]=1 (stop), [+0x58]=1 if [+0x54]; Leave; while (GetExitCodeThread == STILL_ACTIVE) { TryEnter/check [+0x5c]/Leave; Sleep(10) }; CloseHandle` — thread stop/join, called from `0x00735794` (BackgroundWorker teardown).
|
||
|
||
## 4. Hypotheses — verdict on current evidence
|
||
|
||
- **(a) audio-thread critical-section contention (`g_musicCS`)** — *Untested; cannot be tested on this VM until an audio device is added.*
|
||
Dynamic: the TIME_CRITICAL thread never left `WaitForMultipleObjects` (0 CPU) because DirectSound never initialised. Static: its loop is event-wait +
|
||
`Sleep(100)`, so even when alive it wakes ≤10×/s plus buffer events; contention would need the main thread to take `g_musicCS` inside the load
|
||
path (`MusicPlayer::OpenMusicFile 0x8ef040`, `StreamingSound::FillBuffer 0x91b5a0`). Plausible mechanism (a TIME_CRITICAL waiter on a CS the
|
||
loader holds for long stretches → priority-inversion-style stalls), no evidence either way yet.
|
||
- **(b) D3D9 runtime/driver worker threads** — *No evidence; not reproducible here.* On this VM the "driver" is DXVK+lavapipe (29 threads) and the
|
||
main thread's dominant wait is DXVK's present path — an artefact. Nothing about Microsoft's d3d9 runtime threads can be inferred from it.
|
||
- **(c) `Sleep(0)`/spin loops, timer resolution** — *Partially refuted, partially supported.* Refuted: no yield-spins exist. Supported: the timer stays
|
||
at 15.6 ms (all the `Sleep(10)` loops are really 15.6 ms), and the engine's job-completion wait `0x71ea60` polls with **`Sleep(1000)`** and treats a
|
||
lost `TryEnterCriticalSection` race as "not done" — a pattern that is benign on one core (the worker cannot hold the CS while the poller runs) and
|
||
costs whole seconds per collision on many cores. It is wired to the star-map blob mesh job here; the open question — one Ghidra query — is whether
|
||
the combat loader (`CombatLoaderPainter`/`CombatLobbyClient`, C2 in the UI map) submits work through the same `0x8fc160`/`0x8fa5b0` job API with
|
||
`0x71ea60`-style waiters, or takes `g_netCS` while the watchdog polls it every 15.6 ms. That, plus (a) with audio enabled, is what the next dynamic run should discriminate.
|
||
|
||
## 5. Files alongside this report (`Z:\profiling\` = `/bulk-storage/re-lab/profiling/`)
|
||
|
||
- `samp_idle.txt`, `samp_endturn1.txt` — raw sampler output (modules, threads, per-sample stacks, per-500 ms CPU); `*.parsed.txt` — digested.
|
||
- `tools/` — `sampler.ps1`, `parse.py`, `funcs.py`, `funcs.txt`, `names.txt`, `iat.py`, `timerres.ps1`, `ui.sh`, `turnloop.sh`, `battle-run.sh`, `shots.sh`, `inspect.ps1`.
|
||
- `screens/` — build screen, fleet/move attempts (range dialog), End Turn, final turn-27 state; `turns/` — one screenshot per automated End Turn + `log.txt`.
|