audio: move callback diagnostics to the watchdog

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);

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

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 <stdio.h>
+#include <pthread.h>
+#include <stdatomic.h>
+#include <stdarg.h>
+#include <dispatch/dispatch.h>
+#include <string.h>
+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;
+}

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)