Capture native audio callback timing

openpilot/selfdrive/ui/soundd.py

@@ -280,6 +280,7 @@ class Soundd:
         sm.update(0)
         if self.native_audio is not None:
           self.native_audio.sync_owner()
+          self.native_audio.report_underflow_timing()
         self.log_pending_stream_status(stream)
         self.refresh_saved_volumes(time.monotonic())
         self.load_sounds()
@@ -298,7 +299,10 @@ class Soundd:
 
         rk.keep_time()
 
-        assert stream.active
+        active = stream.active
+        if not active and self.native_audio is not None:
+          self.native_audio.report_underflow_timing(closing=True)
+        assert active
 
 
 def main():

openpilot/starpilot/audio/native/audio_mixer.c

@@ -6,6 +6,11 @@
 #include <stdlib.h>
 #include <string.h>
 #include <math.h>
+#include <time.h>
+
+#define DIAG_ROWS 32U
+#define DIAG_WORDS 22U
+#define DIAG_HEADER 10U
 
 #define SLOTS 16
 #define MAX_PCM 1440000U
@@ -24,6 +29,10 @@ struct audio {
   float gain;
   bool pending_stop;
   atomic_flag rendering;
+  // Bounded first-underflow timing. Callback is sole ring writer; getter reads atomics.
+  _Atomic uint64_t diag_seq, diag_frozen, diag_total, diag_first;
+  _Atomic uint64_t diag_abort_count, diag_clock_errors;
+  _Atomic uint64_t diag_rows[DIAG_ROWS][DIAG_WORDS];
 };
 static void free_bank(struct bank *b) { if (b) { for(unsigned i=0;i<SLOTS;i++) free(b->pcm[i]); free(b); } }
 unsigned audio_mixer_abi(void) { return 3; }
@@ -75,13 +84,70 @@ int audio_prepare(struct audio *a) {
   accept_command(a);
   return a->active!=NULL && a->applied_seq!=0;
 }
+// Diagnostic ABI1: clock failures are explicit, never fake valid timestamps.
+static uint64_t diag_clock(clockid_t clock, uint64_t bit, uint64_t *errors) {
+  struct timespec ts;
+  if(clock_gettime(clock,&ts)!=0) { *errors|=bit;return 0; }
+  return (uint64_t)ts.tv_sec*1000000000ULL+(uint64_t)ts.tv_nsec;
+}
+static uint64_t diag_double(double value) { uint64_t bits;memcpy(&bits,&value,sizeof(bits));return bits; }
+static void diag_finish(struct audio *a,uint64_t entry_mono,uint64_t entry_cpu,
+                        const struct pa_time *t,unsigned long frames,unsigned long flags,uint64_t errors) {
+  uint64_t exit_cpu=diag_clock(CLOCK_THREAD_CPUTIME_ID,4U,&errors);
+  uint64_t exit_mono=diag_clock(CLOCK_MONOTONIC,8U,&errors);
+  uint64_t ordinal=atomic_load(&a->diag_total)+1U;
+  uint64_t first=atomic_load(&a->diag_first);
+  if(!first && (flags&4U)) first=ordinal;
+  uint64_t values[DIAG_WORDS]={ordinal,entry_mono,entry_cpu,exit_mono,exit_cpu,
+    t?diag_double(t->input_adc):0,t?diag_double(t->current):0,t?diag_double(t->output_dac):0,
+    frames,flags,a->applied_seq,a->restart,a->sound,a->frame,a->active?a->active->revision:0,
+    a->status_count,a->underflows,a->last_flags,errors,t!=NULL,
+    atomic_load(&a->pending)!=NULL,atomic_load(&a->retired)!=NULL};
+  uint64_t seq=atomic_load(&a->diag_seq);atomic_store(&a->diag_seq,seq+1U);
+  unsigned index=(unsigned)((ordinal-1U)%DIAG_ROWS);
+  for(unsigned i=0;i<DIAG_WORDS;i++) atomic_store(&a->diag_rows[index][i],values[i]);
+  atomic_store(&a->diag_total,ordinal);atomic_store(&a->diag_first,first);
+  if(errors) atomic_fetch_add(&a->diag_clock_errors,1U); // Rows with any failed clock.
+  if(first && ordinal>=first+4U) atomic_store(&a->diag_frozen,1U);
+  atomic_store(&a->diag_seq,seq+2U);
+}
+unsigned audio_diagnostic_abi(void) { return 1; }
+// Returns words copied,0 if unavailable/too-small. At most3 attempts; no wait.
+unsigned audio_diagnostic_snapshot(struct audio *a,uint64_t *out,unsigned capacity) {
+  if(!a || !out || capacity<DIAG_HEADER+DIAG_ROWS*DIAG_WORDS) return 0;
+  for(unsigned attempt=0;attempt<3;attempt++) {
+    uint64_t seq=atomic_load(&a->diag_seq);if(seq&1U) continue;
+    uint64_t total=atomic_load(&a->diag_total),first=atomic_load(&a->diag_first);
+    uint64_t start=first?(first>16U?first-16U:1U):(total>DIAG_ROWS?total-DIAG_ROWS+1U:1U);
+    uint64_t count=total>=start?total-start+1U:0;
+    if(count>DIAG_ROWS) return 0;
+    out[0]=1;out[1]=DIAG_WORDS;out[2]=DIAG_ROWS;out[3]=total;out[4]=first;
+    out[5]=atomic_load(&a->diag_frozen);out[6]=start;out[7]=count;
+    out[8]=atomic_load(&a->diag_abort_count);out[9]=atomic_load(&a->diag_clock_errors);
+    for(uint64_t row=0;row<count;row++) {
+      unsigned index=(unsigned)((start+row-1U)%DIAG_ROWS);
+      for(unsigned col=0;col<DIAG_WORDS;col++) out[DIAG_HEADER+row*DIAG_WORDS+col]=atomic_load(&a->diag_rows[index][col]);
+    }
+    if(seq==atomic_load(&a->diag_seq)) return DIAG_HEADER+(unsigned)count*DIAG_WORDS;
+  }
+  return 0;
+}
 static int audio_callback(const void *input,void *output,unsigned long frames,const struct pa_time *t,unsigned long flags,void *user) {
-  (void)input;(void)t;struct audio *a=user;
-  if(!a || !output || frames>MAX_FRAMES || atomic_flag_test_and_set(&a->rendering)) return 2;
+  (void)input;struct audio *a=user;
+  if(!a) return 2;
+  if(!output || frames>MAX_FRAMES || atomic_flag_test_and_set(&a->rendering)) {
+    atomic_fetch_add(&a->diag_abort_count,1U);return 2;
+  }
+  bool diagnostic=!atomic_load(&a->diag_frozen);
+  uint64_t errors=0,entry_mono=0,entry_cpu=0;
+  if(diagnostic) {
+    entry_mono=diag_clock(CLOCK_MONOTONIC,1U,&errors);
+    entry_cpu=diag_clock(CLOCK_THREAD_CPUTIME_ID,2U,&errors);
+  }
   accept_command(a);
   float *out=output;memset(out,0,frames*sizeof(float));
   unsigned length=a->active?a->active->lengths[a->sound]:0;
-  if(a->alert && !length) { atomic_flag_clear(&a->rendering);return 2; }
+  if(a->alert && !length) { atomic_fetch_add(&a->diag_abort_count,1U);atomic_flag_clear(&a->rendering);return 2; }
   unsigned written=0;
   while(a->alert && written<frames && (a->loops<0 || a->frame/length<(uint64_t)a->loops)) {
     unsigned pos=(unsigned)(a->frame%length),n=length-pos;
@@ -99,6 +165,7 @@ static int audio_callback(const void *input,void *output,unsigned long frames,co
   atomic_store(&a->status[6],1U);atomic_store(&a->status[7],a->applied_seq);
   atomic_store(&a->status[8],a->restart);atomic_store(&a->status[9],a->sound);
   atomic_store(&a->status_seq,status_seq+2);
+  if(diagnostic) diag_finish(a,entry_mono,entry_cpu,t,frames,flags,errors);
   atomic_flag_clear(&a->rendering);return 0;
 }
 uintptr_t audio_callback_address(void) { return (uintptr_t)&audio_callback; }

openpilot/starpilot/audio/native_playback.py

@@ -9,6 +9,12 @@ import numpy as np
 from openpilot.starpilot.audio.alert_volume import effective_volume
 
 LIBRARY = Path(__file__).with_name('native') / 'libaudio_mixer.so'
+TIMING_HEADER = ('abi', 'row_words', 'capacity', 'total_recorded', 'first_underflow', 'frozen',
+                 'start_ordinal', 'row_count', 'callback_aborts', 'clock_error_rows')
+TIMING_COLUMNS = ('ordinal', 'entry_mono_ns', 'entry_cpu_ns', 'exit_mono_ns', 'exit_cpu_ns',
+                  'pa_input_bits', 'pa_current_bits', 'pa_output_bits', 'frames', 'flags', 'command',
+                  'restart', 'slot', 'cursor', 'bank_revision', 'status_callbacks', 'underflows',
+                  'last_flags', 'clock_error_mask', 'timeinfo_present', 'pending_bank', 'retired_bank')
 # sounddevice marks its pointer closed even when Pa_CloseStream returns an error.
 # Keep code, userdata and PCM alive until process exit if that fence fails.
 _unclosed_streams = []
@@ -59,6 +65,11 @@ class NativePlayback:
     self.stop_frame = 0
     self.previous_alert = self.previous_sound = None
     self.status_count = 0
+    self.timing_reported = False
+    self.timing_getter = getattr(self.lib, 'audio_diagnostic_snapshot', None)
+    if self.timing_getter is not None:
+      self.timing_getter.argtypes = [ctypes.c_void_p, ctypes.POINTER(ctypes.c_uint64), ctypes.c_uint]
+      self.timing_getter.restype = ctypes.c_uint
     try:
       if not self.publish():
         raise ValueError('Native sounds were not admitted')
@@ -150,6 +161,29 @@ class NativePlayback:
       self.status_count = value[3]
     owner.stream_status_count, owner.output_underflow_count = value[3], value[4]
 
+  def report_underflow_timing(self, *, closing=False):
+    """Read one fixed native trace on the service thread, after four recovery callbacks."""
+    if self.timing_reported or self.timing_getter is None or (not closing and not self.owner.output_underflow_count):
+      return
+    values = (ctypes.c_uint64 * 714)()
+    words = self.timing_getter(self.handle, values, len(values))
+    if not words or (not closing and not values[5]):
+      return
+    if not values[4] and not values[8]:
+      return
+    self.timing_reported = True
+    from openpilot.common.swaglog import cloudlog
+    # Integer clock values and raw PortAudio double bits keep invalid clocks
+    # explicit and make JSON finite. Decode host stream clocks separately.
+    count = values[7]
+    if values[0] != 1 or values[1] != 22 or values[2] != 32 or count > 32 or words != 10 + 22 * count:
+      cloudlog.error({'event': 'soundd_underflow_timing', 'error': 'invalid_native_diagnostic'})
+      return
+    cloudlog.error({'event': 'soundd_underflow_timing', 'schema': 1, 'sample_rate': self.rate,
+                    'block_frames': self.buffer, 'header_columns': TIMING_HEADER, 'columns': TIMING_COLUMNS,
+                    'header': list(values[:10]),
+                    'rows': [list(values[i:i + 22]) for i in range(10, words, 22)]})
+
   def stream(self):
     # Public OutputStream/RawOutputStream wrap callbacks in Python; only the existing base CData path avoids the GIL.
     callback = self.sd._ffi.cast('PaStreamCallback*', self.lib.audio_callback_address())

openpilot/starpilot/audio/tests/native/test_diagnostic.c

@@ -0,0 +1,48 @@
+#define _GNU_SOURCE
+#include <time.h>
+#include <assert.h>
+#include <stdint.h>
+static unsigned clock_calls;
+static int fail_clocks;
+static int fake_clock(clockid_t id,struct timespec *ts) {
+  (void)id;clock_calls++;
+  if(fail_clocks)return -1;
+  ts->tv_sec=1;ts->tv_nsec=clock_calls*1000;return 0;
+}
+#define clock_gettime fake_clock
+#include "../../native/audio_mixer.c"
+#undef clock_gettime
+static struct audio *fixture(void) {
+  struct audio *a=audio_create();assert(a);
+  static const float pcm[]={.25f,.5f,.75f,1.f};
+  const float *p[]={pcm};const unsigned lengths[]={4};
+  assert(audio_publish_bank(a,p,lengths,1,1));
+  assert(audio_command(a,1,0,-1,0,0.f,1,1,0)==2);
+  assert(audio_prepare(a));return a;
+}
+int main(void) {
+  uint64_t out[DIAG_HEADER+DIAG_ROWS*DIAG_WORDS];float rendered[4];
+  struct pa_time t={1.,2.,3.};struct audio *a=fixture();
+  for(unsigned i=0;i<20;i++)assert(audio_callback(NULL,rendered,4,&t,0,a)==0);
+  assert(audio_callback(NULL,rendered,4,&t,4,a)==0);
+  for(unsigned i=0;i<4;i++)assert(audio_callback(NULL,rendered,4,&t,0,a)==0);
+  assert(clock_calls==100);assert(audio_diagnostic_snapshot(a,out,714)==10+21*22);
+  assert(out[0]==1 && out[3]==25 && out[4]==21 && out[5]==1 && out[6]==5 && out[7]==21);
+  for(unsigned i=0;i<21;i++)assert(out[10+i*22]==5+i);
+  assert(out[10+16*22+9]==4);assert(out[10+16*22+16]==1);
+  for(unsigned i=0;i<4;i++)assert(rendered[i]==0.f); // Gain0 still advances real cursor.
+  assert(a->frame==100);assert(a->underflows==1);
+  for(unsigned i=0;i<3;i++)assert(audio_callback(NULL,rendered,4,&t,0,a)==0);
+  assert(clock_calls==100 && a->frame==112); // Frozen ring adds no further clock calls.
+  assert(audio_diagnostic_snapshot(a,out,713)==0);
+  atomic_store(&a->diag_seq,3);assert(audio_diagnostic_snapshot(a,out,714)==0);atomic_store(&a->diag_seq,4);
+  atomic_flag_test_and_set(&a->rendering);assert(audio_callback(NULL,rendered,4,&t,0,a)==2);
+  assert(atomic_load(&a->diag_abort_count)==1);atomic_flag_clear(&a->rendering);audio_destroy(a);
+  a=fixture();for(unsigned i=0;i<40;i++)assert(audio_callback(NULL,rendered,4,NULL,0,a)==0);
+  assert(audio_diagnostic_snapshot(a,out,714)==714);assert(out[3]==40 && out[4]==0 && out[5]==0 && out[6]==9 && out[7]==32);
+  assert(out[10+19]==0); // Missing PaTimeInfo explicit.
+  fail_clocks=1;assert(audio_callback(NULL,rendered,4,NULL,0,a)==0);
+  assert(audio_diagnostic_snapshot(a,out,714)==714);assert(out[9]==1);
+  unsigned last=10+31*22;assert(out[last+18]==15 && out[last+1]==0 && out[last+4]==0);
+  audio_destroy(a);return 0;
+}

openpilot/starpilot/audio/tests/native/test_diagnostic_concurrent.c

@@ -0,0 +1,58 @@
+#define _GNU_SOURCE
+#include <assert.h>
+#include <pthread.h>
+#include <sched.h>
+#include <stdio.h>
+#include <unistd.h>
+#include "../../native/audio_mixer.c"
+static struct audio *engine;
+static pthread_mutex_t barrier_mutex = PTHREAD_MUTEX_INITIALIZER;
+static pthread_cond_t barrier_cond = PTHREAD_COND_INITIALIZER;
+static unsigned barrier_arrived;
+static void barrier_wait(void) {
+  assert(pthread_mutex_lock(&barrier_mutex) == 0);
+  barrier_arrived++;
+  if (barrier_arrived == 2) assert(pthread_cond_broadcast(&barrier_cond) == 0);
+  while (barrier_arrived < 2) assert(pthread_cond_wait(&barrier_cond, &barrier_mutex) == 0);
+  assert(pthread_mutex_unlock(&barrier_mutex) == 0);
+}
+static _Atomic int done;
+static uint64_t reader_attempts,reader_successes,reader_unavailable,accepted_unfrozen,accepted_wrapped_unfrozen;
+static void validate(const uint64_t *out,unsigned words) {
+  assert(out[0]==1 && out[1]==22 && out[2]==32 && out[7]<=32);
+  assert(words==10+out[7]*22);
+  for(uint64_t n=0;n<out[7];n++) {
+    const uint64_t *row=out+10+n*22;
+    assert(row[0]==out[6]+n && row[8]==64 && row[18]==0 && row[19]==1);
+    assert(row[3]>=row[1] && row[4]>=row[2]);
+    assert(row[10]==2 && row[11]==1 && row[12]==0 && row[14]==1);
+  }
+  if(out[5])assert(out[4] && out[3]==out[4]+4 && out[7]==21);
+}
+static void *reader(void *unused) {
+  (void)unused;uint64_t out[714];
+  barrier_wait();
+  while(!atomic_load(&done)) {
+    unsigned words=audio_diagnostic_snapshot(engine,out,714);reader_attempts++;
+    if(words) {validate(out,words);reader_successes++;if(!out[5]){accepted_unfrozen++;if(out[3]>32)accepted_wrapped_unfrozen++;}}else reader_unavailable++;
+  }
+  unsigned words=audio_diagnostic_snapshot(engine,out,714);assert(words);validate(out,words);
+  return NULL;
+}
+int main(void) {
+  alarm(15);engine=audio_create();assert(engine);
+  float pcm[1024];for(unsigned i=0;i<1024;i++)pcm[i]=(float)(i%31)/31.f;
+  const float *p[]={pcm};unsigned lengths[]={1024};float output[64];struct pa_time t={0,1,2};
+  assert(audio_publish_bank(engine,p,lengths,1,1));assert(audio_command(engine,1,0,-1,0,.25f,1,1,0)==2);assert(audio_prepare(engine));
+  pthread_t thread;assert(pthread_create(&thread,NULL,reader,NULL)==0);
+  barrier_wait();
+  for(unsigned n=0;n<100000;n++){assert(audio_callback(NULL,output,64,&t,n==99990?4:0,engine)==0);if(n%128==0)sched_yield();}
+  // Test-only additional postfreeze yields; prefreeze writer also yields every128 calls.
+  for(unsigned n=0;n<1000;n++){assert(audio_callback(NULL,output,64,&t,0,engine)==0);sched_yield();}
+  atomic_store(&done,1);assert(pthread_join(thread,NULL)==0);assert(reader_attempts>0 && reader_successes>0 && accepted_unfrozen>0 && accepted_wrapped_unfrozen>0);
+  uint64_t out[714];assert(audio_diagnostic_snapshot(engine,out,714)==472);assert(out[3]==99995 && out[4]==99991 && out[5]==1);
+  assert(engine->underflows==1 && atomic_load(&engine->diag_abort_count)==0 && atomic_load(&engine->diag_clock_errors)==0);
+  printf("{\"attempts\":%llu,\"accepted\":%llu,\"boundedUnavailable\":%llu,\"joined\":true}\n",(unsigned long long)reader_attempts,(unsigned long long)reader_successes,(unsigned long long)reader_unavailable);
+  printf("{\"acceptedUnfrozen\":%llu,\"acceptedWrappedUnfrozen\":%llu}\n",(unsigned long long)accepted_unfrozen,(unsigned long long)accepted_wrapped_unfrozen);
+  assert(pthread_cond_destroy(&barrier_cond)==0);assert(pthread_mutex_destroy(&barrier_mutex)==0);audio_destroy(engine);alarm(0);return 0;
+}

openpilot/starpilot/audio/tests/test_native_diagnostics.py

@@ -0,0 +1,14 @@
+"""Native ring wrap/freeze/faults and concurrent snapshots; no output device needed."""
+from pathlib import Path
+import subprocess
+
+import pytest
+
+
+@pytest.mark.parametrize('name', ('test_diagnostic', 'test_diagnostic_concurrent'))
+def test_native_diagnostic_contract(tmp_path, name):
+  source = Path(__file__).with_name('native') / (name + '.c')
+  executable = tmp_path / name
+  subprocess.run(['cc', '-std=c11', '-O2', '-Wall', '-Wextra', '-Werror', '-pthread', str(source),
+                  '-o', str(executable)], check=True, capture_output=True, timeout=15)
+  subprocess.run([str(executable)], check=True, capture_output=True, timeout=20)

openpilot/starpilot/audio/tests/test_native_timing_report.py

@@ -0,0 +1,146 @@
+from types import SimpleNamespace
+from unittest.mock import patch
+
+from openpilot.starpilot.audio.native_playback import NativePlayback
+
+
+def playback(*, frozen=1, count=21, words=None, underflows=1, clock_errors=0):
+  obj = NativePlayback.__new__(NativePlayback)
+  obj.owner = SimpleNamespace(output_underflow_count=underflows)
+  obj.timing_reported = False
+  obj.handle, obj.rate, obj.buffer = 1, 48000, 4096
+  calls = []
+  def read(handle, values, capacity):
+    calls.append((handle, capacity))
+    header = (1, 22, 32, 25, 21, frozen, 5, count, 0, clock_errors)
+    for index, value in enumerate(header):
+      values[index] = value
+    for row in range(min(count, 32)):
+      values[10 + row * 22] = 5 + row
+    return 10 + 22 * count if words is None else words
+  obj.timing_getter = read
+  return obj, calls
+
+
+def test_healthy_or_old_native_library_does_not_poll_or_log():
+  obj, calls = playback(underflows=0)
+  with patch('openpilot.common.swaglog.cloudlog.error') as error:
+    obj.report_underflow_timing()
+    obj.owner.output_underflow_count = 1
+    obj.timing_getter = None
+    obj.report_underflow_timing()
+  assert not calls
+  error.assert_not_called()
+
+
+def test_waits_for_recovery_then_logs_one_bounded_trace():
+  obj, calls = playback(frozen=0)
+  with patch('openpilot.common.swaglog.cloudlog.error') as error:
+    obj.report_underflow_timing()
+    error.assert_not_called()
+    assert not obj.timing_reported
+    obj.timing_getter = playback()[0].timing_getter
+    obj.report_underflow_timing()
+    obj.report_underflow_timing()
+  assert len(calls) == 1
+  error.assert_called_once()
+  trace = error.call_args.args[0]
+  assert trace['event'] == 'soundd_underflow_timing' and trace['schema'] == 1
+  assert trace['sample_rate'] == 48000 and trace['block_frames'] == 4096
+  assert len(trace['columns']) == 22 and trace['columns'][1:5] == ('entry_mono_ns', 'entry_cpu_ns', 'exit_mono_ns', 'exit_cpu_ns')
+  assert len(trace['header_columns']) == 10 and trace['header_columns'][8] == 'callback_aborts'
+  assert trace['header'] == [1, 22, 32, 25, 21, 1, 5, 21, 0, 0]
+  assert len(trace['rows']) == 21 and all(len(row) == 22 for row in trace['rows'])
+  assert [row[0] for row in trace['rows']] == list(range(5, 26))
+
+
+def test_unavailable_snapshot_retries_and_clock_errors_remain_explicit():
+  obj, calls = playback(words=0)
+  with patch('openpilot.common.swaglog.cloudlog.error') as error:
+    obj.report_underflow_timing()
+    assert not obj.timing_reported
+    obj.timing_getter = playback(clock_errors=3)[0].timing_getter
+    obj.report_underflow_timing()
+  assert len(calls) == 1
+  assert error.call_args.args[0]['header'][9] == 3
+
+
+def test_invalid_native_metadata_is_an_error_without_unbounded_rows():
+  for count, words in ((33, 736), (21, 999)):
+    obj, _ = playback(count=count, words=words)
+    with patch('openpilot.common.swaglog.cloudlog.error') as error:
+      obj.report_underflow_timing()
+      obj.report_underflow_timing()
+    error.assert_called_once_with({'event': 'soundd_underflow_timing', 'error': 'invalid_native_diagnostic'})
+
+
+def test_closing_stream_preserves_partial_underflow_trace():
+  obj, _ = playback(frozen=0)
+  with patch('openpilot.common.swaglog.cloudlog.error') as error:
+    obj.report_underflow_timing(closing=True)
+  error.assert_called_once()
+  assert error.call_args.args[0]['header'][5] == 0
+  assert error.call_args.args[0]['rows']
+
+
+def test_closing_stream_reports_native_abort_without_claiming_an_underflow():
+  obj, _ = playback(frozen=0, underflows=0)
+  read = obj.timing_getter
+  def aborted(handle, values, capacity):
+    words = read(handle, values, capacity)
+    values[4], values[8] = 0, 1
+    return words
+  obj.timing_getter = aborted
+  with patch('openpilot.common.swaglog.cloudlog.error') as error:
+    obj.report_underflow_timing(closing=True)
+  header = error.call_args.args[0]['header']
+  assert header[4] == 0 and header[8] == 1
+
+
+def test_compiled_native_trace_reaches_service_logger_with_exact_pcm(tmp_path):
+  import ctypes
+  import subprocess
+  from pathlib import Path
+
+  source = Path(__file__).parents[1] / 'native/audio_mixer.c'
+  library = tmp_path / 'mixer.so'
+  subprocess.run(['cc', '-std=c11', '-O2', '-shared', '-fPIC', str(source), '-o', str(library)],
+                 check=True, capture_output=True, timeout=15)
+  lib = ctypes.CDLL(str(library))
+  lib.audio_create.restype = ctypes.c_void_p
+  lib.audio_destroy.argtypes = [ctypes.c_void_p]
+  lib.audio_callback_address.restype = ctypes.c_size_t
+  lib.audio_publish_bank.argtypes = [ctypes.c_void_p, ctypes.POINTER(ctypes.POINTER(ctypes.c_float)),
+                                    ctypes.POINTER(ctypes.c_uint), ctypes.c_uint, ctypes.c_uint64]
+  lib.audio_command.argtypes = [ctypes.c_void_p, ctypes.c_uint, ctypes.c_uint, ctypes.c_int, ctypes.c_int,
+                               ctypes.c_float, ctypes.c_uint64, ctypes.c_uint64, ctypes.c_uint64]
+  lib.audio_prepare.argtypes = [ctypes.c_void_p]
+  lib.audio_diagnostic_snapshot.argtypes = [ctypes.c_void_p, ctypes.POINTER(ctypes.c_uint64), ctypes.c_uint]
+  lib.audio_diagnostic_snapshot.restype = ctypes.c_uint
+  obj, _ = playback()
+  obj.handle = lib.audio_create()
+  assert obj.handle
+  obj.timing_getter = lib.audio_diagnostic_snapshot
+  samples = (ctypes.c_float * 4)(.25, -.5, .75, -1.)
+  bank = (ctypes.POINTER(ctypes.c_float) * 1)(samples)
+  lengths = (ctypes.c_uint * 1)(4)
+  output = (ctypes.c_float * 4)()
+  callback = ctypes.CFUNCTYPE(ctypes.c_int, ctypes.c_void_p, ctypes.c_void_p, ctypes.c_ulong,
+                             ctypes.c_void_p, ctypes.c_ulong, ctypes.c_void_p)(lib.audio_callback_address())
+  try:
+    assert lib.audio_publish_bank(obj.handle, bank, lengths, 1, 1)
+    assert lib.audio_command(obj.handle, 1, 0, -1, 0, .5, 1, 1, 0)
+    assert lib.audio_prepare(obj.handle)
+    with patch('openpilot.common.swaglog.cloudlog.error') as error:
+      for index in range(25):
+        assert callback(None, output, 4, None, 4 if index == 20 else 0, obj.handle) == 0
+        assert list(output) == [.125, -.25, .375, -.5]
+        obj.report_underflow_timing()
+      obj.report_underflow_timing()
+    error.assert_called_once()
+    trace = error.call_args.args[0]
+    assert trace['header'][:8] == [1, 22, 32, 25, 21, 1, 5, 21]
+    assert trace['rows'][16][9] == 4 and trace['rows'][16][16] == 1
+    assert all(row[19] == 0 for row in trace['rows'])  # Missing host clock metadata remains explicit.
+  finally:
+    lib.audio_destroy(obj.handle)

prebuilt.json

@@ -1 +1 @@
-{"protected_inventory_sha256": "e34dc5ce97408242abb88bb2622d2e6818238101b65cbc8a64e640118694c8a2", "schema_version": 1}
+{"protected_inventory_sha256": "82d25db7fd74f13c48363100d4e16fd4936a1e1c05da3241b2c8d019f6ef5ef0", "schema_version": 1}