From c12afe13e705244e15a05abc5aa1d8a05d9ceb35 Mon Sep 17 00:00:00 2001 From: firestar5683 <168790843+firestar5683@users.noreply.github.com> Date: Sat, 24 Oct 2026 21:46:43 -0500 Subject: [PATCH] Capture native audio callback timing --- openpilot/selfdrive/ui/soundd.py | 6 +- .../starpilot/audio/native/audio_mixer.c | 73 ++++++++- .../starpilot/audio/native/libaudio_mixer.so | Bin 79264 -> 84040 bytes openpilot/starpilot/audio/native_playback.py | 34 ++++ .../audio/tests/native/test_diagnostic.c | 48 ++++++ .../tests/native/test_diagnostic_concurrent.c | 58 +++++++ .../audio/tests/test_native_diagnostics.py | 14 ++ .../audio/tests/test_native_timing_report.py | 146 ++++++++++++++++++ prebuilt.json | 2 +- 9 files changed, 376 insertions(+), 5 deletions(-) create mode 100644 openpilot/starpilot/audio/tests/native/test_diagnostic.c create mode 100644 openpilot/starpilot/audio/tests/native/test_diagnostic_concurrent.c create mode 100644 openpilot/starpilot/audio/tests/test_native_diagnostics.py create mode 100644 openpilot/starpilot/audio/tests/test_native_timing_report.py diff --git a/openpilot/selfdrive/ui/soundd.py b/openpilot/selfdrive/ui/soundd.py index fe4d8058f9..75dc46f8b8 100644 --- a/openpilot/selfdrive/ui/soundd.py +++ b/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(): diff --git a/openpilot/starpilot/audio/native/audio_mixer.c b/openpilot/starpilot/audio/native/audio_mixer.c index f1cae365a0..9c1b86af6f 100644 --- a/openpilot/starpilot/audio/native/audio_mixer.c +++ b/openpilot/starpilot/audio/native/audio_mixer.c @@ -6,6 +6,11 @@ #include #include #include +#include + +#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;ipcm[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;idiag_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 || capacitydiag_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;rowdiag_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 && writtenloops<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; } diff --git a/openpilot/starpilot/audio/native/libaudio_mixer.so b/openpilot/starpilot/audio/native/libaudio_mixer.so index a5c890f0d14168c04db0bf1fe9232efdd6a851b3..b56c2653070c63be352568e1cafbb237bfc0f7c5 100755 GIT binary patch literal 84040 zcmeHvdwf*Ywf{bI&Y4Fhk4ea5@*+ccg#ZcRA)p|`I|-nO!Gc95lVl(RNhT%}1Yd-R zN+oSG1uIoFsnQlGZF9ZpEmB$|<#&H+>+OwK>P=g&Mt}4+3T>lCn<$vyckQzeOoq^F z@9pRJ`{x{7XRW>V+H0@<-LEs}?6`aR>J=tQV)`YsAF*pG#@r&KaM3lbo6Tbu*Xj(<@!areo;>6-6Bk#TQxUK z0VnDb`H_5ru+ur&(zW*Y!3vUlQ+e__epXX6o$KZ9Ksk!@^Ii^NxK7k}BV2L>9y%Az z;cZKV4;i%bw)O1r(vxeBU3u+{vbk|r^Ka9y-1R~8JgS27V?pG`0&=s`Mgnw?^n|1I z%hGbnO8_N-I+woldc~&x=51e*CL~?_#j~INa>~H@^(UY8@BCK&@x&i5|D4!>Zh`JEG3CzwKV>E?Z z=zT)JHcC_E2>r`K-x94U`h~t(=-1jch2Dv~guYSu$q@EYA|7|VrV#EJ`J;GTahl#G z#_3JMzCT&h_aaT#dJx&Wg@1imJSX(EA|98p|DDh~gn!+hc|2RI12vxdptmmQ@i0$O z$r?|Eug6{zu*c+0AMTHfe6p7Nbu&lZ1;x5|INk9iv^`~gq3f2Xg` z<1O=xba|c68}zYqZ&g*GT-ODvs(j@^wx!Oe7c2MHcxoHUs{Hkp!bqe%W!{?YtXeBx z?W-=Y-F4MVb+xyqLN~AT)q3l6cNKo`)|x^~##>uo83^jG;J(aTzTM-k zsHpSR*Ryg2yWO+Z7YzEVeGJvs`*d4i7Hp^&1uJ~@!MeaM!qXS@HtgKttzuRFvhuw8 zK;BJkhWfgEIQ3TL@9@>^$cIsW?XF;Dpk`KH!OZ-6f6zC*77=*2 z`s(wyY^kpGZO!-BpsuPavPD1AWnvOY|EI|kbff>H)n8)wU@YkCr%IV9E+Z*mVgOpNF8v>EB_uyhpCOTyBzNSB4B6Oe8SOD7}!d{{aS=`&&J zu}HrYmd-}nB=P#GEzH#TZ`7WThKHYGF6*6md}^U~xt2-uscpSz54*H-$jw+s-|%n> z>Gbws7`HID6rwWYz!x!gv6Hcqw^3%?g_T2Il!~t6~3Bj{S#rHZ%slN|!92@0QqH9%J9ip+=P9F->p} z9YcG1KrYs}u5^hs|3kZb=*k0Ucz@~fpGSLinRqE|!`r9#HTjVK(6sId{FR~(D{D-! z4zic@{?~oz_L7^0dgZL+?XosTFdGud#;vlBD-Zni7{yPRTM_4nGCSTYTaSN(eCN7{ zo+6&-9(t1aO!v?M;y1a6Ld0)&4}F#Rt?r>O6JO#U+E09id+1BVi`_$y6Ti(p^eFLl z?x9DB-{l_KL;P;{&~DEW# z9G^ZOdsgmlH@kPAiIr5ESjRHZl?P58yBv^?eX`YbY|tYg`}hmWv4PuF-gmZfEHnlF zrbw&<808M!z8v|>V7CMZ)Bky;M~gCy-_Oq z(8fZ!i19sH%H77fDc9b{LL_f{(0#z(smW2jEOgP*nzjo1D8y)I61RzRNulMW!#rO> zyi^LU1kVA{_@!~t3%tU|H;rwqs|PDh?xCX?OO+URd>p|)%?av%ecVxb8aJO}Zj3f= ztfee82JN}i%H~=(VH}&R7ke$N#M;P0HpG&QJZl>Zr4a9AAt&)(7D^({q);MpmlR4P z?w0tNo)4L@qVc%fWV`59sb4Uc5bG3)Vzpgt#2B%;G#kI7=@&`Xi`Y9$tZr>?9F^G* zCD?qb&4=SJn%F_V>>i@|@t&NH`JH~eP?ZLYfR(k>J>-$C7u{GV(;kdI_Ogk+pS)@8 zls;hM#F~;?$%d>cw){X7#g|vY=1A%w8I^i4D=b`4nqf_}tOwjlLey zxEwiOvvOSy)**pBIre*h7RO4kAGTu*=DHisES$njp(v$sojtj69ro44SeFv|6|iZQ zVlTGEqP;4M&x&F9_QtT1Xyi2`uWHybH>Okx{Qz=IqY`Qd|KmgKwc$PN{qH^6`gH6P z_WrNHv(V1(OJ8~VkMQ-!xnF+zW#k{Vvl7I(aE5~o;Y$&c%$P?Jmnooy2e)SLw{aLmh@0Vka>+O9l-u*R)nY~|N`tCEo!kC}=juKk; z*;`#7NST8(O{ymEft)R5Y3$(4CAuDRnXb*$w$WtJjESmr6kh6tc0C|a!=RhvA zgbJEOdOjN}K-=G6$cFy>iYYYiFT*9x+M1M$`I<}PqRZ5{u1IQJ*EZ3bPHDzyKUYKg zm{GA`4KFplcI5#X>#~CNS;abS#(HhRdTu>->3iyvXl9+2hZZ%gbT_U5^jOO#ML`uG9Z4`S`ROlveK8{^IUyjJElmj6{veTVpxW~Vd*i%#A75IiuIdI*=sb`Q{CTKx3T^^b>F{&wR-aIV_8`HD6bTG zgP32|iK)+gGG^b?-$s5TW3#Dlr@Z?`JfkL(eFpMrFMRW};it}gtnCMHV{SYTds@T# zFem*VyI-=}Z2MDf?w2Y*aKChvu{l`d60z6hQraqE-+@kV%a75PN??(7rPcaN;D7ld zJ2n`HIj*wVH196UskwL-=FbOyDv!Nsio#}pfk z4bJsQ_KVrj7kw+^nO~aHR^`gJRlQMZ`?I8|ixlV1f+y0pAx_iohhMkGMD4dubPq|0 zxs=)gUslPv-)~wrzj6y3@?RdFZG-QeZ)QAWy*&KG-5;=*cAJ#>ccFh?#aycVKo0%l zvDT;G!aP2MI^P9m7ZLY1tOZj(diZrFxqtHZHveg69XGaj+mzGq%2Bz+$Xg^OUzCT3 zOZ-g|--l=qqW#BT;~q-FJ~0^Q9-0DO!w$qy!-hUm9CH_-pQZqdZ9CjUB$Le~q^Ult zw^d~Y?#md*S4v-xMyzikzU?L@^mD|wTS~czb-U!wCFUHsW6!zJwJ?lnb!eDG@* z@w|KqYlYXg`+Loc+54vR*)`?y?(a$G$JNN^$Jcmmiy%*^DOa0Ly#3j5i3jB`%C_9M z2Zu|#(P!K0+(Q^E)UMFBIyUqk_W13qg_>Jq|kQsAD7>O417u6ZZd_c zmY70*lC#0#i)4S9DKr&rd;;>eCdick?N!HCQTlmPi1vzYXJC(hBw53;wd>P3_CtM4 z4_wy9F+Jxv<%eISadd3z?qgQWgF?)M`BSXV=yT&;VN1^&PWhqhY;$1iFH=ITGP`#g z=BK|&;rrryDa}tmg?8f^O7k z8ra;6ad-!83&6{=S*Uyo3)P`tE3%c4w`t9>C70joYQ}oqihZFR@?p@Uc(!`C>8kZ+oOhT#J{PAzO=_2 ziX!ob%AqVlr=1?4QuQ?P8J{|O>Z<<52Cwmz7 z6Qmb|o_O0FdKbFg(7BPW1MMGY3B3p1PLdZ}LY3hAycR8%Jr*8EC2&oFz7m+GgC7De z-ZR=-_m6l!`V{HPF)TEUXPQSahG~tQg0aEdV`m|Mwt_i?@>oacnTghtmpLdB4C85@e~6tV)jSIAb#*z37XG-Q{Mu@6VNg`5bvRLD-q zjY7uW9MvXd7vxSMPk@X%7hw&;?>^es`Pxjs9gZR<8)Bm8EX?mA8)D)zVzMD7E+Zxz zGifqnvbltem~3t#BPLs^kP(xuQOJnN)+S`cWa|_%VzM=A{%K7Z5f}9Tzwsh$=vgv6 zF4`0H{n?E*n4YHxZkPCPrvW@q(lhlw^Ws5z=B~n=uEgA8@Z+cX{n=YxTfu1$8@Qc* zN1Zt;U%vL6-7`V{bw7SzJ60^7UyJ?E)z~|a_RoHq<+?6=tTQghTVERLtwP(E}?BkhZf5GLrt{;Teq5o#qe@o*TMR91^hhHo#1F2S~onbpx|2Y9Pm=`67X8^O7J%D7Vu8+lcaxtc=!T%3-};-`v=3r zz@4>yh;rb);17b&zzdR2a5wll@Y25w5BGuBf?o!ATp1oNL_GbU4G(VucMlH_?*p#| zZv$@wKM78kLt{+3e;reHj+N4*v$&4lSD*OP@bCar(;(_=7y5{8iY?s`omqOobWnNH{B`S7QHP?x5&N{` znS{fM&m}+Wj9MF=Rk{Hl&;9z1fA9ItZ-00G&Hq@2hcxm{W1|v%-w&BCYJ(HHW$1r5 zDMrLraWyo`bHi>E>X zFgzU1H3$p56S^ws+UVtJVQh=E>92uc+7z7ylaVm21`OPPH0tUc8XoS2Pr9g&sQ%_p zhlf{_LdO9ZQ!iBsB+j8BG``NlwjH*7oRB>((w~REYZUze^u5r};Fj8r#!NKk#LkPu z!_*HL%Z_JF&q*uZ{0}~kH7nz8AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1 zAYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1AYdS1An^A=V1`Ze zGb2jly&^3M_xA`PQ>5!eI$ESlt(p)c((S35AQCLX3^<@n;!3I~sth||dGp5g+)xguUrw9!b`Q=sKnys!KzPfsUpvF}&FRvhPmMf<~ zvo4sz9t8R-lX!>{%M=otYGUVO86!Q7S0a-<8+S!YP-Kf$c0)GH>0GCprps%QwkhfI z25_rsnqpC{N|Z(6`F8boC0bSFAo616GF660A;QUc52iR5ol zxq0(aSdw!L1j6f21(;|Iy0|u!Q~vQX-b`0Hk!cBN~dccI7>b0 z9H$AL&TLKSa*o%8Zs!Cpr1dx_YC^Abk|y*yCv%+A`<*$OFyQ2Ivy4G!?w_gB%*&}$ zlc=t-OiG=eN>Y|2r55l&##yD*nVRH~QfFzBQ%aq!NiHdM4wtfXq|}=I)Q=8x3d_A6bIoB%V!7ocSp6)Q!gbgZSuRCmu~)L`6k8UJ z;4~LhY?>SsMI)KHm?e4x%j3`|(6CPD(;|aUi!Mo<7S=ull?mDOI3^)kjitn+5TfRr z+pbL*X3pw|QVMw39IDz8lfdRsoa3ZBCbKzI%Q$IWjxOCfh0USnjFU>X3CYyr&Si55 z(s9!IahjKL(p}qi=?mjE$r5`Po5x!hx1P5=lJpD z%#yT$xw-fF39BicQp1)Kz7}VIt>ANssS~Zpkpg9`jx5cST*#LKyXbolCZ)``P_GmW;dDeO$<_XFItt_D&&W1=%jr#7|y8;kz2x zZc4h8>@ToJ?nkwZ+rjpbs9kDKGz2M7!Ma+g>85P!6e-((u>#z3NG8t zHeLj0@|(CXv|41sa)IesGL=eO?y%XNi)Cz^HV1PqwUdx!WqiqAVrt`jndyH`Siv@9 z{n<m0=44}>#Xo__#xUnE(@{~5TTdMZ4$Eo2-53$F0(NxR6k3CLnu4DY|>~RX)F`j)Suu!W%|G1uH{)+C@v}W!+RGvaf(^nl?8n;d+E>+}nwq-77zD1l>t^}Jh?{>P+{{r1_ z_R#&7t#n@yp!>r6aL=OPbElySR+=J3-lwMG5Q#bu8AnT6Tiwi_30t*Rk&toUUlg;=9-nsOMZUmL(fl zI|mubyqUCkNYz`}KRK2ruzw;Kd_2ygyaTot#=UW)XfnnDeC3Gc2>2DOa- zc4CjnlX$jDt`?+{GrNk~@%VSmX91EiDm;-8TgY~gX_8X+NbnPP%}9?3sFUfnO5^Q3 zI3P$RsrE6~D%Gk?6bk!fMBo|+w3Ae{ngF0slH+(pDPs_;UDaT5#=xLx3?=3Pn$)l) zdO3}o+BMU3Ng^*9W_yZu&(V^?y|S(#G77(#G^eWU#g(7Wu?`tcYxXo>S$ z9NDwOf*OA<=Atn?<_Xs{JU!8lhD@5oYnXgJP!v-RRlI(@UhNd>E&>_P$tEWWQ&pA` zL&7u&aU@KK4bRHE-X(Qk{v?bb_ESs=de%-w2$Cdy8XH3l38pEs01{vVxj_w}10Y$- zGR3K5?Z1M|KC&N5nX<|B&leZ``ShKpZs!%~q-o3g#y$TJPiDNC*ZygquX1Y~+?n2f z?4H(lTHpTRuYSGuN2iv5^|=&MP7M6w$A5nQ!K44Wxq9xp%{9rBNLlgByqim3e&J$E z-v;-K?LT$RhEjgHebKSA+a7st&d;WPt@S5A{>nm9?tcE#i?g5DGT2f4(l_t^iM?(G zlu}0SpK_mEc)7&VurO=sGyeP5L8;iDZcJK`dv5>#{%GKv`+iwHVKXV$pHEuz;Rk7V zA6s_*2dAD{`f)A!jLYxn`N_qJ^MCW5H9b9ZT)P#fW=Aob$t`{k%M&G)eW=ckYEsvj zPstmL)%Eh^V)ZMMy;x=D57h!>Og7t3sng9-KT_A5KTy{;sq356wJ1o z6hKfj%_~u;81fobUU@rem)Cq?mgk^!)GBp_*&39KO=~6jref7$-m7M=Rvm?^dzCu9 zNR`*9(^sk~tJKU@MNsSkSKTksJ$|K{33t}ttI{gf93`hTA+b=6S*50-Dp#>OwOIb{ z?o-sPHyA>fx59gr^?PdCBM6{aO)FNj&5x*dlY5M6HaDqJNW?=wu~@}D1*zCaz>3vL z#p;wM)k+qt)YK2vs3LXBDm5SNiZic9QTS+9pao~bvEw}v%F_F#U(dN)&**Mky^4^ zO)sSToiHmYR`2|Oe?P_REk-(Tc$}VX8CuR0aM`_9W@W5{Sh?@iDXQs zG2pX`)y!f{h(~A&$nPO`oBVZnkAuERU3m(sQ|L(fkkn+B`w&w!#1AksNlt)_DOIda zpmFkuI&}}`EGoi)q#j1E7pZZpRcn!&zKZU-G!BYYXR$g1U0bYTp|QhoW0C4yrH)4q z2JHM|brr?B+AP2GFece^Qj?lptWHPd0Ou4rPcffHJy;OrUc?I=zDaPtg@DGAsOCW+ zd@w-YgmR-{8{nQ8u*obZA#NX3t> zz-oat0bu~YjapmtDO{xXsM)I^VQP`$5j7VfQik~v`9*ZpsT=joDTG?|*Rm7Mcc?L| z)x<(IVU-$#IaNqWbuT)RR$uvPjJ_nZ{0Gd!d}z?gi;LA;F)?TatyU*MH_2S2I?xjs zu9)X2yj-2IMs=)0kd%2^Rpt9ldnJjMr%7wn%pYMoQpOr}!H-BGV-3ndd(3E8EOMgF zKQ_yu-No{sF}Sdlpq=u3ELb0D>%!~k7Yv#opfd`%pH&zUO*GRd{_Xb|tO!_r{}o+{ zIo2UzJTCuxy5&>%s$0Z|`u>j5n&nq9V>Y(Z<9)TK@8y~Qe4`27-X zcuz{FObQ-WKIhBKK&`K))?XC}=GO^EqkuKk)cdzWrRh6$i$h^#3PGPYsU(MEFWj$(Gyl&m%jh;J; z?q2RG*|>JO$HQvNtJ#*SfH%m{xC%eQsq+Q>b-oH#9;mMN)>L@vefKi7H`q|mMQ?3w zmEWhS>wE-65ZQrR&z3qbei;kP@&H~Rqn#DLI(WaYo>h74gPtu_-mUe_TjirNu&7{F zfk16N+v@e#==FQZ8S^X&1ga1UIiR3CcX_KC(7<4z+F$M|qf8-_PgddgZspN&VM|@$ zeqW8I3R~M+O*G%dtY7Qu?)*!xS2qbv{ ze+4?A%pYXI9jLt=>Y%@x`V#3HO;NwAo_ferPhCwpFsQGEtrn@j#$R8_d^N$kU7qSd zO+bj{wGGT)Q`->qcq?EUXeg`lvGRsG01{+@h9Kosc*|L>m)D5i2ln;Mx6_YSp)41; zzd#*26$tDg{OaMf!nc!Yt=;MiQZ!=J@KNjWmihHjROj;seSBPb%Dgq(b+xy~Q;TpY zY;CxS)CePO=;#J@zFKb`>M1Yx)e`D_T!~DAp(aotM6X_}J4{($2ZWtV*!3rCcHMXnLDzubOneQs3Z5wVjo0q{hWfhv zDt}piRn?B_=>_w+%s+$WBjK+puWG39vHU=7Fdu{3KOGA|T>x7K6%)DnUTx<6kZG-*TBB+*ONN|2J-29<0F?6}~MVZD-1>WZVrn^w@)@(?(Qt zEjc2ksR58CXsa~js|zOA*EN&}`O-yeAvClQf#qO0(6m{GE^=TBC4(k_7K45cdJXg^ zkb?JKX`ov{n?co}2SEow-vZIsoBT9#1{H!fgBm~& zfto?z0(F2+gU*6p2mKCo7}M$qr~%XG6zFx(UuY@;7iGdcX)ROSYo)cy+D*y}(%M$0 zlF3B{%Rq2wtCDYBVO1IP_ znQm!SdZb>-w4hb#mHH&p!d9hE>X%HnwkrM7pk!Lqstii|OeQyiY%v|-@wA&dz?BYD zze(Dlw8$r9uoH5(g7>RRJ8AEL_Mi-QkhB#-yAIkmSz4#Gk+xiD?}YZKEZwObm3w7r zi_$B1DAIQ2tOA?u!lnc^M`Wo)IYKsDl}6>D0*p!!)Iq)avoclRDR;?;t&3{#G38a* z6L#FGUvuhbaDCbgtJCIAv*>_xYOgA7U`n6bugZ5HuqyrPWmP?3CGoPl&#WGBkl1WK zWOf{Ie(`|yfOY)=>s<$|Ux4-D{@4+G}n$Q(rZkTg((s zi}|pb`s}dzh?)BAi1~z>`s{?c!%ThF0gvc2G|${-mhMKo%;zZLbLK%a#>k-gvL1M& z<*XGMXRQ~k1lJKuyN#gjuyk6eqE1Vfg#ziabXzEpZcC4a0_m~zS}1^COP_@T=(F@& zD1d&;fQ14Wu(2(1>a7_i2R7XODavSti zXVUfh4agd>bXc9EX8DoZVLf3>xjy%R6`4$FvmUid8w@aIua@2m(PCifCyX>|`_7Ka6-<^(rh`A6GttaE9Y;^fq z`+078-ri@YuIsZ8*s1FV?2XaXb&b)@(bRR#(TAd`>kdU9iKebQ65Sq6UDqCcI-2JD z>FBO#KHsCyMbmsg7u_38^Sw9vQZ&u?OVNYTG~WlK_r}nC-y72sL-V~Q=5P$=yK*?@ zXpCtw){~fy7}FAr$(YU<(^3qnnC=+UG7P1do*2_|tqGDZPy%+dC^ zlW|C$j60l+)Zyf|RG@nYH#-}PMc`~~V;rVCH(Lj@_Ec#L`8XeowctEuR%n@bYMEF? zT4H-*u?X}~rccW((K0dBTVhYfO6!%Au?OQYLk`BZ$DzLUfP>KTRVtSp?Wv}( zIx!~V`s2`}k;0d2vF=b6Gm*uGS-L=3%??5kE1~1GL-H$~j?+nCXOqr>VSG6*^Vs&q zx5U$G9DgC6Lg^rm(SADq)p+S{<<=O6Iv3eCG81k6Xg4Mw<>27UQM9&<$S`S zF(`g0@nj;6_;X2ZspP#e`D6;E4<;W;##}mrUZhoqdXqvrl6)dL9t*-(9Uv@;n6fl4 zPb7CFr(CDrsI8_Q$(^H>=}bPG?7Bf2EVr2Dw62^@?n<8YUs;tNuzFzImHcY*l+S0o z8RoAhUr3(zxy|oEi3`b>l4t)dB@Q^t4p?cyyaZTp{+mi#?>Jyxd%!BnpGP zfDby4I%j>Ja^8rR9(A5}Uf$*%b3bPQ2OQeqxLSD7*_N7lqrwN=7>AhODVWGu(V9~ZrO>)?DCI~B?KwwM zPNdMDb0Vc9h4!3|l+!7+=bTPCn?ifeSqwnhb6!p9PN6-d8zYMLo}QHRDYS>2#~7hK z=t4?g3hg0%Dg7z57xkwMrqEtAn9}H^y{OT-&q;gHK4-I&{4_fcJ83UE>}+$ApEhT^ zllG!^XNQygbT~Vmv=?vC2Jh+&fORuAvX;!F zgzM4F?o4dV-I+ZC@1D%_(6e~_4y50T^af!bXep=+R1JCv^kvW?&#kashn`0bYc6JNDpMtXz5Ht*Pcs9KlEqdvp0dFU6aA? z0@Z>Z20aRT9JCA60{R;0Y0!5-1kyi%{tpe)cN&{R+XXclN8$O`%kVpt4b2)YBb5wsl?1T}*8gHE9hPlC6C zz76_5=q1oApi0!!1^yc7KOz4P{QrRH5CNUc+6Vvr;GcnFA*X{Tg64vXK^s6@K=i`l z3D6PHk3qix{X6LQAUaX-WzZiWe+2pjbQvV!<%0^cff7K!gU!vLG{|E?*`O()JkT7_ zLeMRs#h{g-&vD62VqI_udvQhs+2JZ_4D&1?afR-cRx~Z zVfy*~k$NlB&-stk+gK@%okU(Ti(-wV>g_nz6={uQ8hC%H|6N3QuFPUscWSsslVz+n zy`$>m*irotC&G%!I4G?Dokf@$^~N*(?<+>?6WC~f4`Y*O#i!yk@_U2 zpXVQ`PiAXrjfl8poE;zSl9_WfHR2xy1X#-an9ub^WQLk~PXD<4*-fyJQ^x z9_^A@)@W+PAnl3lLUq3!IeKNZvVw`CDIMyD~HA~^= zuf=G;8@`gup&qBP2U zJOMq&P5-3A%U{E-H{$PhPI5mE7O8jha&hc*#QLD=uf@sDaQk=AXn6jf8`!UYQqt|; zgFtcWpO7eSx&}a`*FU+?33s|=&aYqJtk9Fa{;8!+JV($8J8V338*ycDeZ=5|1w8`b z4?;%RQi2ZUVbiADh-)g>yGH0JF@x)`UpMA({q^exZISdhFsq4$U5mIrj=3US(W8lW zEHTU&B0Z|$;O0mrQg=WWlw{pS3se(-`5$_h0yFyn&xX z5q@qofA#pgBkb=*y%LLKk$P(GX!z`gy=jzvmLB_Pyy>`2<9Oj42={;ee5c1kve(-+ zL)f1YdL1|2&u_S&YwH-2{2Ji;_lG0*S#3IBzrQ=MT}mwJ>UtvFunew$e>ieqo(a9_ zhWoFTPspt~oD;-Zes_CAM&TJJUa9>f@arZ4(Gj{ZlH^bbSRpTN6jzk8=AF zDxRRnU-F}Wx^)Yaf4zbI+c(hD-;RyeE)|csy*7=Qrp?$$dWWcF&d?26YY8RrS8< zI873SNX%2|-Qn{<>CwKx*0TvX(o+|#4>oMsg2PETSL562uMhfgoT!>kv((@_vBy&p z@NBILlzFQ>6+s+@@pv0hTcEnO$`|xilUwB?pc1@G8~lRjYMO_ zw|fuD6nMPl_u@cF6~R&;0OU0lIHz;XhI^YAW))U=H1&0T=2^D!w#93Tmcr-C+tz!Q z7mAPym#u@UWX)1NxRtAKU$S_$=k^sV?p$8tDOtQ^^>TzvV6$ppb$RVB_sZ2pOO|?O z<`v9ko}!X9o@)aDZm9c9ymZJ&>y8R>W=5p0ozb~^90w<$c6tdDZxxQOg?k@yxF|eB zb5<)(18IkZB457%fu#Q7eNXDiM);jjYEpivKbaH0tV7Dt_~FLHz9 zO`5-vN0LT6&=hv+iALx3{;wXoQR}k4Sishk@&*0z#^- z3bH&tV)BA?CMu6+HSz)#-k_J^4=}_$uB<>=J*Ab<=Dt=!m*LopvwEl%hqvgK$1BjB zmEq)89-&U>+43rUWer;~Shoap*;`hIb6R=|$7FoE3>0(`Gxe%WCKw3U(t&auQNsZ* z;k>S9>xeW=J%KG-Fy87%tg-)t1U+6_K-l*9rN3X%x&FILWaC+BK4C0bRJos zp4R!-M0vgcdPRAipAD}Ja%BB&5#{ywaXO!-cf9bU_n%0z;}Bv&x|#mouIGwop~tD) z>*aO+PspH0Z@s+!ey>lI*X?dp{tPl`?C9n7-zWW|d^drMOK-RCPmk-D$RiWIy#BkS zQ@rWQp~7L8US8+j$O|v8zgO%Ncr0viR%4bGtmKFNI z7S1EfTcC*4k?EdjO?xH+ut?i6qI_igm(sTxTY_9XpXC$3K2 zP~=1;@yFn!4DG@6`YSEOz64ayHvV7LSfS3N|Q zzxxK|W9VBJE;@4>enpn2bc6{vcjjr9-Qss-HndwodUxvk0u3*H?DK-+);C`(PoLnz ZugLo8XJmv4H$O*z~qCiBF{a-egt@{7~ delta 8715 zcmbVSdw5jUwO{)@=9Niu=8?=yUNaLy$csE6yul0*Gzka+gFLE+K!7BWha@OcFGG=! zqH=5EKo34@0>(_WT+K+SgIeX}97TYcf&1tTIECzZBz;rM|0LDRbOM&0A+oc+IyIN|p%?+Gd+tzaE zhyEdlS{W-lwNRa*V)n$0A3iW=!B?5?#;6Hj6`ZcGm+7aD{pM7*wR!U`kio2T34}o^V*7ao60LHE4Qp~Yz%!WJ{Ee=5EG(Lb4sObKIkl#4p zqZt*;Kv<2)Frqc|Z^pMHy*~b(8{a?Gaf64Jsi9iau~4o#k)?zdn|C}cITUA^&-r(T$}M@^ zHtyJymeq{&bD>Wo>R8ONd##xqx1EI^i`o;!1e;;!jFw)${9Vc_fR~pGfh$MsPJ5R> z40Hd}o4yR3*aRcf%2~vvWaNuqa6j`OoM+)DT+qC**W!8H%Pf~DtL=G@#noI3oR}Bf zan2NJdE7KUFv>7NFJ+CvOf2s4YOZib)dm=?z8=muWAL;??q^Kb!>Gl6@aE5BYpPFz$)D6)lYa7J z-jY#*#sU@-dcxre=Hn2hi_p^a05(V47sEVU6mvUneE*k6XwguYsB5hvd+;G85w3*7iy-yzg@-uzo%D@s~* z!%HZ^UmTfrBka;wc6kc_&Jf->Qfer}lfzO&t39cqZjTgX@%*e#ybqj+ox|a913s>M zQJ%*75Xyd(xu1u_m&uM&!n?T{-5Xv^BY^TCdUPT;h`q#Zp|s4JSQ_H?3kM88Hp!NQ)~BMLmY%c!#A)GEIIFj` zEDFw@f9Kuz`v3Ij_y1am+Y$Bk0>)U0BSk|>B@Hozddl^1co7jrQNAK;q7UPSRwTwu z-H&Y*p^bX07n zG=tvpE+bjh-Jj$IM=0awef}zeD(cGs$pDQB7HyM*t)Y&aIjlGIr<-2e5WO*A(IP=^ z$Q;gLQfNll%e^m#R)>E&_pE07|H{CDVphgw7!I^D4|m;spobNd@%h-MMO-387zM#9 z3VajRqxd+!5@jTpAp$KYRzDdMi7_ym3s##CNo_a=M%>I5#dI8L&diqb(q2x!ld;+E zDUcv>1(2{7J8d)UMZ1v?KtiQ_h_M~Pso<+ZN)qhgqe$Sifj7nuUZoQI0#dF#69dWZ zpaA&(z>Ttli~s9 znRt%0INaG|H=-8j>4RvuQ;8J~?wGw~jW)Sm!Gnrc1o0F#ffld?iLoYQd^@UIJ(l7N zZb3+*AxNSq@zg)XY`R6afRM#8{x4|DHNF^^%Zx9&vp>O_@kM-Lxr$1T@xCNV(%|vo z$g(AM8Gy6I=Kidtac{kOAb5a zlga2TgejE1G4>9aLZOpyhXoYbHjaWBV*)TuiEc{?E+WEJ1T$&WjP7EXqbz0+$6L|D z>SsaKJ*bRJrKcsUoehgAjhMS&@nnZ6pAguN_Xq3|J&`2@tA0m~Z{LNJUW<}K_JrQDmhaDY%4*$gVlSb1X`vGYb zE}r6RH$vJ#(R)0b>~89A0!IOsndeC0sG z``KMzWv{Q=*o!Q8anHT2AGBV4?RW2#9`9N3#B+T_j<5gq8~;4~@R8r&S37OleRZ+# z5n1`n^qFf;J%6craAn}tuAlk-jwFAotDxg_%_GlEc`NhD);Hhy(WgWP4_|&Y|FI1t z-6baut$s6N%NIzpgp5x!4$R59US`}n$2IVf7lPzH8^sh8Nfr;>$m~Yu7-f8IJ z*OrLO`6T)6NOpMIeI+6@@R_Dg1HZgP%ro%b5(8h+!+U$g2_>T4utdx>^oUR*7M6&- zVWENlUWpjPkC)q{*o@e_uNwHQ9?@)BDBf-`HSu?GrHr2_e-_0`P2IsBiu_x7VKm!6 zF~h(*ELs_TwljbV0Xt=L*wT@SVRQC`1J4!GG4 z`5$h!aN+|Mo42lSgtgU8jqm`}t>4xJ^_wf9err?1)+X4nrJ@$CTN~GJAxduWusFHj z#j=7GO-<`-8=9aA?Hlv^E z^wX9>g^rW3_I$>cop$3;u=E4r?wN3iI{^}fY^t4 z2k}?LH3Xi3K_udCgoKYzdW23u+<~|k(I~)VcodaZ#A}GR5g#BvL5w2o_)LyNlq0qw zo<+Q1IQ~D0Y&Rd=Yhg=;y_T*hwn6BMIvFKA&z80dy-|J9Yy$`b=5`BPCbV0QM6vZM zyPnuK3o8@aEbWo3Qe`WNZMLxGLNocUQ`vRj#dcdhv|xjmEkShN@O5+jL~j&^D8xpU z-3Y?&i2V^nkb57EF@AwNQ51kIT9K6^8X{pds~ z4@M71D;GxxcS>~iPHCTnR}1^3gAzBnRX8ZMOI&`d&@OdJ+>}wZJ0rRygwwbTXb}ur zg??PbxBziJlvz@yi0U6w{kje7`yDhF0}_tgunqgz?0^QkD={V&YU^$UwNrz*AJK?d zk9Zid1F;9ujChJZntp;xD}o*YbmrZS_yyuL;vu}1-$r>3@e$$@g1+RhprrF)dP%aP zPbA8FQPNpL3L+0dr}cQA2!)6xh}DQShz*F%i2D&cg7{}Q;zx)Bh(m~%5XTTbh+iY# zLtI3BhA?0w^z2DSD-e~4Er>q!xef6Uq6zChl)F$qiue(t8F2vd6rv3=vkV(_+`0jlI5 zWHXoNeSK=aHsV_wzD`Q=D`;l9Bw~0I45`Z3zZ_WLtojo|1T=*1=VFSjcnEPz3{B;6 z_t1abxYf$zdvcreRz}r%h?ZM(n2VQSP(FkT8zK?I+o4xxxh#e`WIU#D(JvQr9@gd9 zToxBv%bapyE;}#h<}qK%e%e)TDYU_H_#=SM>+Py;*d@9ZZYe5H9g?5UW7+Aw-(epd z(_ydtgGtPnJ*IWq!Kiip%qK-_DWJ$`xnL4=WyU};I^9}Sa}=y`-O2*Ym-F(Nx1wuI zD~r*KS{ciiYW%<$e>FUg;+SUFY5qQ$O=dBk7%0*la49M!p!}8OoXO1Pz**9MzEF+0 zROMH&Kk~pNW{8gl{YMYo`Z_8MkeBC9VlhG#bUWogPGYI@*~!e8r@wpY-k+dCebV2x zIyJ+v#)It7XO0+h(O*K8Q$RG^<)u?_@wnuceC9GHD9O8IJo|RZ8}gZ5K9Y}z266JQ z@>$OOSXiV5*2PT4AHU>cbVij03XflCW6A>g3PmoR!UVZ{3QI`eIc8-9lnbIDcg$oi zmtUE}ym4LM;a=pDCrxEp2~n_f%!TEc3B!A6r%T>Gm8Ax2vChG_@4-fe$KSuS7P7R= zA5*UX_Vm-yin5Hx_`j_9f3r%ls+2Pde?^`)joE^KRM>Cd@PAjFoL?^`?OM2^UL5WX zD;MfC81YWv;JfZieDaLBA0yG<4j}&ulMuaF@!{jo;hCk--~REkSoTlHC*L~FtiSID zwD#|pe?ASD&LgTgpom0z3e)e1`pfNrmT|Y<8hcA|4ANuxU;W@nr(^%>m(edYUVreW6@Xq%@}r1AQzyH%y3{P-Vc zusG&WzOBmjA3PzYGCNPcIg?F^Y<#exJg+=IyB<)Jm(60ua`!BDB(l7G-L{JI4b^oO zo2$3W&(3Bea>pF@U&lAz#uAvkw}7o-i{y_BSdJ}#{iLGHG&wzhw0>f(%dK)X(fY2W z%WSy=X|seM1ym&YVt`FE=W5kl**_Pn`ib@sRUNodY@N%-S@ef{mr*`Emrb?li$|Aj zp+lTQzCM>F*!3s0E;mQW8S_}SMc>$PKUj-(kJgp1H#U8P>y$eRm^b|(W=ON8yXpI! zEih z0$Mu(`A{L7AijsBN&fdjmKh50g8XoRSv?n!ql9vm3%>bNB>NYz3Buozk(XvOM+6*D z`~b2Ia!r6G3G^zZnckxR3xI`jsww=9=`^03Q~9T;n35x~`mfqM7Nz>#;N*-27(EuN zN^}c!*;LauntyL{GS-L~n{k>$b>o>DVG>rg{4$-Y=?_}!^K_F1uE(jSgP}a$p$v(z zOt<1&LA+{hVsgzLY-)@tQLT?ylum&kMTPv@9W2ufX{zZV`Qtlq!9A3zR@W;@|1Zz- BpF98n diff --git a/openpilot/starpilot/audio/native_playback.py b/openpilot/starpilot/audio/native_playback.py index 33d0eb8190..dc3671befd 100644 --- a/openpilot/starpilot/audio/native_playback.py +++ b/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()) diff --git a/openpilot/starpilot/audio/tests/native/test_diagnostic.c b/openpilot/starpilot/audio/tests/native/test_diagnostic.c new file mode 100644 index 0000000000..00375109d3 --- /dev/null +++ b/openpilot/starpilot/audio/tests/native/test_diagnostic.c @@ -0,0 +1,48 @@ +#define _GNU_SOURCE +#include +#include +#include +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; +} diff --git a/openpilot/starpilot/audio/tests/native/test_diagnostic_concurrent.c b/openpilot/starpilot/audio/tests/native/test_diagnostic_concurrent.c new file mode 100644 index 0000000000..d38d5b642e --- /dev/null +++ b/openpilot/starpilot/audio/tests/native/test_diagnostic_concurrent.c @@ -0,0 +1,58 @@ +#define _GNU_SOURCE +#include +#include +#include +#include +#include +#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=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; +} diff --git a/openpilot/starpilot/audio/tests/test_native_diagnostics.py b/openpilot/starpilot/audio/tests/test_native_diagnostics.py new file mode 100644 index 0000000000..fc5ee21d5a --- /dev/null +++ b/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) diff --git a/openpilot/starpilot/audio/tests/test_native_timing_report.py b/openpilot/starpilot/audio/tests/test_native_timing_report.py new file mode 100644 index 0000000000..ee247c71f9 --- /dev/null +++ b/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) diff --git a/prebuilt.json b/prebuilt.json index e126105566..49b3241455 100644 --- a/prebuilt.json +++ b/prebuilt.json @@ -1 +1 @@ -{"protected_inventory_sha256": "e34dc5ce97408242abb88bb2622d2e6818238101b65cbc8a64e640118694c8a2", "schema_version": 1} +{"protected_inventory_sha256": "82d25db7fd74f13c48363100d4e16fd4936a1e1c05da3241b2c8d019f6ef5ef0", "schema_version": 1}