Make audio device watchdog tests independent of scheduler delays

dm/host/hle_audio.c

@@ -352,42 +352,46 @@ static void stats_drain(void) {
     pthread_mutex_unlock(&g_aos_lock);
     for (int i = 0; i < n; i++) stats_log(&reports[i]);
 }
+// One registry tick; the caller holds g_aos_lock and reads t after taking it.
+static void au_watchdog_tick(uint64_t t, uint64_t gap) {
+    for (int i = 0; i < AOMAX; i++) {
+        aout *a = g_aos[i]; if (!a || !a->au) continue;
+        uint64_t n = atomic_load_explicit(&a->cb_n, memory_order_relaxed);
+        if (a->start_phase == AU_WAIT_CALLBACK) {
+            if (n != a->wd_n) {
+                null_stop(a);
+                atomic_store_explicit(&a->hold_device, 0, memory_order_release);
+                if (a->stalled) LOG("audio #%d: AudioUnit restarted", a->id);
+                a->backend = BK_AU; a->start_phase = AU_IDLE; a->stalled = a->retry_ms = 0;
+                a->wd_n = n; a->wd_t = t;
+            } else if (gap > 4ull * WD_TICK_MS * 1000000) a->wd_t = t;
+            else if (t - a->wd_t >= 1000000000ull) {
+                if (!a->stalled) LOG("[RED] audio #%d: no device callback after start; continuing on the silent sink", a->id);
+                AudioOutputUnitStop(a->au); a->start_phase = AU_IDLE; au_retry(a, t);
+            }
+            continue;
+        }
+        if (a->backend == BK_NULL) {
+            if (t >= a->retry_at) au_request_start(a);
+            continue;
+        }
+        if (a->backend != BK_AU) continue;
+        if (gap > 4ull * WD_TICK_MS * 1000000 || n != a->wd_n) {
+            a->wd_n = n; a->wd_t = t;
+        } else if (t - a->wd_t > WD_STALL_MS * 1000000ull) {
+            LOG("[RED] audio #%d: the device has not called back for %.0f ms while playing: the silent sink stands in, retrying the AudioUnit", a->id, (t - a->wd_t) / 1e6);
+            AudioOutputUnitStop(a->au); a->backend = BK_NONE; null_start(a);
+            au_retry(a, t);
+        }
+    }
+}
 static void *au_watchdog(void *p) {
     (void)p; uint64_t last = now_ns();
     for (;;) {
         usleep(WD_TICK_MS * 1000);
         pthread_mutex_lock(&g_aos_lock);
         uint64_t t = now_ns(), gap = t - last; last = t;
-        for (int i = 0; i < AOMAX; i++) {
-            aout *a = g_aos[i]; if (!a || !a->au) continue;
-            uint64_t n = atomic_load_explicit(&a->cb_n, memory_order_relaxed);
-            if (a->start_phase == AU_WAIT_CALLBACK) {
-                if (n != a->wd_n) {
-                    null_stop(a);
-                    atomic_store_explicit(&a->hold_device, 0, memory_order_release);
-                    if (a->stalled) LOG("audio #%d: AudioUnit restarted", a->id);
-                    a->backend = BK_AU; a->start_phase = AU_IDLE; a->stalled = a->retry_ms = 0;
-                    a->wd_n = n; a->wd_t = t;
-                } else if (gap > 4ull * WD_TICK_MS * 1000000) a->wd_t = t;
-                else if (t - a->wd_t >= 1000000000ull) {
-                    if (!a->stalled) LOG("[RED] audio #%d: no device callback after start; continuing on the silent sink", a->id);
-                    AudioOutputUnitStop(a->au); a->start_phase = AU_IDLE; au_retry(a, t);
-                }
-                continue;
-            }
-            if (a->backend == BK_NULL) {
-                if (t >= a->retry_at) au_request_start(a);
-                continue;
-            }
-            if (a->backend != BK_AU) continue;
-            if (gap > 4ull * WD_TICK_MS * 1000000 || n != a->wd_n) {
-                a->wd_n = n; a->wd_t = t;
-            } else if (t - a->wd_t > WD_STALL_MS * 1000000ull) {
-                LOG("[RED] audio #%d: the device has not called back for %.0f ms while playing: the silent sink stands in, retrying the AudioUnit", a->id, (t - a->wd_t) / 1e6);
-                AudioOutputUnitStop(a->au); a->backend = BK_NONE; null_start(a);
-                au_retry(a, t);
-            }
-        }
+        au_watchdog_tick(t, gap);
         pthread_mutex_unlock(&g_aos_lock);
         stats_drain();
     }

dm/host/tests/t_audio_device.c

@@ -4,6 +4,10 @@
 #include <assert.h>
 #include <stddef.h>
 #include <time.h>
+#include <pthread.h>
+
+static int mock_once(pthread_once_t *, void (*)(void));
+#define pthread_once mock_once
 
 static AudioComponent mock_find(AudioComponent, const AudioComponentDescription *);
 static OSStatus mock_new(AudioComponent, AudioComponentInstance *);
@@ -28,6 +32,12 @@ static OSStatus mock_dispose(AudioComponentInstance);
 #define AudioUnitUninitialize mock_uninit
 #define AudioComponentInstanceDispose mock_dispose
 #include "../hle_audio.c"
+#undef pthread_once
+// The device is mocked, so drive its watchdog ticks too. Real scheduler delays must not
+// reset the no-callback deadline while this fixture waits for a timeout it assumes is fixed.
+static int mock_once(pthread_once_t *once, void (*init)(void)) {
+    (void)once; assert(init == au_watchdog_start); return 0;
+}
 __thread _Atomic int dm_host_work;   // defined by the graphics host in a full build
 
 static struct {
@@ -144,6 +154,40 @@ static void *guest_close(void *out) { h_au_Close(out); dispatch_semaphore_signal
 static int signaled(dispatch_semaphore_t s, int seconds) {
     return dispatch_semaphore_wait(s, dispatch_time(DISPATCH_TIME_NOW, seconds * (int64_t)NSEC_PER_SEC)) == 0;
 }
+static void wait_phase(aout *a, int phase) {
+    uint64_t until = now_ns() + NSEC_PER_SEC;
+    for (;;) {
+        pthread_mutex_lock(&g_aos_lock);
+        int ready = a->start_phase == phase;
+        pthread_mutex_unlock(&g_aos_lock);
+        if (ready) return;
+        assert(now_ns() < until);
+        usleep(1000);
+    }
+}
+static void watchdog_tick(uint64_t t, uint64_t gap) {
+    pthread_mutex_lock(&g_aos_lock);
+    // Zero selects the real clock for callback handoff, read under the same lock as the startup stamp.
+    au_watchdog_tick(t ? t : now_ns(), gap);
+    pthread_mutex_unlock(&g_aos_lock);
+}
+static void retry_at_deadline(aout *a) {
+    wait_phase(a, AU_IDLE);
+    pthread_mutex_lock(&g_aos_lock);
+    uint64_t t = a->retry_at;
+    assert(a->stalled && t);
+    pthread_mutex_unlock(&g_aos_lock);
+    watchdog_tick(t - 1, 50000000);
+    pthread_mutex_lock(&g_aos_lock);
+    assert(a->start_phase == AU_IDLE);
+    pthread_mutex_unlock(&g_aos_lock);
+    assert(!signaled(start_entered, 0));
+    watchdog_tick(t, 1);
+    pthread_mutex_lock(&g_aos_lock);
+    assert(a->start_phase == AU_STARTING);
+    pthread_mutex_unlock(&g_aos_lock);
+    assert(signaled(start_entered, 2));
+}
 static void blocked_start(void *out) {
     start_entered = dispatch_semaphore_create(0);
     start_allowed = dispatch_semaphore_create(0);
@@ -179,28 +223,63 @@ static void blocked_start(void *out) {
     dispatch_semaphore_signal(start_allowed);
     pthread_join(guest, NULL);
     until = now_ns() + NSEC_PER_SEC;
-    do { au_render(a, NULL, NULL, 0, 1, &bl); if (samples[0]) break; usleep(1000); } while (now_ns() < until);
+    do {
+        au_render(a, NULL, NULL, 0, 1, &bl);
+        watchdog_tick(0, 50000000);
+        if (samples[0]) break;
+        usleep(1000);
+    } while (now_ns() < until);
     assert(samples[0] == 1234 && samples[1] == 1234);
 
+    // Finish the long handoff buffer through the callback. The resumed silent sink gets
+    // a separate 10 ms buffer: its real-time pacing must not depend on virtual watchdog time.
+    static int16_t drained[RATE * 2];
+    AudioBufferList drain = {.mNumberBuffers = 1, .mBuffers = {{2, sizeof drained, drained}}};
+    au_render(a, NULL, NULL, 0, RATE, &drain);
+    assert(h_au_Released(out) == &next);
+    gbuf resumed = {pcm, sizeof pcm, sizeof pcm};
+    assert(h_au_Append(out, &resumed));
     dm_audio_suspend(1);
     assert(signaled(device_stopped, 1));
     dm_audio_suspend(0);
     assert(signaled(start_entered, 2));
     // A successful start with no callbacks keeps releasing buffers and is retried.
     dispatch_semaphore_signal(start_allowed);
-    assert(signaled(device_stopped, 3));
+    wait_phase(a, AU_WAIT_CALLBACK);
+    pthread_mutex_lock(&g_aos_lock);
+    uint64_t t = a->wd_t;
+    pthread_mutex_unlock(&g_aos_lock);
+    // Late wakes deliberately restart the deadline; three seconds of them must not stop the device.
+    for (int i = 0; i < 12; i++) {
+        t += 250000000;
+        watchdog_tick(t, 250000000);
+        assert(!signaled(device_stopped, 0));
+    }
+    // Only a full second of timely ticks without a callback stops it, exactly at the boundary.
+    for (int i = 0; i < 19; i++) {
+        t += 50000000;
+        watchdog_tick(t, 50000000);
+        assert(!signaled(device_stopped, 0));
+    }
+    t += 49999999; watchdog_tick(t, 49999999);
+    assert(!signaled(device_stopped, 0));
+    watchdog_tick(t + 1, 1);
+    assert(signaled(device_stopped, 0));
     until = now_ns() + NSEC_PER_SEC;
     while (!(released = h_au_Released(out)) && now_ns() < until) usleep(1000);
-    assert(released == &next);
-    assert(signaled(start_entered, 3));
+    assert(released == &resumed);
+    retry_at_deadline(a);
     start_result = kAudioUnitErr_FailedInitialization;
     dispatch_semaphore_signal(start_allowed);
-    assert(signaled(start_entered, 4));
+    retry_at_deadline(a);
     // Reset while the retry blocks. The old unit stays alive until Start returns, then its replacement starts.
     start_result = noErr;
     dm_audio_reset(); assert(unit.disposals == 0);
     dispatch_semaphore_signal(start_allowed);
-    assert(signaled(device_stopped, 1) && signaled(start_entered, 2));
+    assert(signaled(device_stopped, 1));
+    wait_phase(a, AU_IDLE);
+    watchdog_tick(0, 50000000);
+    assert(signaled(start_entered, 2));
     assert(unit.disposals == 1);
     // Close returns while the driver still blocks Start: it unregisters the output and leaves the unit to the start's worker,
     // which stops and disposes it when Start returns.