On Wed, Oct 2, 2019 at 12:03 AM Tony Lindgren <tony@xxxxxxxxxxx> wrote:
>
> Hi,
>
> * Tony Lindgren <tony@xxxxxxxxxxx> [191001 16:52]:
> > * Yegor Yefremov <yegorslists@xxxxxxxxxxxxxx> [191001 09:20]:
> > > I've tried to increase the autosuspend_delay_ms and to set control to
> > > "on" but nothing changes. Below you can see the output of my testing
> > > script [1] (Py2 only). As one can see, the first cycle i.e. after the
> > > port is open for the first time, fails. But the subsequent cycle is
> > > successful. If you invoke the script again, everything repeats.
> > >
> > > I've also made printk() in cppi41_run_queue() and it looks like this
> > > routine will be called from cppi41_dma_issue_pending() only in the
> > > beginning of the second test cycle.
> >
> > So sounds like for you intially cppi41_dma_issue_pending() has
> > !cdd->is_suspended and just adds the request to the queue. And
> > then cppi41_run_queue() never gets called if this happens while
> > we have cppi41_runtime_resume() is still running?
>
> I got it reproducable here by adding msleep(500) to the beginning
> of cppi41_runtime_resume() :) Otherwise I'm only able to trigger
> the issue maybe one out of 20 tries it seems.
>
> Turns out the first dma call done by musb_ep_program() must wait
> if cppi41 is PM runtime suspended. Otherwise musb_ep_program()
> continues with other PIO packets before the DMA transfer is
> started.
>
> The patch below fixes it for me with a pm_runtime_get_sync()
> in device_prep_slave_sg, so adding Peter and Vinod to Cc.
>
> The other way to fix this would be to just wake up cpp41 in
> cppi41_dma_prep_slave_sg() and return NULL so that we can
> have musb_ep_program() continue with PIO while cppi41 is
> asleep.
>
> Anyways, care to try it out and see if it fixes your issue?
>
> Regards,
>
> Tony
>
> 8< ------------------
> diff --git a/drivers/dma/ti/cppi41.c b/drivers/dma/ti/cppi41.c
> --- a/drivers/dma/ti/cppi41.c
> +++ b/drivers/dma/ti/cppi41.c
> @@ -586,9 +586,18 @@ static struct dma_async_tx_descriptor *cppi41_dma_prep_slave_sg(
> enum dma_transfer_direction dir, unsigned long tx_flags, void *context)
> {
> struct cppi41_channel *c = to_cpp41_chan(chan);
> + struct cppi41_dd *cdd = c->cdd;
> struct cppi41_desc *d;
> struct scatterlist *sg;
> unsigned int i;
> + int error;
> +
> + error = pm_runtime_get_sync(cdd->ddev.dev);
> + if (error < 0) {
> + pm_runtime_put_noidle(cdd->ddev.dev);
> +
> + return NULL;
> + }
>
> d = c->desc;
> for_each_sg(sgl, sg, sg_len, i) {
> @@ -611,6 +620,9 @@ static struct dma_async_tx_descriptor *cppi41_dma_prep_slave_sg(
> d++;
> }
>
> + pm_runtime_mark_last_busy(cdd->ddev.dev);
> + pm_runtime_put_autosuspend(cdd->ddev.dev);
> +
> return &c->txd;
> }
The fix is working but on the first invocation, I get this output
(minicom provokes the same output):
# serialtest.py -c 2 /dev/ttyUSB0 /dev/ttyUSB0
[ 210.674524]
[ 210.676065] ================================
[ 210.680359] WARNING: inconsistent lock state
[ 210.684660] 5.4.0-rc1 #5 Not tainted
[ 210.688255] --------------------------------
[ 210.692550] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
[ 210.698592] serialtest.py/250 [HC0[0]:SC0[0]:HE1:SE1] takes:
[ 210.704284] ccce4050 (&(&musb->lock)->rlock){?.-.}, at:
musb_urb_enqueue+0x2e4/0x768 [musb_hdrc]
[ 210.713299] {IN-HARDIRQ-W} state was registered at:
[ 210.718229] _raw_spin_lock_irqsave+0x38/0x4c
[ 210.722716] dsps_interrupt+0x28/0x288 [musb_dsps]
[ 210.727631] __handle_irq_event_percpu+0x48/0x35c
[ 210.732452] handle_irq_event_percpu+0x28/0x7c
[ 210.737011] handle_irq_event+0x38/0x5c
[ 210.740963] handle_level_irq+0xc8/0x158
[ 210.744999] generic_handle_irq+0x20/0x34
[ 210.749121] __handle_domain_irq+0x64/0xe0
[ 210.753334] __irq_usr+0x54/0x80
[ 210.756669] 0xb6dc6820
[ 210.759218] irq event stamp: 28856
[ 210.762655] hardirqs last enabled at (28855): [<c02de7e0>]
kmem_cache_alloc_trace+0xc0/0x724
[ 210.771231] hardirqs last disabled at (28856): [<c09983d4>]
_raw_spin_lock_irqsave+0x1c/0x4c
[ 210.779718] softirqs last enabled at (28774): [<c0102580>]
__do_softirq+0x360/0x520
[ 210.787507] softirqs last disabled at (28759): [<c0142954>]
irq_exit+0x148/0x180
[ 210.794939]
[ 210.794939] other info that might help us debug this:
[ 210.801499] Possible unsafe locking scenario:
[ 210.801499]
[ 210.807449] CPU0
[ 210.809909] ----
[ 210.812367] lock(&(&musb->lock)->rlock);
[ 210.816490] <Interrupt>
[ 210.819125] lock(&(&musb->lock)->rlock);
[ 210.823422]
[ 210.823422] *** DEADLOCK ***
[ 210.823422]
[ 210.829376] 4 locks held by serialtest.py/250:
[ 210.833843] #0: ccf138dc (&tty->legacy_mutex){+.+.}, at:
tty_init_dev+0x48/0x1cc
[ 210.841395] #1: cce50160 (&port->mutex){+.+.}, at: tty_port_open+0x4c/0xc0
[ 210.848412] #2: ccb08d4c (&serial->disc_mutex){+.+.}, at:
serial_port_activate+0x20/0x90 [usbserial]
[ 210.857747] #3: ccce4050 (&(&musb->lock)->rlock){?.-.}, at:
musb_urb_enqueue+0x2e4/0x768 [musb_hdrc]
[ 210.867105]
[ 210.867105] stack backtrace:
[ 210.871495] CPU: 0 PID: 250 Comm: serialtest.py Not tainted 5.4.0-rc1 #5
[ 210.878232] Hardware name: Generic AM33XX (Flattened Device Tree)
[ 210.884387] [<c0112220>] (unwind_backtrace) from [<c010cf04>]
(show_stack+0x10/0x14)
[ 210.892190] [<c010cf04>] (show_stack) from [<c0977494>]
(dump_stack+0xd8/0x110)
[ 210.899554] [<c0977494>] (dump_stack) from [<c01a2af8>]
(mark_lock+0x54c/0x59c)
[ 210.906910] [<c01a2af8>] (mark_lock) from [<c01a2b94>]
(mark_held_locks+0x4c/0x78)
[ 210.914527] [<c01a2b94>] (mark_held_locks) from [<c01a2c70>]
(lockdep_hardirqs_on+0xb0/0x208)
[ 210.923105] [<c01a2c70>] (lockdep_hardirqs_on) from [<c099859c>]
(_raw_spin_unlock_irq+0x24/0x2c)
[ 210.932037] [<c099859c>] (_raw_spin_unlock_irq) from [<c065fc94>]
(__rpm_callback+0x70/0x11c)
[ 210.940612] [<c065fc94>] (__rpm_callback) from [<c065fd60>]
(rpm_callback+0x20/0x80)
[ 210.948402] [<c065fd60>] (rpm_callback) from [<c065f7cc>]
(rpm_resume+0x468/0x7a0)
[ 210.956018] [<c065f7cc>] (rpm_resume) from [<c065fb50>]
(__pm_runtime_resume+0x4c/0x64)
[ 210.964086] [<c065fb50>] (__pm_runtime_resume) from [<bf020940>]
(cppi41_dma_prep_slave_sg+0x20/0xfc [cppi41])
[ 210.974221] [<bf020940>] (cppi41_dma_prep_slave_sg [cppi41]) from
[<bf0bfa5c>] (cppi41_dma_channel_program+0x134/0x3b4 [musb_hdrc])
[ 210.986232] [<bf0bfa5c>] (cppi41_dma_channel_program [musb_hdrc])
from [<bf0b4d78>] (musb_start_urb+0xa00/0xe08 [musb_hdrc])
[ 210.997626] [<bf0b4d78>] (musb_start_urb [musb_hdrc]) from
[<bf0b6248>] (musb_urb_enqueue+0x620/0x768 [musb_hdrc])
[ 211.008416] [<bf0b6248>] (musb_urb_enqueue [musb_hdrc]) from
[<bf07320c>] (usb_hcd_submit_urb+0xdc/0x928 [usbcore])
[ 211.019104] [<bf07320c>] (usb_hcd_submit_urb [usbcore]) from
[<bf05911c>] (usb_serial_generic_submit_read_urb+0x44/0x8c
[usbserial])
[ 211.031123] [<bf05911c>] (usb_serial_generic_submit_read_urb
[usbserial]) from [<bf05917c>]
(usb_serial_generic_submit_read_urbs+0x18/0x60 [usbserial])
[ 211.044795] [<bf05917c>] (usb_serial_generic_submit_read_urbs
[usbserial]) from [<bf05731c>] (serial_port_activate+0x44/0x90
[usbserial])
[ 211.057233] [<bf05731c>] (serial_port_activate [usbserial]) from
[<c061ed70>] (tty_port_open+0x80/0xc0)
[ 211.066690] [<c061ed70>] (tty_port_open) from [<c06179a8>]
(tty_open+0xdc/0x3f4)
[ 211.074144] [<c06179a8>] (tty_open) from [<c02fcb30>]
(chrdev_open+0xa0/0x194)
[ 211.081424] [<c02fcb30>] (chrdev_open) from [<c02f4080>]
(do_dentry_open+0x22c/0x40c)
[ 211.089312] [<c02f4080>] (do_dentry_open) from [<c030864c>]
(path_openat+0x2bc/0x1494)
[ 211.097281] [<c030864c>] (path_openat) from [<c030a984>]
(do_filp_open+0x6c/0xdc)
[ 211.104810] [<c030a984>] (do_filp_open) from [<c02f55a0>]
(do_sys_open+0x168/0x218)
[ 211.112513] [<c02f55a0>] (do_sys_open) from [<c0101000>]
(ret_fast_syscall+0x0/0x28)
[ 211.120298] Exception stack(0xcc9a3fa8 to 0xcc9a3ff0)
[ 211.125387] 3fa0: b6ee3000 00022050 000c6000
00020902 00000000 00000000
[ 211.133616] 3fc0: b6ee3000 00022050 00022050 00000005 0002e7b4
00022050 b6aa8760 00000002
[ 211.141838] 3fe0: 00000005 befb4800 b6d44217 b6d458b6
Regards,
Yegor
