alex/sots-re
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions
sots-re/findings/subsystems/battle-load-profile.md

14 KiB
Raw Blame History

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.