> >>
> >> On 5/12/2020 8:05 AM, Peter Chen wrote:
> >>> Cc: Baolin Wang <baolin.wang@xxxxxxxxxx> Cc: Mathias Nyman
> >>> <mathias.nyman@xxxxxxxxxxxxxxx> Cc: <stable@xxxxxxxxxxxxxxx>
> >>> Fixes: b0c69b4bace3 ("usb: host: plat: Enable xHCI plat runtime
> >>> PM") Reviewed-by: Peter Chen <peter.chen@xxxxxxx> Signed-off-by:
> >>> Li Jun <jun.li@xxxxxxx> --- drivers/usb/host/xhci-plat.c | 1 + 1
> >>> file changed, 1 insertion(+)
> >>>
> >>> diff --git a/drivers/usb/host/xhci-plat.c
> >>> b/drivers/usb/host/xhci-plat.c index 1d4f6f85f0fe..f38d53528c96
> >>> 100644 --- a/drivers/usb/host/xhci-plat.c +++
> >>> b/drivers/usb/host/xhci-plat.c @@ -362,6 +362,7 @@ static int
> >>> xhci_plat_remove(struct platform_device *dev) struct clk *reg_clk =
> >>> xhci->reg_clk; struct usb_hcd *shared_hcd =
> >>> xhci->shared_hcd;
> >>>
> >>> + pm_runtime_get_sync(&dev->dev);
> >> Where is corresponding _put() call?
> >>
> >
> > At the end of this function, there is a
> > pm_runtime_set_suspended(&dev->dev). Calling
> > pm_runtime_put_sync(&dev->dev) will cause xhci_plat_runtime_suspend is
> > called which is not expected.
> >
> > Peter
> >
>
> This seems odd,
> I don't understand why pm_runtime_set_suspended() would call
> pm_runtime_put_sync()?
> I thought pm_runtime_set_suspended() is used to let pm core know the hardware is
> suspended, and inform the parent of this, possibly allowing parent to runtime
> suspend.
Sorry, I may let you misunderstand. I mean call pm_runtime_set_suspended will
NOT call xhci_plat_runtime_suspend , and only let its parents be runtime suspend.
And if call pm_runtime_put_sync instead of pm_runtime_set_suspended , the
xhci_plat_runtime_suspend is called, although it doesn't cause any issues, but
hcd has been removed at the time, it is should not call xhci_suspend after that.
> Not sure if it's needed in the remove function.
> It makes sense to allow the parent to suspend, but xhci isn't really suspended.
> Yes is stopped, but we can't resume our way back to a active state.
>
> Could it be that the runtime suspend call you are seeing is because we are
> removing all child devices, disconnecting and freeing everything, including roothubs
> and hcd's.
This issue occurs plug out Type-C-to-A cable with USB3 device connected from Type-C
port. From what I see it most probably dues to disconnect event triggers roothub auto-suspend,
and this auto-suspend is async, if it is scheduled later than hcd is removed, this oops occurs.
Below are several logs I capture:
1. whole debug message when this issue occurs:
[ 93.889693] xhci-hcd xhci-hcd.1.auto: remove, state 1
[ 93.889911] xhci-hcd xhci-hcd.1.auto: Port change event, 2-1, id 2, portsc: 0x4202c0
[ 93.894774] xhci-hcd xhci-hcd.1.auto: handle_port_status: starting port polling.
[ 93.894830] xhci-hcd xhci-hcd.1.auto: roothub graceful disconnect
[ 93.894853] usb usb2: USB disconnect, device number 1
[ 93.896876] hub 2-0:1.0: state 0 ports 1 chg 0000 evt 0002
[ 93.899940] usb 2-1: USB disconnect, device number 2
[ 93.904985] usb 2-1: unregistering device
[ 93.904996] usb 2-1: unregistering interface 2-1:1.0
[ 93.954023] usb 2-1: usb_disable_device nuking all URBs
[ 93.954050] xhci-hcd xhci-hcd.1.auto: xhci_drop_endpoint called for udev 00000000e6468cd7
[ 93.954138] xhci-hcd xhci-hcd.1.auto: drop ep 0x81, slot id 1, new drop flags = 0x8, new add flags = 0x0
[ 93.954146] xhci-hcd xhci-hcd.1.auto: xhci_drop_endpoint called for udev 00000000e6468cd7
[ 93.954197] xhci-hcd xhci-hcd.1.auto: drop ep 0x2, slot id 1, new drop flags = 0x18, new add flags = 0x0
[ 93.954652] usb usb2-port1: usb_disconnect: call pm_runtime_put
[ 93.954786] xhci-hcd xhci-hcd.1.auto: // Ding dong!
[ 93.954851] usb usb2: unregistering device
[ 93.954863] usb usb2: unregistering interface 2-0:1.0
[ 93.955252] usb usb2: usb_disable_device nuking all URBs
[ 93.955264] xHCI xhci_drop_endpoint called for root hub
[ 93.955269] xHCI xhci_check_bandwidth called for root hub
[ 93.955901] xhci-hcd xhci-hcd.1.auto: usb_remove_hcd:3016
[ 93.955914] xhci-hcd xhci-hcd.1.auto: USB bus 2 deregistered
[ 93.966119] xhci-hcd xhci-hcd.1.auto: usb_remove_hcd:3037
[ 93.966130] xhci-hcd xhci-hcd.1.auto: remove, state 4
[ 93.971434] xhci-hcd xhci-hcd.1.auto: roothub graceful disconnect
[ 93.971452] usb usb1: USB disconnect, device number 1
[ 93.976783] xhci-hcd xhci-hcd.1.auto: at xhci_plat_runtime_suspend
[ 93.976807] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000240
[ 93.979340] usb usb1: unregistering device
[ 93.985784] usb usb1: unregistering interface 1-0:1.0
[ 93.986064] Mem abort info:
[ 93.989013] ESR = 0x96000004
[ 93.992222] EC = 0x25: DABT (current EL), IL = 32 bits
[ 93.997735] SET = 0, FnV = 0
[ 94.000840] EA = 0, S1PTW = 0
[ 94.004125] Data abort info:
[ 94.007220] ISV = 0, ISS = 0x00000004
[ 94.011255] CM = 0, WnR = 0
[ 94.014424] user pgtable: 4k pages, 48-bit VAs, pgdp=00000008b6dd3000
[ 94.021025] [0000000000000240] pgd=0000000000000000, p4d=0000000000000000
[ 94.028025] Internal error: Oops: 96000004 [#1] PREEMPT SMP
[ 94.033605] Modules linked in:
[ 94.036677] CPU: 0 PID: 121 Comm: kworker/0:2 Not tainted 5.6.0-rc4-next-20200304-03579-gfe93ddfb2c17-dirty #120
[ 94.047102] Hardware name: Freescale i.MX8QXP MEK (DT)
[ 94.052261] Workqueue: pm pm_runtime_work
[ 94.056280] pstate: 60000005 (nZCv daif -PAN -UAO)
[ 94.061080] pc : xhci_suspend+0x30/0x698
[ 94.065013] lr : xhci_plat_runtime_suspend+0x80/0x90
[ 94.069976] sp : ffff80001243bbb0
[ 94.073294] x29: ffff80001243bbb0 x28: ffff800011c56000
[ 94.078611] x27: 0000000000000008 x26: ffff80001243bd38
[ 94.083928] x25: ffff8000101412d8 x24: 0000000000000000
[ 94.089244] x23: 0000000000000000 x22: ffff000837e8e104
[ 94.094562] x21: ffff80001085d058 x20: ffff000836b42000
[ 94.099878] x19: ffff000836b42250 x18: 0000000000000010
[ 94.105194] x17: 0000000000000000 x16: 0000000000000000
[ 94.110512] x15: ffff00083ace0470 x14: 8810000000000000
[ 94.115828] x13: 0000000000001b58 x12: ffff800011ef1000
[ 94.121145] x11: ffff800011c78000 x10: ffff800011ef1360
[ 94.126462] x9 : ffff800010c73d28 x8 : 0000000000000007
[ 94.131778] x7 : 0000000000000531 x6 : ffff800011ef1000
[ 94.137095] x5 : 0000000000000000 x4 : ffff00083f99b1b8
[ 94.142412] x3 : ffff00083f9aa208 x2 : fd7e7f70d3ccaf00
[ 94.147729] x1 : 0000000000000001 x0 : 0000000000000000
[ 94.153044] Call trace:
[ 94.155505] xhci_suspend+0x30/0x698
[ 94.159090] xhci_plat_runtime_suspend+0x80/0x90
[ 94.163722] pm_generic_runtime_suspend+0x30/0x48
[ 94.168437] __rpm_callback+0x90/0x148
[ 94.172189] rpm_callback+0x28/0x88
[ 94.175682] rpm_suspend+0x100/0x5f0
[ 94.179260] rpm_idle+0x28c/0x420
[ 94.182579] pm_runtime_work+0xa0/0xc0
[ 94.186334] process_one_work+0x1c8/0x470
[ 94.190345] worker_thread+0x50/0x428
[ 94.194013] kthread+0xfc/0x128
[ 94.197158] ret_from_fork+0x10/0x18
[ 94.200741] Code: 34001f00 7100101f 54003141 f9400660 (b9424000)
[ 94.206844] ---[ end trace 3ba7d185e60c149e ]---
2 & 3 are related debug message and trace message (I can't get the whole debug message due to
console is stuck when the issue occurs)
2.
soot@imx8qmmek:~# echo 500 > /sys/bus/usb/devices/usb2/power/autosuspend_delay_m
usb/devices/usb2/power/autosuspend_delay_ms[ 206.901805] xhci-hcd xhci-hcd.1.auto: remove, state 1
[ 206.906941] usb usb2: USB disconnect, device number 1ower/autosuspend_delay_ms
[ 206.958838] usb 2-1: USB disconnect, device number 2
[ 206.994172] xhci-hcd xhci-hcd.1.auto: USB bus 2 deregistered
[ 207.000017] xhci-hcd xhci-hcd.1.auto: remove, state 4
[ 207.005213] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000240
[ 207.014082] usb usb1: USB disconnect, device number 1
[ 207.014106] Mem abort info:
[ 207.022005] ESR = 0x96000004
[ 207.025138] EC = 0x25: DABT (current EL), IL = 32 bits
[ 207.030510] SET = 0, FnV = 0
[ 207.033598] EA = 0, S1PTW = 0
[ 207.036777] Data abort info:
[ 207.039699] ISV = 0, ISS = 0x00000004
[ 207.043569] CM = 0, WnR = 0
[ 207.046549] user pgtable: 4k pages, 48-bit VAs, pgdp=00000008b6f19000
3.
kworker/0:5-411 [000] d..1 206.991613: rpm_idle: 2-1:1.0 flags-1 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.991626: rpm_return_int: rpm_idle+0xa8/0x420:2-1:1.0 ret=0
kworker/0:5-411 [000] d..1 206.991629: rpm_suspend: 2-1:1.0 flags-9 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.991634: rpm_idle: 2-1 flags-1 cnt-2 dep-0 auto-0 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.991636: rpm_return_int: rpm_idle+0xa8/0x420:2-1 ret=-11
kworker/0:5-411 [000] d..1 206.991638: rpm_return_int: rpm_suspend+0x174/0x5f0:2-1:1.0 ret=0
kworker/0:5-411 [000] .... 206.991839: rpm_usage: 2-1 flags-c cnt-1 dep-0 auto-0 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.992523: rpm_resume: 2-1 flags-4 cnt-2 dep-0 auto-0 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.992534: rpm_return_int: rpm_resume+0x114/0x758:2-1 ret=1
kworker/0:5-411 [000] .... 206.992548: rpm_usage: 2-1 flags-4 cnt-1 dep-0 auto-0 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.992618: rpm_idle: usb2 flags-1 cnt-0 dep-0 auto-1 p-0 irq-0 child-1
kworker/0:5-411 [000] d..1 206.992627: rpm_return_int: rpm_idle+0xa8/0x420:usb2 ret=-16
kworker/0:5-411 [000] .... 206.992690: rpm_usage: usb2-port1 flags-5 cnt-2 dep-0 auto-1 p-0 irq-0 child-0
kworker/0:5-411 [000] .... 206.992892: rpm_usage: usb2-port1 flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.992924: rpm_idle: 2-0:1.0 flags-4 cnt-0 dep-0 auto-1 p-0 irq-0 child-1
kworker/0:5-411 [000] d..1 206.992928: rpm_return_int: rpm_idle+0xa8/0x420:2-0:1.0 ret=0
kworker/0:5-411 [000] d..1 206.992931: rpm_suspend: 2-0:1.0 flags-c cnt-0 dep-0 auto-1 p-0 irq-0 child-1
kworker/0:5-411 [000] d..1 206.992936: rpm_idle: usb2 flags-1 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.992944: rpm_return_int: rpm_idle+0x2c8/0x420:usb2 ret=0
kworker/0:5-411 [000] d..1 206.992946: rpm_return_int: rpm_suspend+0x174/0x5f0:2-0:1.0 ret=0
kworker/0:5-411 [000] d..1 206.993033: rpm_idle: usb2 flags-2 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/0:5-411 [000] d..1 206.993038: rpm_return_int: rpm_idle+0xa8/0x420:usb2 ret=-16
kworker/u8:5-409 [002] d..1 206.993112: rpm_resume: 2-0:1.0 flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-1
kworker/u8:5-409 [002] d..1 206.993118: rpm_idle: 2-0:1.0 flags-1 cnt-1 dep-0 auto-1 p-0 irq-0 child-1
kworker/u8:5-409 [002] d..1 206.993121: rpm_return_int: rpm_idle+0xa8/0x420:2-0:1.0 ret=-11
kworker/u8:5-409 [002] d..1 206.993123: rpm_return_int: rpm_resume+0x114/0x758:2-0:1.0 ret=1
kworker/u8:5-409 [002] d..1 206.993135: rpm_idle: 2-0:1.0 flags-4 cnt-0 dep-0 auto-1 p-0 irq-0 child-1
kworker/u8:5-409 [002] d..1 206.993138: rpm_return_int: rpm_idle+0xa8/0x420:2-0:1.0 ret=0
kworker/u8:5-409 [002] d..1 206.993140: rpm_suspend: 2-0:1.0 flags-c cnt-0 dep-0 auto-1 p-0 irq-0 child-1
kworker/u8:5-409 [002] d..1 206.993143: rpm_idle: usb2 flags-1 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [002] d..1 206.993159: rpm_return_int: rpm_idle+0x2c8/0x420:usb2 ret=0
kworker/u8:5-409 [002] d..1 206.993161: rpm_return_int: rpm_suspend+0x174/0x5f0:2-0:1.0 ret=0
kworker/u8:5-409 [002] d..1 206.993165: rpm_resume: usb2 flags-4 cnt-1 dep-0 auto-1 p-1 irq-0 child-0
kworker/u8:5-409 [002] d..1 206.993167: rpm_return_int: rpm_resume+0x114/0x758:usb2 ret=1
kworker/u8:5-409 [003] d..1 206.993257: rpm_resume: usb1-port1 flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [003] d..1 206.993261: rpm_return_int: rpm_resume+0x114/0x758:usb1-port1 ret=1
kworker/u8:5-409 [003] d..1 206.993275: rpm_idle: usb2-port1 flags-5 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [003] d..1 206.993288: rpm_return_int: rpm_idle+0x2c8/0x420:usb2-port1 ret=0
kworker/u8:5-409 [003] d..1 206.993291: rpm_idle: usb1-port1 flags-5 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [003] d..1 206.993295: rpm_return_int: rpm_idle+0x2c8/0x420:usb1-port1 ret=0
kworker/u8:5-409 [003] d..1 206.993383: rpm_suspend: usb2 flags-c cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [003] d..1 206.993392: rpm_return_int: rpm_suspend+0x174/0x5f0:usb2 ret=0
kworker/3:2-208 [003] d..1 206.993770: rpm_idle: usb1-port1 flags-2 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/3:2-208 [003] d..1 206.993775: rpm_return_int: rpm_idle+0xa8/0x420:usb1-port1 ret=0
kworker/3:2-208 [003] d..1 206.993778: rpm_suspend: usb1-port1 flags-a cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/3:2-208 [003] d..1 206.993785: rpm_return_int: rpm_suspend+0x174/0x5f0:usb1-port1 ret=-11
kworker/u8:5-409 [003] d..1 206.993956: rpm_resume: usb2 flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [003] d..1 206.993964: rpm_return_int: rpm_resume+0x114/0x758:usb2 ret=1
kworker/u8:5-409 [003] d..1 206.993977: rpm_idle: usb2 flags-4 cnt-0 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [003] d..1 206.993982: rpm_return_int: rpm_idle+0xa8/0x420:usb2 ret=-16
kworker/u8:5-409 [003] d..1 206.994064: rpm_idle: xhci-hcd.1.auto flags-1 cnt-0 dep-0 auto-1 p-0 irq-0 child
-0
kworker/3:2-208 [003] d..1 207.005157: rpm_idle: xhci-hcd.1.auto flags-2 cnt-0 dep-0 auto-1 p-0 irq-0 child
-0
kworker/3:2-208 [003] d..1 207.005169: rpm_return_int: rpm_idle+0xa8/0x420:xhci-hcd.1.auto ret=0
kworker/3:2-208 [003] d..1 207.005172: rpm_suspend: xhci-hcd.1.auto flags-a cnt-0 dep-0 auto-1 p-0 irq-0 ch
ild-0
kworker/u8:5-409 [002] d..1 207.022142: rpm_resume: 1-0:1.0 flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-1
kworker/u8:5-409 [002] d..1 207.022153: rpm_resume: usb1 flags-0 cnt-1 dep-0 auto-1 p-0 irq-0 child-0
kworker/u8:5-409 [002] d..1 207.022155: rpm_resume: xhci-hcd.1.auto flags-0 cnt-1 dep-0 auto-1 p-0 irq-0 chi
ld-0
> Currently probe and remove looks like:
>
> xhci_plat_probe()
> pm_runtime_set_active()
> pm_runtime_enable()
> pm_runtime_get_noresume()
> ...
> pm_runtime_put_noidle()
> pm_runtime_forbid()
>
> xhci_plat_remove()
> <remove and put both hcd's>
> pm_runtime_set_suspended()
> pm_runtime_disable()
>
> Would it make sense to change xhci_plat_remove() to
>
> xhci_plat_remove()
> pm_runtime_disable()
> <remove and put both hcd's>
> pm_runtime_set_suspended()
>
I think this makes sense and tested at my platform.
Peter
