On Fri, Dec 06, 2024 at 03:07:10PM -0800, Linus Torvalds wrote: > So I'm not sure if this is new or not, but I *think* I would have > noticed it earlier. > > On my Ampere Altra (128-core arm64 system), I started seeing 'top' > claiming a load average of roughly 2.3 even when idle, and it seems to > be all due to this: > > $ ps ax | grep ' [DR] ' > 869 ? D 0:00 [kworker/24:1+usb_hub_wq] > 1900 ? D 0:00 [kworker/24:7+pm] > > where sometimes there are multiple of those 'pm' workers. > > Doing a sysrq-w, I get this: > > task:kworker/24:3 state:D stack:0 pid:1308 tgid:1308 ppid:2 > flags:0x00000008 > Workqueue: pm pm_runtime_work > Call trace: > __switch_to+0xf4/0x168 (T) > __schedule+0x248/0x648 > schedule+0x3c/0xe0 > usleep_range_state+0x118/0x150 > xhci_hub_control+0xe80/0x1090 > rh_call_control+0x274/0x7a0 > usb_hcd_submit_urb+0x13c/0x3a0 > usb_submit_urb+0x1c8/0x600 > usb_start_wait_urb+0x7c/0x180 > usb_control_msg+0xcc/0x150 > usb_port_suspend+0x414/0x510 > usb_generic_driver_suspend+0x68/0x90 > usb_suspend_both+0x1c8/0x290 > usb_runtime_suspend+0x3c/0xb0 > __rpm_callback+0x50/0x1f0 > rpm_callback+0x70/0x88 > rpm_suspend+0xe8/0x5a8 > __pm_runtime_suspend+0x4c/0x130 > usb_runtime_idle+0x48/0x68 > rpm_idle+0xa4/0x358 > pm_runtime_work+0xb0/0xe0 > > task:kworker/24:7 state:D stack:0 pid:1900 tgid:1900 ppid:2 > flags:0x00000208 > Workqueue: pm pm_runtime_work > Call trace: > __switch_to+0xf4/0x168 (T) > __schedule+0x248/0x648 > schedule+0x3c/0xe0 > usleep_range_state+0x118/0x150 > xhci_hub_control+0xe80/0x1090 > rh_call_control+0x274/0x7a0 > usb_hcd_submit_urb+0x13c/0x3a0 > usb_submit_urb+0x1c8/0x600 > usb_start_wait_urb+0x7c/0x180 > usb_control_msg+0xcc/0x150 > usb_port_suspend+0x414/0x510 > usb_generic_driver_suspend+0x68/0x90 > usb_suspend_both+0x1c8/0x290 > usb_runtime_suspend+0x3c/0xb0 > __rpm_callback+0x50/0x1f0 > rpm_callback+0x70/0x88 > rpm_suspend+0xe8/0x5a8 > __pm_runtime_suspend+0x4c/0x130 > > so it seems to be all in that xhci_hub_control() path. I'm not seeing > anything that has changed in the xhci driver in this merge window, so > maybe this goes back further, and I just haven't noticed this odd load > average issue before. > > The call trace for the usb_hub_wq seems a lot less stable, but I've > seen backtraces like > > task:kworker/24:1 state:D stack:0 pid:869 tgid:869 ppid:2 > flags:0x00000008 > Workqueue: usb_hub_wq hub_event > Call trace: > __switch_to+0xf4/0x168 (T) > __schedule+0x248/0x648 > schedule+0x3c/0xe0 > schedule_preempt_disabled+0x2c/0x50 > __mutex_lock.constprop.0+0x478/0x968 > __mutex_lock_slowpath+0x1c/0x38 > mutex_lock+0x6c/0x88 > hub_event+0x144/0x4a0 > process_one_work+0x170/0x408 > worker_thread+0x2cc/0x400 > kthread+0xf4/0x108 > ret_from_fork+0x10/0x20 > > But also just > > Workqueue: usb_hub_wq hub_event > Call trace: > __switch_to+0xf4/0x168 (T) > usb_control_msg+0xcc/0x150 > > or > > Workqueue: usb_hub_wq hub_event > Call trace: > __switch_to+0xf4/0x168 (T) > __schedule+0x248/0x648 > schedule+0x3c/0xe0 > schedule_timeout+0x94/0x120 > msleep+0x30/0x50 > > so at a guess it's just some interaction with that 'pm' workqueue. > > I did a reboot just to verify that yes, it happened again after a > fresh boot. So it is at least *somewhat* consistently repeatable, > although I wouldn't be surprised if it's some kind of timing-dependent > race condition that just happens to trigger on this machine. > > I could try to see if it's so consistent that I could bisect it, but > before I start doing that, maybe just the backtraces makes somebody go > "Ahh, that smells like XYZ".. > > Hmm? In the past (not recently) I have seen the system get into a loop, repeatedly suspending and resuming some device over and over. What do you get if you enable dynamic debugging for usbcore? Alan Stern
