On 8/23/24 1:43 PM, FPS wrote:
> If possible I'd like to see xhci traces of this issue. Here is a curl'able trace (from running timeout -s KILL 0.1 jackd -R -P 70 -d alsa -d hw:USB -p 48 -n 2 (thanks to Michal for the suggestion)): https://uni-bielefeld.sciebo.de/s/1ixBodEpmSg8M2k/download Or should I include it inline (it's ca. 1M.)
OK, that trace is possibly unnecessarily complex. Maybe it makes sense to look at a more isolated issue first. I mentioned before that just using the capture direction with jackd seems to be fine, but the playback direction is broken. It is broken in a somewhat "weird" way. Jack doesn't report XRuns, but playback is definitely broken (Sound plays back as if there is a zero buffer inserted after every buffer and with ca. half the speed. I ran jackd like this: timeout -s KILL 2 jackd -R -P 70 -d alsa -d hw:USB -p 48 -n 2 -P 2>&1 | logger This gave me (somewhat imprecise) timestamps for the jack output: [119172.966606] arch97 fps[177753]: jackd 0.126.0 [119172.966616] arch97 fps[177753]: Copyright 2001-2009 Paul Davis, Stephane Letz, Jack O'Quinn, Torben Hohn and others. [119172.966619] arch97 fps[177753]: jackd comes with ABSOLUTELY NO WARRANTY [119172.966621] arch97 fps[177753]: This is free software, and you are welcome to redistribute it [119172.966622] arch97 fps[177753]: under certain conditions; see the file COPYING for details [119172.966624] arch97 fps[177753]: [119172.973620] arch97 fps[177753]: no message buffer overruns [119172.975503] arch97 fps[177753]: JACK compiled with System V SHM support. [119172.989889] arch97 fps[177753]: loading driver .. [119172.990672] arch97 fps[177753]: creating alsa driver ... hw:USB|-|48|2|48000|0|0|nomon|swmeter|-|32bit [119172.991245] arch97 fps[177753]: configuring for 48000Hz, period = 48 frames (1.0 ms), buffer = 2 periods [119172.991249] arch97 fps[177753]: ALSA: final selected sample format for playback: 32bit integer little-endian [119172.991252] arch97 fps[177753]: ALSA: use 2 periods for playback [119174.533438] arch97 fps[177753]: delay of 1003.000 usecs exceeds estimated spare time of 966.000; restart ... [119174.533463] arch97 fps[177753]: [119174.536202] arch97 fps[177753]: delay of 1051.000 usecs exceeds estimated spare time of 966.000; restart ... [119174.536222] arch97 fps[177753]: [119174.539134] arch97 fps[177753]: delay of 1060.000 usecs exceeds estimated spare time of 966.000; restart ... [119174.539152] arch97 fps[177753]: [119174.542173] arch97 fps[177753]: delay of 1049.000 usecs exceeds estimated spare time of 966.000; restart ... [119174.542192] arch97 fps[177753]: [119174.545145] arch97 fps[177753]: delay of 1047.000 usecs exceeds estimated spare time of 966.000; restart ... [119174.545164] arch97 fps[177753]: [119174.548423] arch97 fps[177753]: delay of 993.000 usecs exceeds estimated spare time of 966.000; restart ... [119174.548447] arch97 fps[177753]: which continues for a while until jackd is killed.. The timestamps allow us to correlate (again, imprecisely) what's in the trace (curl'able link): https://uni-bielefeld.sciebo.de/s/5gXyqY0cqNrQZdE/download It is quite peculiar. Jack seems to start up fine and is done configuring it's "driver" at 119172.991252 and seems to run fine until 119174.533438 which is ca. 1.5 secs later where weird things start to happen. A delay of 1.003 ms is reported which is just above the 1 ms period duration of 48 samples @ 48000 Hz sampling rate. So the last buffer would have been sent off to the soundcard about 1 ms before this time. Now looking at the trace I noticed a little thing. In the part pf the trace before the excessive delays start I see things like this: irq/125-xhci_hc-169 [003] ..s.3 119173.246016: xhci_ring_ep_doorbell: Ring doorbell for Slot 3 ep1out irq/125-xhci_hc-169 [003] b...3 119173.247898: xhci_handle_event: EVENT: TRB 000000010a3f14d0 status 'Success' len 0 slot 3 ep 2 type 'Transfer Event' flags e:c or irq/125-xhci_hc-169 [003] ..s.3 119173.248024: xhci_ring_ep_doorbell: Ring doorbell for Slot 3 ep1out irq/125-xhci_hc-169 [003] b...3 119173.248883: xhci_handle_event: EVENT: TRB 000000010a3f1560 status 'Success' len 0 slot 3 ep 2 type 'Transfer Event' flags e:c The time between ringing the doorbell and the next xhci_handle_event is mostly below 2 ms. But lateron I see things like this: irq/125-xhci_hc-169 [003] ..s.3 119174.323020: xhci_ring_ep_doorbell: Ring doorbell for Slot 3 ep1out irq/125-xhci_hc-169 [003] b...3 119174.324897: xhci_handle_event: EVENT: TRB 000000010a3f1d30 status 'Success' len 0 slot 3 ep 2 type 'Transfer Event' flags e:C Suddenly this time has jumped to almost 3 ms. I'm still getting my head around the low level USB stuff but possibly this is a hint? Kind regards, FPS
