Re: MSI interrupt for xhci still lost on 5.6-rc6 after cpu hotplug

From: Mathias Nyman
Date: Mon Mar 23 2020 - 05:40:05 EST


On 20.3.2020 11.52, Thomas Gleixner wrote:
> Mathias,
>
> Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx> writes:
>> I can reproduce the lost MSI interrupt issue on 5.6-rc6 which includes
>> the "Plug non-maskable MSI affinity race" patch.
>>
>> I can see this on a couple platforms, I'm running a script that first generates
>> a lot of usb traffic, and then in a busyloop sets irq affinity and turns off
>> and on cpus:
>>
>> for i in 1 3 5 7; do
>> echo "1" > /sys/devices/system/cpu/cpu$i/online
>> done
>> echo "A" > "/proc/irq/*/smp_affinity"
>> echo "A" > "/proc/irq/*/smp_affinity"
>> echo "F" > "/proc/irq/*/smp_affinity"
>> for i in 1 3 5 7; do
>> echo "0" > /sys/devices/system/cpu/cpu$i/online
>> done
>> trace snippet:
>> <idle>-0 [001] d.h. 129.676900: xhci_irq: xhci irq
>> <idle>-0 [001] d.h. 129.677507: xhci_irq: xhci irq
>> <idle>-0 [001] d.h. 129.677556: xhci_irq: xhci irq
>> <idle>-0 [001] d.h. 129.677647: xhci_irq: xhci irq
>> <...>-14 [001] d..1 129.679802: msi_set_affinity: direct update msi 122, vector 33 -> 33, apicid: 2 -> 6
>
> Looks like a regular affinity setting in interrupt context, but I can't
> make sense of the time stamps

I think so, everything worked normally after this one still.

>
>> <idle>-0 [003] d.h. 129.682639: xhci_irq: xhci irq
>> <idle>-0 [003] d.h. 129.702380: xhci_irq: xhci irq
>> <idle>-0 [003] d.h. 129.702493: xhci_irq: xhci irq
>> migration/3-24 [003] d..1 129.703150: msi_set_affinity: direct update msi 122, vector 33 -> 33, apicid: 6 -> 0
>
> So this is a CPU offline operation and after that irq 122 is silent, right?

Yes, after this irq 122 was silent.

>
>> kworker/0:0-5 [000] d.h. 131.328790: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>> kworker/0:0-5 [000] d.h. 133.312704: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>> kworker/0:0-5 [000] d.h. 135.360786: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>> <idle>-0 [000] d.h. 137.344694: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>> kworker/0:0-5 [000] d.h. 139.128679: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>> kworker/0:0-5 [000] d.h. 141.312686: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>> kworker/0:0-5 [000] d.h. 143.360703: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>> kworker/0:0-5 [000] d.h. 145.344791: msi_set_affinity: direct update msi 121, vector 34 -> 34, apicid: 0 -> 0
>
> That kworker context looks fishy. Can you please enable stacktraces in
> the tracer so I can see the call chains leading to this? OTOH that's irq
> 121 not 122. Anyway moar information is always useful.
>
> And please add the patch below.
>

Full function trace with patch is huge, can be found compressed at

https://drive.google.com/drive/folders/19AFZe32DYk4Kzxi8VYv-OWmNOCyIY6M5?usp=sharing

xhci_traces.tgz contains:
trace_full: full function trace.
trace: timestamp ~48.29 to ~48.93 of trace above, section with last xhci irq
trace_prink_only: only trace_printk() of "trace" above

This time xhci interrupts stopped after
migration/3-24 [003] d..1 48.530271: msi_set_affinity: twostep update msi, irq 122, vector 33 -> 34, apicid: 6 -> 4

Thanks
-Mathias