On 8/19/24 15:38, Mathias Nyman wrote:
On 18.8.2024 23.56, FPS wrote:
Hi!
Here's another observation: When I run the audio interface with 2
periods of 48 frames at 48000 Hz sampling rate I get constant Xruns from
jack of about 0.004-0.008 ms. It seems that the xHCI is not willing to
deliver all microframes in a timely manner but somehow wants a minimum
time interval of 1 ms between them (I read the term interrupt moderation
somewhere on the web - but I don't know if the linux xhci driver does
something like that at all.)
The default interrupt moderation is 1ms for xHC hardware, but the xhci
PCI driver should set it to 40 microseconds.
Interupt moderation value can be checked from debugfs:
# mount -t debugfs none /sys/kernel/debug/
# cat /sys/kernel/debug/usb/xhci/0000:00:14.0/reg-runtime
MFINDEX = 0x00002570
IR0_IMAN = 0x00000002
IR0_IMOD = 0x000000a0
IR0_ERSTSZ = 0x00000002
IR0_ERSTBA_LOW = 0x05069000
IR0_ERSTBA_HIGH = 0x00000001
IR0_ERDP_LOW = 0x05067b80
IR0_ERDP_HIGH = 0x00000001
IR0_IMOD shows the interrupt moderation value in 250 nanosecond steps.
i.e. 0xa0 is 160 * 250ns => 40000ns
Hi! Thanks for your reply! I checked. It's 40 microseconds for this xhci:
# cat /sys/kernel/debug/usb/xhci/0000\:00\:14.0/reg-runtime
MFINDEX = 0x00001b55
IR0_IMAN = 0x00000002
IR0_IMOD = 0x000000a0
IR0_ERSTSZ = 0x00000001
IR0_ERSTBA_LOW = 0x02c00000
IR0_ERSTBA_HIGH = 0x00000001
IR0_ERDP_LOW = 0x02c01570
IR0_ERDP_HIGH = 0x00000001
How could I debug this further? All help appreciated :)
Was looking at a similar issue which turned out to be wifi driver debug
blocking softirqs for a long time. This caused the the URBs that were given
back to audio class driver in a tasklet (softirq) context to be delayed.
This changed recently a bit. USB core now uses workqueues instead of
tasklets,
but issue could be similar.
I'm not familiar with cyclictest. I was debugging using ftrace myslelf.
maybe ftrace preemptoff could show if something is blocking for a long
time?
echo preemptoff > /sys/kernel/debug/tracing/current_tracer
I will have to look into enabling this tracer on my kernel first. I'll
come back to it. Thanks for the tip!
xhci dynamic debug could show if xHC controller has any issues processing
TRBs on ring buffer in time. This debug should be limited to
handle_tx_event()
as dynamic debug causes some delays itself.
If there are any issues on xHC side it should print underrun/overrun, or
miss
service interval errors.
OK, I read up a little on dynamic debug and performed:
[root@ogfx97:/sys/kernel/debug]# echo "func handle_tx_event +p" >
dynamic_debug/control
which then gives me this log output (snipped - it merrily continues on
like this) upon running jackd with a period size of 48 and 2 periods at
48000 Hz:
Aug 19 22:06:34.029680 ogfx97 kernel: xhci_hcd 0000:00:14.0: Stopped on
Transfer TRB for slot 18 ep 4
Aug 19 22:06:34.029990 ogfx97 kernel: xhci_hcd 0000:00:14.0: Stopped on
Transfer TRB for slot 18 ep 1
Aug 19 22:06:34.034685 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.035034 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.035272 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.035403 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.035545 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.035682 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.035821 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.035958 ogfx97 kernel: xhci_hcd 0000:00:14.0: underrun
event on endpoint
Aug 19 22:06:34.036080 ogfx97 kernel: xhci_hcd 0000:00:14.0: Underrun
Event for slot 18 ep 1 still with TDs queued?
Aug 19 22:06:34.036192 ogfx97 kernel: xhci_hcd 0000:00:14.0: WARN Event
TRB for slot 18 ep 1 with no TDs queued?
Aug 19 22:06:34.036309 ogfx97 kernel: xhci_hcd 0000:00:14.0: td_list is
empty while skip flag set. Clear skip flag for slot 18 ep 1.
Aug 19 22:06:34.036424 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 4, set skip flag
Aug 19 22:06:34.036539 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 4, set skip flag
Aug 19 22:06:34.036648 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 4, set skip flag
Aug 19 22:06:34.036794 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 4, set skip flag
Aug 19 22:06:34.036911 ogfx97 kernel: xhci_hcd 0000:00:14.0: Found td.
Clear skip flag for slot 18 ep 4.
Aug 19 22:06:34.042676 ogfx97 kernel: xhci_hcd 0000:00:14.0: Stopped on
Transfer TRB for slot 18 ep 4
Aug 19 22:06:34.042909 ogfx97 kernel: xhci_hcd 0000:00:14.0: Stopped on
Transfer TRB for slot 18 ep 1
Aug 19 22:06:34.048684 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.048927 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.049045 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.049158 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.049269 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.049379 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.049484 ogfx97 kernel: xhci_hcd 0000:00:14.0: Miss
service interval error for slot 18 ep 1, set skip flag
Aug 19 22:06:34.049595 ogfx97 kernel: xhci_hcd 0000:00:14.0: underrun
event on endpoint
Aug 19 22:06:34.049722 ogfx97 kernel: xhci_hcd 0000:00:14.0: Underrun
Event for slot 18 ep 1 still with TDs queued?
Aug 19 22:06:34.049833 ogfx97 kernel: xhci_hcd 0000:00:14.0: WARN Event
TRB for slot 18 ep 1 with no TDs queued?
Aug 19 22:06:34.049944 ogfx97 kernel: xhci_hcd 0000:00:14.0: td_list is
empty while skip flag set. Clear skip flag for slot 18 ep 1.
I have to note that these "WARN Event TRB for slot 18 ep 1 with no TDs
queued?" were there before enabling this dynamic debug feature, I just
forgot to mention them in my original mail.
So does this actually point to the xHCI?
And sorry for the newline-wrapped lines. I'll try and see if I can teach
my email client not to do that ;)
Kind regards,
FPS
