Date:   Thu, 12 Dec 2019 09:54:05 +0100
From:   Martin Kepplinger <martin.kepplinger@...i.sm>
To:     Felipe Balbi <balbi@...nel.org>, linux-usb@...r.kernel.org,
        gregkh@...uxfoundation.org
Cc:     kernel@...i.sm, linux-kernel@...r.kernel.org,
        p.zabel@...gutronix.de
Subject: Re: suspend problem with dwc3 gadget / g_multi when usb disconnected

On 10.12.19 12:39, Felipe Balbi wrote:
> 
> Hi,
> 
> Martin Kepplinger <martin.kepplinger@...i.sm> writes:
>> I'm running today's linux-next with this defconfig on a librem 5 devkit:
>>
>> https://source.puri.sm/martin.kepplinger/linux-next/blob/next-20191205/librem5/arch/arm64/configs/librem5_defconfig
>>
>> So I want to have host and gadget mode (G_MULTI, most importantly a
>> serial ACM console), and I'm having trouble with S3 suspend:
>>
>> * The most interesting case here: When I boot with USB disconnected
>> (from the battery) I can't suspend or unload dwc3. After "echo mem >
>> /sys/power/state" I get nothing in the my logs except
>>
>> [   18.107380] PM: suspend entry (deep)
>>
>> and the system hangs. similarly, I can't work around this by rmmod -f
>> dwc3. What can go wrong here? I don't know enough about usb hci and why
>> this shouldn't work. What can I do to help you here?
>>
>> * When I boot with USB connected, then unplug USB, I get:
>>
>> [   19.289602] dwc3 38100000.usb: request 000000006a19695c was not
>> queued to ep3in
> 
> please capture ftrace logs from dwc3. We have documentation for this:
> 
> https://www.kernel.org/doc/html/latest/driver-api/usb/dwc3.html
> 
> (note to self: update email address :-)

thanks for getting back at me! I hope I won't confuse you by seemingly
different issues:

First, the above message again: I see it (on -next-20191212) every time
a few seconds after startup, also when keeping usb connected:

[   38.375833] dwc3 38100000.usb: request 0000000051c55cfc was not
queued to ep3in


and I append the "full" trace with that timestamp included. Just to
paste a (maybe) relevant part here:


     irq/41-dwc3-310   [000] d..2    38.375802: dwc3_writel: addr
0000000023f39630 value 00050c08
     irq/41-dwc3-310   [000] d..2    38.375803: dwc3_readl: addr
0000000023f39630 value 00050808
     irq/41-dwc3-310   [000] d..2    38.375804: dwc3_gadget_ep_cmd:
ep2in: cmd 'End Transfer' [50c08] params 00000000 00000000 00000000 -->
status: Successful
     irq/41-dwc3-310   [000] d..2    38.375805: dwc3_readl: addr
000000002c8ca7cf value 40102400
     irq/41-dwc3-310   [000] d..2    38.375806: dwc3_writel: addr
000000002c8ca7cf value 40102540
     irq/41-dwc3-310   [000] d..2    38.375808: dwc3_readl: addr
00000000ad4ae082 value 00000003
     irq/41-dwc3-310   [000] d..2    38.375809: dwc3_writel: addr
00000000ad4ae082 value 00000003
     irq/41-dwc3-310   [000] d..2    38.375815: dwc3_ep_dequeue: ep3in:
req 0000000051c55cfc length 0/0 zsI ==> 0
     irq/41-dwc3-310   [000] d..2    38.383461: dwc3_free_request:
ep3in: req 0000000051c55cfc length 0/0 zsI ==> 0
     irq/41-dwc3-310   [000] d..2    38.383480: dwc3_gadget_ep_disable:
ep2out: mps 512/1024 streams 15 burst 0 ring 16/11 flags E:swBp:>



Now, I still have a lot configured in (G_MULTI and much more) and will
compare that to less later. But I see a second issue:

On next-20191212 now when shutting down or doing rmmod with USB
disconnected, I get the following and can always reproduce it:

[   64.393272] WARNING: CPU: 3 PID: 884 at
drivers/usb/dwc3/gadget.c:2719
dwc3_stop_active_transfer.constprop.38+0xe8/0x100 [dwc3]
[   64.405226] Modules linked in: rfkill st_magn_spi st_sensors_spi
mousedev qmi_wwan caam_jr caamhash_desc caamalg_desc cdc_wdm option
usbnet usb_wwan mii usbserial st_magn_i2c st_magn st_sensors_i2c
st_sensors industrialio_triggered_buffer goodix kfifo_buf tcpci tcpm
roles imx2_wdt watchdog aes_ce_blk crypto_simd typec bq25890_charger
caam imx_sdma virt_dma error crct10dif_ce ghash_ce sha2_ce sha1_ce
gpio_vibra usb_f_acm u_serial usb_f_rndis g_multi usb_f_mass_storage
u_ether libcomposite ip_tables x_tables ipv6 nf_defrag_ipv6
xhci_plat_hcd xhci_hcd usbcore dwc3 snvs_pwrkey ulpi udc_core
phy_fsl_imx8mq_usb usb_common
[   64.462126] CPU: 3 PID: 884 Comm: ip Not tainted
5.5.0-rc1-next-20191212-librem5-00019-g4fb81fdd9c7d #1
[   64.471909] Hardware name: Purism Librem 5 devkit (DT)
[   64.477264] pstate: 60000085 (nZCv daIf -PAN -UAO)
[   64.482268] pc : dwc3_stop_active_transfer.constprop.38+0xe8/0x100 [dwc3]
[   64.489351] lr : dwc3_stop_active_transfer.constprop.38+0x64/0x100 [dwc3]
[   64.496421] sp : ffff00009f213240
[   64.499874] x29: ffff00009f213240 x28: 0000000000000000
[   64.505410] x27: ffff00009f2137b0 x26: ffff0000a4e0cc10
[   64.510946] x25: 0000000000000001 x24: ffff0000a324518c
[   64.516482] x23: ffff0000a3245193 x22: ffff0000a41f0080
[   64.522018] x21: 0000000000000000 x20: ffff0000a4176600
[   64.527553] x19: ffff800010ee87c8 x18: 0000000000000000
[   64.533089] x17: 0000000000000000 x16: 0000000000000000
[   64.538625] x15: 0000000000000000 x14: 0000000000000000
[   64.544160] x13: ffff0000a4176868 x12: ffff0000a4176868
[   64.549696] x11: ffffffffffff3f08 x10: 0000000000000008
[   64.555232] x9 : ffffffffffff3f04 x8 : 0000000000000811
[   64.560767] x7 : ffffffffffff3f00 x6 : ffffffffffff3f0c
[   64.566303] x5 : 0000000000000000 x4 : ffff80001007483c
[   64.571839] x3 : 0000000000000808 x2 : ffff00009f21327c
[   64.577375] x1 : 0000000000000040 x0 : 00000000ffffff92
[   64.582911] Call trace:
[   64.585474]  dwc3_stop_active_transfer.constprop.38+0xe8/0x100 [dwc3]
[   64.592194]  __dwc3_gadget_ep_disable+0x34/0x380 [dwc3]
[   64.597649]  dwc3_gadget_ep_disable+0x44/0xf8 [dwc3]
[   64.602841]  usb_ep_disable+0x34/0x100 [udc_core]
[   64.607749]  eth_stop+0xb4/0x130 [u_ether]
[   64.612026]  __dev_close_many+0xb4/0x138
[   64.616116]  __dev_change_flags+0xb8/0x1d0
[   64.620385]  dev_change_flags+0x28/0x68
[   64.624384]  do_setlink+0x30c/0xc90
[   64.628021]  __rtnl_newlink+0x3f8/0x788
[   64.632018]  rtnl_newlink+0x54/0x80
[   64.635654]  rtnetlink_rcv_msg+0x128/0x370
[   64.639926]  netlink_rcv_skb+0x60/0x120
[   64.643924]  rtnetlink_rcv+0x1c/0x28
[   64.647650]  netlink_unicast+0x1b8/0x278
[   64.651739]  netlink_sendmsg+0x1ac/0x3b0
[   64.655829]  ____sys_sendmsg+0x250/0x298
[   64.659918]  ___sys_sendmsg+0x88/0xc8
[   64.663735]  __sys_sendmsg+0x70/0xc0
[   64.667463]  __arm64_sys_sendmsg+0x28/0x30
[   64.671736]  el0_svc_common.constprop.3+0x98/0x170
[   64.676729]  el0_svc_handler+0x20/0x28
[   64.680638]  el0_sync_handler+0x134/0x1a0
[   64.684817]  el0_sync+0x140/0x180
[   64.688271] ---[ end trace 4f6aa846a9c6f20c ]---

... again. at every shutdown or rmmod.

I hope that this might be already helpful.


> 
>> and then try to suspend:
>>
>> root@...eos:/home/purism# echo mem > /sys/power/state
>> [   37.863066] xhci-hcd xhci-hcd.0.auto: xHCI host controller not
>> responding, assume dead
>> [   37.871345] xhci-hcd xhci-hcd.0.auto: HC died; cleaning up
>> [   37.877260] PM: dpm_run_callback(): platform_pm_suspend+0x0/0x78
>> returns -22
>> [   37.884626] PM: Device xhci-hcd.0.auto failed to suspend async: error -22
>> [   37.891728] PM: Some devices failed to suspend, or early wake event
>> detected
>> bash: echo: write error: Invalid argument
>>
>>
>> * When I keep USB connected, the behaviour is similar actually, but
>> rmmod works (but that use-case is not that interesting to me).
>>
>>
>> Since my experience with USB drivers is limited, I'm glad to hear about
>> any of your experience with dwc3- or more general gadget-problems with
>> suspend and that or a similar configuration.
>>
>> Without G_MULTI and dwc3 host-only, suspend works btw. And all the above
>> is basically identical on previous stable kernels too.
> 
> Have you tried any other gadget drivers or just g-multi? Care to try
> with something simple like g-zero?
> 

will do.

                                martin


View attachment "trace" of type "text/plain" (335782 bytes)

Powered by blists - more mailing lists