diff --git a/context/open-questions.md b/context/open-questions.md index 666d59f..f3606ca 100644 --- a/context/open-questions.md +++ b/context/open-questions.md @@ -1034,17 +1034,32 @@ contributions already: see — an authored record that resolves with no distinct behaviour to reconstruct. Mike L. could confirm. (Gitea #104.) -**AUDIO SOURCE POOLING IS NOT FIXED — retention, not churn, is the wall** [T2]. -The `#32` pooling change removed the per-sound `alGenSources`/`alDeleteSources` -churn (a real ~10% frame-time win) but every 693 field log still shows - `ACQUIRE FAILED (requested=4 live=240 pooled=240 free=0 ...)` -19,182 fails (Sauron) / 15,333 (Rajel) / 6,818 (Ronin), high-water **225 of 240**, -starting ~1% into the session. `free=0` is the diagnosis: the pool fills and never -returns a source. Each audio component reserves a SourceSet of up to 25 voices and -holds it to entity teardown, so peak demand scales with live audio COMPONENTS, not -audible sounds. A bigger cap only delays the wall. ⚠ Players reported audio as -"working fine" the same night — subjective impressions do not clear this class of -bug; read the log. +**AUDIO #32, CORRECTED DIAGNOSIS (2026-08-02): saturation during combat, NOT +retention** [T2 — census-measured]. An earlier version of this entry claimed the +pool "fills and never returns a source"; that was read off the FAILURE line, where +`free=0` is true by definition (a third instance of the counter-sampling trap). +The 30-second census in the same logs disproves it: `free` returns to ~227-230 +between bursts and `reuses` climbs ~20/s all session — the pool cycles fine, and +release-on-stop exists and works (the engine's steal loop: +AudioSourceStop/SuspendMaintenance -> ReleaseChannels -> ReleaseSourceSet). + * The real regime: during firefights CONCURRENT demand exceeds the 240 cap and + the priority steal loop services each new sound by killing an old one, + thousands of times per combat session. Idle standing demand is only ~13. + * The raw `ACQUIRE FAILED` line count (6.8k-19k/log) is NOISE — the steal loop + retries after every failed attempt, so lines pile up per event and most + events still play via a steal. It is now rate-limited (1/30s) and the census + carries the true metrics: `steals=` and `drops=` (drops = the steal loop ran + dry and the sound NEVER played), plus a per-class drop histogram. + * The saturating requester is class 1005 = **Static3DPatchSource, 4 voices** — + world-placed effect sounds, i.e. EXPLOSIONS/impacts. Demand tracks the + number of SHOOTERS (9-mech one-shooter bench peaks at 130 with 0 fails; a + 6-shooter field lobby pins 240). **#84's double detonation doubles exactly + this class on observer nodes** — fix #84 first, then re-read the field + census before touching the audio budget. + * `BT_AUDIO_SOURCES=` now raises the POOL cap too, not just the AL context + budget (it previously did only the latter, making the experiment + impossible). If post-#84 logs still saturate, that is the field experiment + — with frame time measured, since more concurrent voices = more mixing CPU. **Reading the missile impact line.** `[projectile] IMPACT damage=X ... burst=N` prints X = **per missile**; the delivered total is `X * N`. A tester reading X diff --git a/engine/MUNGA_L4/L4AUDRND.cpp b/engine/MUNGA_L4/L4AUDRND.cpp index 4537c29..4396efc 100644 --- a/engine/MUNGA_L4/L4AUDRND.cpp +++ b/engine/MUNGA_L4/L4AUDRND.cpp @@ -1265,6 +1265,13 @@ Logical source_result = audio_source->GetAudioChannelSet(); Check(source_result); + // #32 census: identify the requester while RequestAudioChannels runs, so a + // failure can be attributed to a component CLASS without threading an + // argument through the virtual (audio is main-thread only). + extern int gBTAudioReqClass, gBTAudioReqVoices; + gBTAudioReqClass = (int)audio_source->GetClassID(); + gBTAudioReqVoices = audio_source->GetAudioVoiceCount(); + resources_available = RequestAudioChannels( audio_source->GetAudioVoiceCount(), @@ -1352,6 +1359,11 @@ Logical // Else suspend the source //-------------------------------------------------------------------- // + { // #32 census: a steal ends a RUNNING sound early -- count it + // ungated so field logs show how hard the mixer is fighting. + extern long gBTAudioSteals; + ++gBTAudioSteals; + } if ( running_audio_source->GetAudioRenderType() == TransientAudioRenderType @@ -1382,6 +1394,19 @@ Logical iterator.Last(); running_audio_source = iterator.GetCurrent(); } + + // #32 census: the steal loop is done and the request is STILL + // unsatisfied -- this sound is genuinely dropped. (The raw + // "ACQUIRE FAILED" print fires once per attempt INSIDE the steal loop, + // so its count wildly overstates real drops; this one does not.) + if (!resources_available) + { + extern long gBTAudioTrueDrops; + extern void BTAudioDropTally(int class_ID, int voices); + ++gBTAudioTrueDrops; + BTAudioDropTally((int)audio_source->GetClassID(), + audio_source->GetAudioVoiceCount()); + } } return resources_available; } @@ -1425,12 +1450,17 @@ Logical if (now_ms - s_censusAt > 30000) { s_censusAt = now_ms; + extern long gBTAudioSteals, gBTAudioTrueDrops; DEBUG_STREAM << "[audio] source census: live=" << gBTAudioSourcesLive << " pooled=" << BTAudioPoolSize() << " free=" << BTAudioPoolFree() << " reuses=" << BTAudioPoolReuses() << " acquireFails=" << gBTAudioAcquireFails + << " steals=" << gBTAudioSteals + << " drops=" << gBTAudioTrueDrops << std::endl << std::flush; + extern void BTAudioDropCensus(); + BTAudioDropCensus(); } } @@ -1466,13 +1496,27 @@ Logical if (!BTAudioPoolAcquire(&src)) { ++gBTAudioAcquireFails; - DEBUG_STREAM << "[audio] ACQUIRE FAILED (requested=" << requested - << " live=" << gBTAudioSourcesLive - << " pooled=" << BTAudioPoolSize() - << " free=" << BTAudioPoolFree() - << " fails=" << gBTAudioAcquireFails - << ") -- the pool is exhausted; expect dropouts" - << std::endl << std::flush; + // Rate-limited: the night-9 field logs carried 6.8k-19k of these per + // player, and the count is NOISE -- the steal loop retries after every + // failed attempt, so lines pile up per EVENT, and most events still + // end in a successful steal. One line per 30s band keeps the signal + // (the census carries the real counters: steals + true drops). + extern int gBTAudioReqClass, gBTAudioReqVoices; + static unsigned long s_failNoteAt = 0; + unsigned long fail_now = GetTickCount(); + if (fail_now - s_failNoteAt > 30000) + { + s_failNoteAt = fail_now; + DEBUG_STREAM << "[audio] ACQUIRE FAILED (requested=" << requested + << " reqClass=" << gBTAudioReqClass + << " reqVoices=" << gBTAudioReqVoices + << " live=" << gBTAudioSourcesLive + << " pooled=" << BTAudioPoolSize() + << " free=" << BTAudioPoolFree() + << " fails=" << gBTAudioAcquireFails + << ") -- saturated this instant; the steal loop decides what plays" + << std::endl << std::flush; + } return False; } source_request->sources[i] = src; @@ -1557,6 +1601,62 @@ Logical long gBTAudioSourcesLive = 0; long gBTAudioAcquireFails = 0; +// +// #32 census v2. The night-9 field logs proved the FIRST generation of these +// counters mislead under pressure: "ACQUIRE FAILED ... free=0" reads as +// permanent retention, but free is 0 at the instant of any failed acquire BY +// DEFINITION -- the 30s census showed free back at ~230 between bursts, i.e. +// the pool cycles and the mixer is simply saturated DURING combat. (Same +// counter-sampling trap as the original live=256-vs-live=6, second offence.) +// These count what actually matters: +// gBTAudioSteals -- a running sound was ended early to service a new one +// gBTAudioTrueDrops -- the steal loop ran dry and the sound NEVER PLAYED +// plus a per-component-class tally of the dropped, so the next field log names +// the class that saturates the mixer instead of leaving it to inference. +// +int gBTAudioReqClass = -1; +int gBTAudioReqVoices = 0; +long gBTAudioSteals = 0; +long gBTAudioTrueDrops = 0; + +struct BTAudioDropBin { int classID; int voices; long count; }; +static BTAudioDropBin gBTAudioDropBins[12]; +static int gBTAudioDropBinCount = 0; + +void BTAudioDropTally(int class_ID, int voices) +{ + for (int i = 0; i < gBTAudioDropBinCount; ++i) + { + if (gBTAudioDropBins[i].classID == class_ID + && gBTAudioDropBins[i].voices == voices) + { + ++gBTAudioDropBins[i].count; + return; + } + } + if (gBTAudioDropBinCount < 12) + { + gBTAudioDropBins[gBTAudioDropBinCount].classID = class_ID; + gBTAudioDropBins[gBTAudioDropBinCount].voices = voices; + gBTAudioDropBins[gBTAudioDropBinCount].count = 1; + ++gBTAudioDropBinCount; + } +} + +// One line under the 30s census, only when something was dropped since boot: +// which component classes lost sounds, and how many. +void BTAudioDropCensus() +{ + if (gBTAudioDropBinCount == 0) + return; + DEBUG_STREAM << "[audio] dropped by class:"; + for (int i = 0; i < gBTAudioDropBinCount; ++i) + DEBUG_STREAM << " {class " << gBTAudioDropBins[i].classID + << " x" << gBTAudioDropBins[i].voices + << "v: " << gBTAudioDropBins[i].count << "}"; + DEBUG_STREAM << std::endl << std::flush; +} + //############################################################################# // OpenAL SOURCE POOL (gitea #32) //############################################################################# @@ -1580,7 +1680,34 @@ long gBTAudioAcquireFails = 0; // Not locked: the audio renderer runs on the main thread (only the network RX // socket has its own). If that ever changes, this needs a mutex. // -static const int kAudioPoolCap = 240; // just under OpenAL Soft's 256 default +// The pool's ceiling. DEFAULT: just under OpenAL Soft's 256-source context +// default. BT_AUDIO_SOURCES= raises the AL context budget at Initialize +// (above); the pool cap now FOLLOWS it -- before this, the env raised the +// context and the pool still stopped at 240, so the experiment was impossible +// to run in the field. kAudioPoolMax bounds the static free-list array. +static const int kAudioPoolMax = 1024; +static int kAudioPoolCap = 240; +static int BTAudioPoolCapResolve() +{ + static int s_done = 0; + if (!s_done) + { + s_done = 1; + const char *sv = getenv("BT_AUDIO_SOURCES"); + if (sv != 0) + { + int n = atoi(sv); + if (n >= 64 && n <= 4096) + { + // stay under the context grant with a small reserve + kAudioPoolCap = (n - 16 < kAudioPoolMax) ? (n - 16) : kAudioPoolMax; + DEBUG_STREAM << "[audio] source pool cap follows BT_AUDIO_SOURCES: " + << kAudioPoolCap << std::endl << std::flush; + } + } + } + return kAudioPoolCap; +} // // PEAK DEMAND is set by how many audio COMPONENTS are alive, not by how many // sounds are audible: each component reserves a SourceSet of up to @@ -1592,7 +1719,7 @@ static const int kAudioPoolCap = 240; // just under OpenAL Soft's 256 default // sources than the cap -- alGenSources failing simply ends growth and the pool // recycles what it has. -static ALuint gAudioPoolFree[kAudioPoolCap]; +static ALuint gAudioPoolFree[kAudioPoolMax]; static int gAudioPoolFreeCount = 0; // entries in gAudioPoolFree static int gAudioPoolTotal = 0; // sources ever generated (<= cap) static long gAudioPoolReuses = 0; // diagnostics @@ -1643,7 +1770,7 @@ Logical --gAudioPoolTotal; // stale name: forget it } - if (gAudioPoolTotal >= kAudioPoolCap) + if (gAudioPoolTotal >= BTAudioPoolCapResolve()) return False; ALuint src = 0; @@ -1678,12 +1805,12 @@ void if (!alIsSource(src)) return; BTAudioScrubSource(src); - if (gAudioPoolFreeCount < kAudioPoolCap) + if (gAudioPoolFreeCount < kAudioPoolMax) { gAudioPoolFree[gAudioPoolFreeCount++] = src; return; } - alDeleteSources(1, &src); // cannot happen (cap == array size) + alDeleteSources(1, &src); // cannot happen (max == array size) --gAudioPoolTotal; --gBTAudioSourcesLive; } diff --git a/scratchpad/night9/audioburst.sh b/scratchpad/night9/audioburst.sh new file mode 100644 index 0000000..4a01ba9 --- /dev/null +++ b/scratchpad/night9/audioburst.sh @@ -0,0 +1,31 @@ +#!/usr/bin/env bash +# #32 v2: reproduce the FIELD regime -- mixer saturated during combat -- and +# name the class that saturates it. 9 mech entities (player + 8 dummies), +# missile autofire for maximum explosion density. +# $1 tag for the log +# $2 optional BT_AUDIO_SOURCES override (empty = default 240 cap) +set -x +. /c/git/bt411/scratchpad/night6/bench_common.sh +cd /c/git/bt411/content || exit 1 +taskkill //F //IM btl4.exe > /dev/null 2>&1 +sleep 2 +sed "s/^map=.*/map=grass/; s/^time=.*/time=day/" MP.EGG > AUD.EGG +TAG="${1:-cap240}" +LOG=audioburst_$TAG.log +rm -f "$LOG" +export BT_SPAWN_ENEMY=8 +export BT_AUTOFIRE=1 BT_AF_MISSILE=1 BT_AF_PERIOD=1 +export BT_GOTO=enemy BT_GOTO_STOP=60 +[ -n "$2" ] && export BT_AUDIO_SOURCES="$2" || unset BT_AUDIO_SOURCES +bt_launch "$LOG" AUD.EGG 0x03 +sleep 150 +taskkill //F //IM btl4.exe > /dev/null 2>&1 +sleep 2 +echo "=== census tail ===" +grep -oE "\[audio\] source census[^\n]*" "$LOG" | tail -4 +echo "=== drop census ===" +grep -oE "\[audio\] dropped by class[^\n]*" "$LOG" | tail -2 +echo "=== failure notes ===" +grep -cE "ACQUIRE FAILED" "$LOG" +echo "=== frame time ===" +grep -oE "\[rstat\][^\n]*avg=[0-9.]+ms" "$LOG" | tail -3