From 90515a68b164e46b77f5465b8ab2779e08243b61 Mon Sep 17 00:00:00 2001 From: seedds Date: Fri, 30 Oct 2026 08:15:01 -0700 Subject: [PATCH] audio: move callback diagnostics to the watchdog --- dm/host/hle_audio.c | 44 ++++++++++++-- dm/host/tests/Makefile | 7 ++- dm/host/tests/t_audio_stats.c | 109 ++++++++++++++++++++++++++++++++++ docs/agents/symptoms.md | 1 + docs/reference/audio.md | 12 +++- 5 files changed, 164 insertions(+), 9 deletions(-) create mode 100644 dm/host/tests/t_audio_stats.c diff --git a/dm/host/hle_audio.c b/dm/host/hle_audio.c index 081cded2ab..0483c146ad 100644 --- a/dm/host/hle_audio.c +++ b/dm/host/hle_audio.c @@ -15,6 +15,7 @@ enum { BK_NONE, BK_AU, BK_NULL }; // what is consuming an output's queue right typedef struct { void *ptr; uint64_t cap, size; } gbuf; // The first 24 bytes written into the guest AudioOutBuffer #define QMAX 64 #define RELMAX QMAX // Released max = number of in-flight buffers (the game must take a buffer back before it can append again), same limit as pending +typedef struct { uint64_t calls, count, qsum, underruns, zero_bytes; uint32_t fmin, fmax; } audio_stats; typedef struct { pthread_mutex_t m; void *event; // Guest SystemEvent: signaled whenever a buffer is released @@ -33,7 +34,8 @@ typedef struct { int id; // open sequence number (#N in the log; tells simultaneous outputs apart, e.g. Engage's Wwise and Unity's built-in FMOD) int nlog; // Start / Stop / Close lines logged so far (at most 32 per output) _Atomic uint64_t under_n, under_b; // underruns: times the pending queue was empty when the callback needed data / zero-filled bytes - uint64_t st_calls, st_qsum, st_u0, st_ub0; uint32_t st_fmin, st_fmax; // sound card callback statistics (read and written only on the callback thread) + uint64_t st_calls, st_count, st_qsum, st_u0, st_ub0; uint32_t st_fmin, st_fmax; // callback-owned accumulators + audio_stats st_report; _Atomic int st_pending; // one snapshot, consumed by the watchdog or Close under g_aos_lock _Atomic uint64_t cb_n; // device callbacks of this output (the watchdog's evidence that the device still plays it) uint64_t wd_n, wd_t; // watchdog: callback count last seen and when it last moved (under g_aos_lock) int stalled, retry_ms; uint64_t retry_at; // the device stopped calling back (or would not start): the silent sink stands in and the watchdog retries the AudioUnit at retry_at, backing off @@ -148,13 +150,17 @@ static OSStatus au_render(void *ctx, AudioUnitRenderActionFlags *f, const AudioT aout *a = ctx; atomic_fetch_add_explicit(&g_render_calls, 1, memory_order_relaxed); atomic_fetch_add_explicit(&a->cb_n, 1, memory_order_relaxed); { - // Every 2000 callbacks of each output, log one line: frames requested per call, pending blocks at callback start, underruns (check this line on a new device; docs/reference/audio.md "RemoteIO's default I/O buffer duration"). - // Kept per output: with two outputs open, combined numbers mislead (one fully fed and one fed by nobody look like "every other callback underruns") + // At each 2000-callback checkpoint publish a snapshot for the watchdog: LOG takes a stdio lock and must never run here or in the release-event notifier. + // A busy logger leaves its mailbox full; keep accumulating then, rather than waiting, overwriting its snapshot or losing counts. uint32_t qd = atomic_load(&a->q_tail) - atomic_load(&a->q_head); if (!a->st_calls || frames < a->st_fmin) a->st_fmin = frames; if (frames > a->st_fmax) a->st_fmax = frames; a->st_qsum += qd; - if (++a->st_calls % 2000 == 0) { uint64_t un = atomic_load(&a->under_n), ubb = atomic_load(&a->under_b); - LOG("audio #%d device callbacks %llu: %u–%u frames each, %.1f blocks queued on average at callback; in these 2000, %llu underruns, %.1f ms zero-padded", a->id, (unsigned long long)a->st_calls, a->st_fmin, a->st_fmax, a->st_qsum / 2000.0, - (unsigned long long)(un - a->st_u0), (ubb - a->st_ub0) / (2.0 * a->ch) / (RATE / 1000.0)); a->st_fmin = ~0u; a->st_fmax = 0; a->st_qsum = 0; a->st_u0 = un; a->st_ub0 = ubb; } } + a->st_count++; + if (++a->st_calls % 2000 == 0 && !atomic_load_explicit(&a->st_pending, memory_order_acquire)) { + uint64_t un = atomic_load(&a->under_n), ubb = atomic_load(&a->under_b); + a->st_report = (audio_stats){a->st_calls, a->st_count, a->st_qsum, un - a->st_u0, ubb - a->st_ub0, a->st_fmin, a->st_fmax}; + atomic_store_explicit(&a->st_pending, 1, memory_order_release); + a->st_fmin = ~0u; a->st_fmax = 0; a->st_qsum = a->st_count = 0; a->st_u0 = un; a->st_ub0 = ubb; + } } pull_device(a, bl->mBuffers[0].mData, bl->mBuffers[0].mDataByteSize); { static int mute = -1; if (mute < 0) { const char *e = getenv("DM_AUDIO_MUTE"); mute = e && atoi(e); } // diagnostic: the whole real-output path (AudioUnit callback pacing, background take-over) but with the output silenced (lifecycle tests on the Mac without noise) if (mute) memset(bl->mBuffers[0].mData, 0, bl->mBuffers[0].mDataByteSize); } @@ -273,6 +279,27 @@ static void au_go(aout *a, uint64_t now) { // The time is read under g_aos_lock: au_go stamps wd_t under it too, and a watchdog time read before the lock was older than the stamp of an AudioUnit the return from the background had just // started (DRAGON QUEST VII Reimagined on an iPhone: "has not called back for 18446744073662 ms", a restart of a running AudioUnit) enum { WD_TICK_MS = 50, WD_STALL_MS = 200 }; +typedef struct { audio_stats stats; int id, ch; } audio_report; +// Both consumers hold g_aos_lock. A local copy owns every log argument, so a slow log cannot hold up registry changes or retain a closed output. +static int stats_take(aout *a, audio_report *r) { + if (!atomic_load_explicit(&a->st_pending, memory_order_acquire)) return 0; + *r = (audio_report){a->st_report, a->id, a->ch}; + atomic_store_explicit(&a->st_pending, 0, memory_order_release); + return 1; +} +static void stats_log(const audio_report *r) { + const audio_stats *s = &r->stats; + LOG("audio #%d device callbacks %llu: %u–%u frames each, %.1f blocks queued on average at callback; in these %llu, %llu underruns, %.1f ms zero-padded", r->id, + (unsigned long long)s->calls, s->fmin, s->fmax, (double)s->qsum / s->count, (unsigned long long)s->count, + (unsigned long long)s->underruns, s->zero_bytes / (2.0 * r->ch) / (RATE / 1000.0)); +} +static void stats_drain(void) { + audio_report reports[AOMAX]; int n = 0; + pthread_mutex_lock(&g_aos_lock); + for (int i = 0; i < AOMAX; i++) if (g_aos[i] && stats_take(g_aos[i], &reports[n])) n++; + pthread_mutex_unlock(&g_aos_lock); + for (int i = 0; i < n; i++) stats_log(&reports[i]); +} static void *au_watchdog(void *p) { (void)p; uint64_t last = now_ns(); for (;;) { @@ -296,6 +323,7 @@ static void *au_watchdog(void *p) { } } pthread_mutex_unlock(&g_aos_lock); + stats_drain(); } return NULL; } @@ -324,6 +352,7 @@ static Result au_open_at(void *g, void *ev, const char *name, const uint8_t *par atomic_init(&a->rel_head, 0); atomic_init(&a->rel_tail, 0); atomic_init(&a->null_run, 0); atomic_init(&a->notify_run, 1); atomic_init(&a->notify_pending, 0); atomic_init(&a->notify_armed, 0); + atomic_init(&a->st_pending, 0); a->notify_sem = dispatch_semaphore_create(0); a->id = atomic_fetch_add(&nopen, 1); pthread_create(&a->notify_th, NULL, event_notify, a); if (ev) hle_bind_system_event(ev, 1); // Buffer release event: bind a kernel event on the guest thread (auto-clear), afterwards signaled by the audio thread @@ -403,9 +432,12 @@ static void au_close(void *g, void *lr) { atomic_store_explicit(&a->notify_run, 0, memory_order_release); dispatch_semaphore_signal(a->notify_sem); pthread_join(a->notify_th, NULL); + audio_report report; pthread_mutex_lock(&g_aos_lock); + int have_report = stats_take(a, &report); for (int i = 0; i < AOMAX; i++) if (g_aos[i] == a) g_aos[i] = NULL; pthread_mutex_unlock(&g_aos_lock); + if (have_report) stats_log(&report); if (a->au) au_dispose(a->au); dispatch_release(a->notify_sem); if (a->rel_sem) dispatch_release(a->rel_sem); diff --git a/dm/host/tests/Makefile b/dm/host/tests/Makefile index 3d79971e76..b639c75ac9 100644 --- a/dm/host/tests/Makefile +++ b/dm/host/tests/Makefile @@ -25,6 +25,7 @@ run: $(B)/t_language $(B)/t_motion $(B)/t_heap_size $(B)/t_touch $(B)/t_gesture TMPDIR="$(abspath $(B))" $(B)/t_save_sync $(QUIET) $(B)/t_audio $(B)/t_audio_spsc + $(B)/t_audio_stats $(B)/t_fpslock $(B)/t_uecvar $(B)/t_audren_work @@ -128,6 +129,9 @@ $(B)/t_audio: t_audio.c ../hle_audio.c ../hle_bigstack.c ../hle.h ../dm.h $(GAME $(CLANG) -O1 -Wno-unused-function -I.. $(GINC) -o $@ t_audio.c ../hle_bigstack.c -framework AudioToolbox $(B)/t_audio_spsc: t_audio_spsc.c ../hle_audio.c ../hle_bigstack.c ../hle.h ../dm.h $(GAME_H) | $(B) $(CLANG) -O1 -Wno-unused-function -I.. $(GINC) -o $@ t_audio_spsc.c ../hle_bigstack.c -framework AudioToolbox +$(B)/t_audio_stats: t_audio_stats.c ../hle_audio.c ../hle_bigstack.c ../hle.h ../dm.h $(GAME_H) | $(B) + $(CLANG) -O1 -Wall -Werror -Wno-unused-function -I.. $(GINC) -o $@ t_audio_stats.c ../hle_bigstack.c -framework AudioToolbox +run: $(B)/t_audio_stats $(B)/t_audio_device: t_audio_device.c ../hle_audio.c ../hle_bigstack.c ../hle.h ../dm.h $(GAME_H) | $(B) $(CLANG) -O1 -g -Wall -Werror -Wno-unused-function -I.. $(GINC) -o $@ t_audio_device.c ../hle_bigstack.c -framework AudioToolbox .PHONY: audio-device @@ -269,12 +273,13 @@ include ../../sanitizers/sanitizers.mk asan: @$(call san_fresh,$(B)/asan,$(ASAN_FLAGS)) $(ASAN_ENV) $(MAKE) B=$(B)/asan SAN="$(ASAN_FLAGS)" run -TSAN_T = t_audio t_audio_device t_thread_leak t_oe t_fs_commit_list t_fs_case t_save_sync t_condvar t_condvar_old t_preempt t_system_event t_notify_sched t_altstack +TSAN_T = t_audio t_audio_stats t_audio_device t_thread_leak t_oe t_fs_commit_list t_fs_case t_save_sync t_condvar t_condvar_old t_preempt t_system_event t_notify_sched t_altstack tsan-threads: @$(call san_fresh,$(B)/tsan,$(TSAN_FLAGS)) $(TSAN_ENV) $(MAKE) B=$(B)/tsan SAN="$(TSAN_FLAGS)" tsan-threads-run tsan-threads-run: $(addprefix $(B)/,$(TSAN_T)) $(B)/t_audio + $(B)/t_audio_stats $(B)/t_audio_device $(B)/t_thread_leak $(B)/t_oe diff --git a/dm/host/tests/t_audio_stats.c b/dm/host/tests/t_audio_stats.c new file mode 100644 index 0000000000..435f5e06a4 --- /dev/null +++ b/dm/host/tests/t_audio_stats.c @@ -0,0 +1,109 @@ +// Exercise the real callback while its diagnostic writer is blocked, without a sound device. +#include +#include +#include +#include +#include +#include +static _Thread_local int in_callback; +static _Atomic int callback_io, block_report, reports, line_slots; +static dispatch_semaphore_t report_entered, report_allow, report_done, released_event; +static char lines[8][512]; +static void checked_flockfile(FILE *f) { (void)f; if (in_callback) atomic_fetch_add(&callback_io, 1); } +static void checked_funlockfile(FILE *f) { (void)f; } +static int checked_fputc(int c, FILE *f) { (void)f; return c; } +static int checked_fprintf(FILE *f, const char *fmt, ...) { + (void)f; + if (in_callback) { atomic_fetch_add(&callback_io, 1); return 0; } + if (!strstr(fmt, "device callbacks")) return 0; + if (atomic_exchange(&block_report, 0)) { + dispatch_semaphore_signal(report_entered); + dispatch_semaphore_wait(report_allow, DISPATCH_TIME_FOREVER); + } + int n = atomic_fetch_add(&line_slots, 1); + va_list ap; va_start(ap, fmt); + if (n < 8) vsnprintf(lines[n], sizeof lines[n], fmt, ap); + va_end(ap); + atomic_fetch_add(&reports, 1); dispatch_semaphore_signal(report_done); + return 0; +} +#define flockfile checked_flockfile +#define funlockfile checked_funlockfile +#define fputc checked_fputc +#define fprintf checked_fprintf +#include "../hle_audio.c" +#undef fprintf +#undef fputc +#undef funlockfile +#undef flockfile +__thread _Atomic int dm_host_work; +int dm_guest_as_contains(uintptr_t a) { (void)a; return 0; } // No guest address space: the real big-stack entry keeps the calling host stack. +uint64_t now_ns(void) { return 0; } +static void *key, *value; +void *objmap_get(const void *k) { return k == key ? value : NULL; } +void objmap_put(const void *k, void *v) { key = (void *)k; value = v; } +void *objmap_del(const void *k) { void *v = objmap_get(k); key = value = NULL; return v; } +static _Atomic int signals; +void hle_signal_system_event(void *g) { (void)g; atomic_fetch_add(&signals, 1); dispatch_semaphore_signal(released_event); } +void hle_bind_system_event(void *g, int c) { (void)g; (void)c; } +module_t *module_of(const void *p) { (void)p; return NULL; } +void dm_host_helper_qos(qos_class_t q) { (void)q; } +static int checks, failures; +#define CHECK(v, why) do { checks++; if (!(v)) { failures++; printf("FAIL: %s\n", why); } } while (0) +static int wait_for(dispatch_semaphore_t s) { return !dispatch_semaphore_wait(s, dispatch_time(DISPATCH_TIME_NOW, 2000000000)); } +static int render(void *out, int count, int with_pcm) { + aout *a = ao(out); + for (int i = 0; i < count; i++) { + int frames = 1 + (i & 1); int16_t input[] = {123, -456, 789, -1234}, played[4] = {0}; + gbuf b = {input, sizeof input, (uint64_t)frames * 4}; + if (with_pcm && !h_au_Append(out, &b)) return 0; + AudioBufferList bl = {.mNumberBuffers = 1, .mBuffers = {{2, frames * 4, played}}}; + in_callback = 1; au_render(a, NULL, NULL, 0, frames, &bl); in_callback = 0; + if (with_pcm && ((a->event && !wait_for(released_event)) || memcmp(input, played, (size_t)frames * 4) || h_au_Released(out) != &b)) return 0; + } + return 1; +} +static void *drain_stats(void *unused) { (void)unused; stats_drain(); return NULL; } +int main(void) { + setenv("DM_AUDIO", "0", 1); setenv("DM_AUDIO_MUTE", "0", 1); + report_entered = dispatch_semaphore_create(0); report_allow = dispatch_semaphore_create(0); + report_done = dispatch_semaphore_create(0); released_event = dispatch_semaphore_create(0); + uint32_t out[16] = {0}; uint8_t prm[8] = {0}, ev[64] = {0}; + CHECK(!h_au_OpenDef(out, ev, prm), "open output with a guest release event"); + atomic_store(&ao(out)->state, STATE_STARTED); atomic_store(&block_report, 1); + CHECK(render(out, 2000, 1), "PCM and release order at first statistics boundary"); + CHECK(!atomic_load(&callback_io), "callback never enters stdio or its stream lock"); + if (atomic_load(&callback_io)) { h_au_Close(out); return 1; } // old code fails here, without waiting for a helper that never logs + pthread_t logger; CHECK(!pthread_create(&logger, NULL, drain_stats, NULL), "run the watchdog's actual statistics drain"); + CHECK(wait_for(report_entered), "hold the diagnostic writer outside the callback"); + CHECK(render(out, 6000, 1), "a blocked diagnostic writer never stops PCM or guest release events"); + CHECK(atomic_load(&signals) == 8000, "every event-driven PCM buffer is released while diagnostics are blocked"); + CHECK(!atomic_load(&callback_io), "backlogged diagnostics still use no callback stdio"); + dispatch_semaphore_signal(report_allow); + pthread_join(logger, NULL); stats_drain(); + CHECK(wait_for(report_done) && wait_for(report_done), "helper drains two complete snapshots"); + CHECK(render(out, 2000, 1), "callbacks continue after the diagnostic backlog"); + stats_drain(); + CHECK(wait_for(report_done), "accumulated callback statistics are eventually reported"); + CHECK(strstr(lines[0], "device callbacks 2000: 1\xe2\x80\x93" "2 frames") && strstr(lines[0], "1.0 blocks queued") && strstr(lines[0], "in these 2000, 0 underruns, 0.0 ms"), "first report preserves frame range, queue depth and underrun fields"); + CHECK(strstr(lines[1], "device callbacks 4000:") && strstr(lines[1], "in these 2000,"), "next pending snapshot is preserved"); + CHECK(strstr(lines[2], "device callbacks 10000:") && strstr(lines[2], "in these 6000,"), "a full mailbox merges later windows without losing their counts"); + h_au_Close(out); + + // The watchdog's local report may outlive the output; Close owns any newer pending snapshot. + atomic_store(&signals, 0); + CHECK(!h_au_OpenDef(out, ev, prm), "open another output with a guest event"); + atomic_store(&ao(out)->state, STATE_STARTED); atomic_store(&block_report, 1); + CHECK(render(out, 2000, 0), "publish a close-case report"); + CHECK(!pthread_create(&logger, NULL, drain_stats, NULL) && wait_for(report_entered), "hold a copied watchdog report"); + CHECK(render(out, 2000, 0), "publish a second report before close"); + h_au_Close(out); + CHECK(atomic_load(&reports) == 4, "close drains the pending snapshot while the watchdog retains only a local copy"); + dispatch_semaphore_signal(report_allow); pthread_join(logger, NULL); + CHECK(atomic_load(&reports) == 5, "the watchdog logs its copied report after the output was freed"); + CHECK(!atomic_load(&signals), "statistics wakes never signal a guest buffer-release event"); + CHECK(!atomic_load(&callback_io), "all callback paths remain free of diagnostic stdio"); + dispatch_release(report_entered); dispatch_release(report_allow); dispatch_release(report_done); dispatch_release(released_event); + printf("audio callback statistics: %d checks, %d failures\n", checks, failures); + return failures != 0; +} diff --git a/docs/agents/symptoms.md b/docs/agents/symptoms.md index f47b4c9cd0..43a4d8178b 100644 --- a/docs/agents/symptoms.md +++ b/docs/agents/symptoms.md @@ -279,6 +279,7 @@ One line per symptom in the [subsystem references](../reference/): what you see - UBSan reports a misaligned `uint32_t` load in `cmd_ok` while `t_audren_layout` probes SDK 4/6 lists (issue #409). → [Unaligned command headers during layout probing](../reference/audio.md#unaligned-command-headers-during-layout-probing) - no music and no sound effects, only the movies' sound (the log repeats `audren: first-frame commands …` every frame and never prints `DeviceSink inputs`). → [SDK 8: command IDs numbered differently](../reference/audio.md#sdk-8-command-ids-numbered-differently) - no sound; red `audren: command 0 in the command list is malformed (first word 0x181901 size 0)`. → [SDK 21 DSP command header without a magic](../reference/audio.md#sdk-21-dsp-command-header-without-a-magic) +- RealtimeSanitizer reports stdio locking in `au_render` at its 2,000-callback diagnostic boundary. A busy log writer can block that callback even when its PCM queue is full. → [Periodic diagnostics outside the AudioUnit callback](../reference/audio.md#periodic-diagnostics-outside-the-audiounit-callback) - FMOD waits for buffer release after stopping an AudioOut, hanging the game during a scene transition. → [Stopping an AudioOut releases its pending buffers](../reference/audio.md#stopping-an-audioout-releases-its-pending-buffers) - crackling on iOS only. → [RemoteIO's default I/O buffer duration](../reference/audio.md#remoteios-default-io-buffer-duration) - clicks and dropouts on the Mac, heard as clipping; the log's `audio #N device callbacks` lines show hundreds of underruns per 2000 callbacks. Closing an output can also log `[RED] audio device buffer: ... (status 560947818)` (`!obj`). → [The Mac's default I/O buffer](../reference/audio.md#the-macs-default-io-buffer) diff --git a/docs/reference/audio.md b/docs/reference/audio.md index 4c7103d0cf..25ab30c751 100644 --- a/docs/reference/audio.md +++ b/docs/reference/audio.md @@ -158,6 +158,14 @@ For a replaced DSP renderer the size query keeps the service's work-buffer contr ## AudioOut and devices +### Periodic diagnostics outside the AudioUnit callback + +- **Symptom:** RealtimeSanitizer reports stdio locking in `au_render` at its 2,000-callback diagnostic boundary. A busy log writer can block that callback even when its PCM queue is full. +- **Cause:** `LOG` takes `stderr`'s stream lock and formats its message on the calling thread. The callback previously called it directly for its frame-count, queue-depth and underrun statistics. +- **Fix:** the callback publishes a bounded snapshot for the existing audio watchdog, which copies ready reports under the output-registry lock and writes them after unlocking. Its local copies own every log argument; a slow writer holds neither an output pointer nor the registry lock. The single-slot mailbox uses release/acquire ownership; a busy writer leaves the callback accumulating later windows instead of waiting or overwriting unread data. Reports retain the output ID, total callbacks, frame range, average queue depth and underrun/zero-padding counts, with the actual window length when several windows merge. The release-event notifier remains independent of diagnostics, so an event-driven game can keep refilling PCM while logging is blocked. Close stops the producer and takes any remaining snapshot under the same registry lock before freeing the output. +- **Found on:** the [synthetic real-time audio audit in issue #313](https://github.com/seedds/nxnative/issues/313#issuecomment-6523656102). No particular game's audible failure is attributed to this finding. +- **Check:** `t_audio_stats` calls the real callback with synthetic PCM and traps callback-thread stdio, including its stream lock. With the watchdog's writer deliberately blocked, each PCM buffer still triggers its guest release event and is refilled correctly; queued and merged reports preserve their fields. Close drains a second pending snapshot while the watchdog holds only a local copy, which it logs after the output was freed. Statistics alone cause no guest event. The fixture needs no sound device or game files. + ### Stopping an AudioOut releases its pending buffers - **Symptom:** FMOD waits for buffer release after stopping an AudioOut, hanging the game during a scene transition. @@ -171,7 +179,7 @@ For a replaced DSP renderer the size query keeps the service's work-buffer contr - **Symptom:** crackling on iOS only. - **Cause:** RemoteIO asks for as many frames per callback as the audio session's I/O buffer duration, about 21 ms by default (1024 frames at 48 kHz), while the renderer keeps 4 blocks × 5 ms = 20 ms in flight. Every callback came up 1.3 ms short and was padded with zeros, about 47 gaps per second. Reproduced on the Mac by forcing 1024-frame callbacks (`DM_DBG_AU_FRAMES=1024` with `DM_AUDIO=1`: 1999 underruns in 2000 callbacks). - **Fix:** `AVAudioSession` `setPreferredIOBufferDuration:0.005` (and 48 kHz) before the game opens audio and again on return to the foreground (`front_ios_audio_session` in `front_ios.m`); the device then calls back with 240 frames and nothing underruns. -- **Check:** when checking a new device, read the host's `audio #N device callbacks` line, logged every 2000 callbacks: frames per callback, queued blocks, underruns. +- **Check:** when checking a new device, read the host's `audio #N device callbacks` line, normally reported every 2000 callbacks: frames per callback, queued blocks, underruns. A busy diagnostic writer can merge windows; the line states their actual callback count. ### The Mac's default I/O buffer @@ -216,7 +224,7 @@ For a replaced DSP renderer the size query keeps the service's work-buffer contr - **Symptom:** combined numbers mislead: one fully fed output plus one fed by nobody look like "every other callback underruns, 2.0 blocks queued". - **Cause:** a game may open several outputs. Engage opens one AudioOut from Wwise (`main+0x177d924`, no release event, the game polls); on the phone it opened a second one later, and the Mac runs never did. Unity's FMOD also has an output (`main+0x4aec0c` / `0x4aec4c`). -- **Fix:** the host logs each output as `audio #N`: the open with its call site, Start / Stop / Close (the first 32 per output), and the callback line every 2000 of that output's callbacks. +- **Fix:** the host logs each output as `audio #N`: the open with its call site, Start / Stop / Close (the first 32 per output), and the callback statistics normally every 2000 of that output's callbacks, through the [watchdog](#periodic-diagnostics-outside-the-audiounit-callback). - **Found on:** [Fire Emblem Engage](../../dm/games/0100A6301214E000/README.md). ### Checking audio without listening