Re: usb: musb: tx fifo flush warning

[John Ogness]

On 2016-03-04, John Ogness <john.ogn...@linutronix.de> wrote:
> Using v4.5-rc6, I modified musb_h_tx_flush_fifo() to allow infinite
> looping and kept a log of the number of loops that were executed. For
> my test I am regularly seeing 3000-3200 loops (with a max so far of
> 3289). Since there used to be an msleep() in the loop, I never hit the
> warnings before.
>
> With my board, 3200 loops takes about 950us. Perhaps the msleep()
> should be reinserted, but with a retry count of only 3 before aborting
> with the warning.

Sorry, since musb_h_tx_flush_fifo() can run in interrupt context,
obviously an msleep() cannot be used. It seems increasing the retry
count may be the only option here. Maybe 5000?

John Ogness
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: usb: musb: tx fifo flush warning

[John Ogness]

On 2016-03-03, John Ogness <john.ogn...@linutronix.de> wrote:
>>> Using next-20160302 I can very reliably hit this warning on an
>>> AM335x BeagleBone by playing a short audio file over USB-Audio:
>>> 
>>> $ aplay -Dplughw:1,0 -r 44100 -c 2 -f S16_LE 
>>> /usr/share/sounds/alsa/Front_Center.wav
>>> 
>>> $ aplay -l
>>>  List of PLAYBACK Hardware Devices 
>>> card 1: Audio [USB Audio], device 0: USB Audio [USB Audio]
>>>   Subdevices: 1/1
>>>   Subdevice #0: subdevice #0
>>> 
>>> The audio file is part of the alsa-utils package. The USB-Audio
>>> device is never disconnected. Simply playing the file triggers the
>>> warning. Any hints/suggestions how I should debug this?
>>
>> In general, it seems this tx fifo flush error has been there for
>> years, it happens when tearing down an active endpoint in some
>> unknown conditions. But I haven't seen a such case in which musb
>> stops working.
>
> Actually, I am tracking down an issue where musb _does_ stop
> working. With the above "aplay" example, I can reproduce a hang with the
> musb on v3.19 and v4.0. Sometimes it takes up to an hour to reproduce
> the hang, so I am slowly moving to newer kernels to see how far I can
> reproduce the hang.

There was a lot of great work done on musb between v4.0 and v4.1. This
seems to have fixed the musb hang. With v4.1 I am not able to reproduce
the problem. Great job!

> I have not been able to reproduce a hang with next-20160302 (yet?),
> but I do get your warning and the backtrace looks very similar to what
> I see in the hang situation on the older kernel versions.

Using v4.5-rc6, I modified musb_h_tx_flush_fifo() to allow infinite
looping and kept a log of the number of loops that were executed. For my
test I am regularly seeing 3000-3200 loops (with a max so far of
3289). Since there used to be an msleep() in the loop, I never hit the
warnings before.

With my board, 3200 loops takes about 950us. Perhaps the msleep() should
be reinserted, but with a retry count of only 3 before aborting with the
warning.

John Ogness
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: usb: musb: tx fifo flush warning

[John Ogness]

On 2016-03-03, Bin Liu <b-...@ti.com> wrote:
>> Using next-20160302 I can very reliably hit this warning on an AM335x
>> BeagleBone by playing a short audio file over USB-Audio:
>> 
>> $ aplay -Dplughw:1,0 -r 44100 -c 2 -f S16_LE 
>> /usr/share/sounds/alsa/Front_Center.wav
>> 
>> $ aplay -l
>>  List of PLAYBACK Hardware Devices 
>> card 1: Audio [USB Audio], device 0: USB Audio [USB Audio]
>>   Subdevices: 1/1
>>   Subdevice #0: subdevice #0
>> 
>> The audio file is part of the alsa-utils package. The USB-Audio
>> device is never disconnected. Simply playing the file triggers the
>> warning. Any hints/suggestions how I should debug this?
>
> In general, it seems this tx fifo flush error has been there for
> years, it happens when tearing down an active endpoint in some unknown
> conditions. But I haven't seen a such case in which musb stops
> working.

Actually, I am tracking down an issue where musb _does_ stop
working. With the above "aplay" example, I can reproduce a hang with the
musb on v3.19 and v4.0. Sometimes it takes up to an hour to reproduce
the hang, so I am slowly moving to newer kernels to see how far I can
reproduce the hang. I have not been able to reproduce a hang with
next-20160302 (yet?), but I do get your warning and the backtrace looks
very similar to what I see in the hang situation on the older kernel
versions.

> In this case, does musb still work or is audio playback broken after
> the warning message?

In this (next-20160302) case musb does continue to work. In my debugging
of the older kernels I can perfectly identify when the situation for a
potential hang happens. Most of the time it does not hang there, but
100% of the hangs were in that exact situation. So I suspect a race
condition exists there.

> Does the issue happen in any previous kernel? Trying to think if there
> is any regression in next-20160302...

I will continue trying to reproduce the hang with newer kernels. I
haven't tried anything between v4.0 and next-20160302 yet. I will post
again when I have more data.

John Ogness
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

usb: musb: tx fifo flush warning

[John Ogness]

Hi Bin,

Using next-20160302 I can very reliably hit this warning on an AM335x
BeagleBone by playing a short audio file over USB-Audio:

$ aplay -Dplughw:1,0 -r 44100 -c 2 -f S16_LE 
/usr/share/sounds/alsa/Front_Center.wav

$ aplay -l
 List of PLAYBACK Hardware Devices 
card 1: Audio [USB Audio], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

The audio file is part of the alsa-utils package. The USB-Audio device
is never disconnected. Simply playing the file triggers the warning. Any
hints/suggestions how I should debug this?

Here is the dmesg output:

[ cut here ]
WARNING: CPU: 0 PID: 0 at /linux/drivers/usb/musb/musb_host.c:139 
musb_h_tx_flush_fifo+0xd4/0xf8 [musb_hdrc]
musb-hdrc musb-hdrc.1.auto: Could not flush host TX10 fifo: csr: 2403
Modules linked in: musb_am335x musb_dsps musb_hdrc snd_usb_audio snd_hwdep 
snd_usbmidi_lib snd_rawmidi
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.5.0-rc6-next-20160302 #75
Hardware name: Generic AM33XX (Flattened Device Tree)
Backtrace:
[] (dump_backtrace) from [] (show_stack+0x18/0x1c)
 r6: r5: r4:60010193 r3:
[] (show_stack) from [] (dump_stack+0x94/0xb4)
[] (dump_stack) from [] (__warn+0xd8/0x104)
 r6:bf050428 r5: r4:c0c01a98 r3:
[] (__warn) from [] (warn_slowpath_fmt+0x40/0x48)
 r10:ca08a010 r8:ca08ab80 r7:bf0510cc r6:d104cc10 r5:bf050ef0 r4:2403
[] (warn_slowpath_fmt) from [] 
(musb_h_tx_flush_fifo+0xd4/0xf8 [musb_hdrc])
 r3:bf04f9ac r2:bf050460
[] (musb_h_tx_flush_fifo [musb_hdrc]) from [] 
(musb_cleanup_urb+0xc8/0x144 [musb_hdrc])
 r10:d104cc10 r9:bf0510cc r8: r7: r6:ca0896d4 r5:cf4d8f00
 r4:ca08ab80
[] (musb_cleanup_urb [musb_hdrc]) from [] 
(musb_urb_dequeue+0xf4/0x12c [musb_hdrc])
 r10:8200 r9:0001 r8:a0010193 r7: r6:ca08a010 r5:ca080f80
 r4:cf4d8f00
[] (musb_urb_dequeue [musb_hdrc]) from [] 
(unlink1+0x34/0x118)
 r10:13e8 r9:2e6c r8:ca0873ec r7:ff98 r6:cf6ff000 r5:cf4d8f00
 r4:cf4d8f00 r3:bf0487f8
[] (unlink1) from [] (usb_hcd_unlink_urb+0x58/0x8c)
 r8:ca0873ec r7:ff98 r6:a0010193 r5:cf545000 r4:cf4d8f00 r3:cf545000
[] (usb_hcd_unlink_urb) from [] (usb_unlink_urb+0x34/0x50)
 r7:ca086000 r6:ca0873f0 r5:ca086000 r4:
[] (usb_unlink_urb) from [] (deactivate_urbs+0xd4/0xf4 
[snd_usb_audio])
[] (deactivate_urbs [snd_usb_audio]) from [] 
(snd_usb_endpoint_stop+0x38/0x70 [snd_usb_audio])
 r10:5dc0 r8:cf471000 r7: r6: r5: r4:ca086000
[] (snd_usb_endpoint_stop [snd_usb_audio]) from [] 
(stop_endpoints+0x64/0x7c [snd_usb_audio])
 r5:cf4f6674 r4:cf4f6610
[] (stop_endpoints [snd_usb_audio]) from [] 
(snd_usb_substream_playback_trigger+0x9c/0xc0 [snd_usb_audio])
 r6:0001 r5:cf4f6200 r4:cf4f6610 r3:cf4fe000
[] (snd_usb_substream_playback_trigger [snd_usb_audio]) from 
[] (snd_pcm_do_stop+0x5c/0x60)
 r4:c0876b34 r3:bf024d94
[] (snd_pcm_do_stop) from [] 
(snd_pcm_action_single+0x40/0x80)
[] (snd_pcm_action_single) from [] 
(snd_pcm_drain_done+0x1c/0x24)
 r7:cf4f6200 r6:00011940 r5:5dc0 r4:4650
[] (snd_pcm_drain_done) from [] 
(snd_pcm_update_state+0xd8/0x108)
[] (snd_pcm_update_state) from [] 
(snd_pcm_update_hw_ptr0+0x1bc/0x3d8)
 r5:00011940 r4:cf4fe000
[] (snd_pcm_update_hw_ptr0) from [] 
(snd_pcm_period_elapsed+0x7c/0xbc)
 r10:03c0 r9:0004 r8:ca086000 r7:0120 r6:60010193 r5:cf4fe000
 r4:cf4f6200
[] (snd_pcm_period_elapsed) from [] 
(prepare_playback_urb+0x2ac/0x578 [snd_usb_audio])
 r6:cf5ad900 r5:cf5ad940 r4:cf4f6610 r3:
[] (prepare_playback_urb [snd_usb_audio]) from [] 
(prepare_outbound_urb+0x4c/0x224 [snd_usb_audio])
 r10:c0c82800 r9: r8:bf02420c r7:ca086000 r6:cf5ad900 r5:ca0861e8
 r4:ca086000
[] (prepare_outbound_urb [snd_usb_audio]) from [] 
(snd_complete_urb+0x108/0x26c [snd_usb_audio])
 r10:c0c82800 r9: r8:cf6ff0dc r7: r6:cf5ad900 r5:ca0861e8
 r4:ca086000
[] (snd_complete_urb [snd_usb_audio]) from [] 
(__usb_hcd_giveback_urb+0x74/0x110)
 r7: r6: r5:60010113 r4:cf5ad900
[] (__usb_hcd_giveback_urb) from [] 
(usb_giveback_urb_bh+0xa4/0xf4
 r7:cf6ff0e0 r6:cf6ff0e4 r5: r4:c0c01e18
[] (usb_giveback_urb_bh) from [] 
(tasklet_hi_action+0x8c/0x138)
 r8:c0b64348 r7:c0c02b14 r6: r5:cf6ff0f0 r4:cf6ff0ec
[] (tasklet_hi_action) from [] (__do_softirq+0xec/0x240)
 r10:c0c02080 r9: r8:0100 r7:c0c02080 r6: r5:c0c02080
 r4: r3:c01390d4
[] (__do_softirq) from [] (irq_exit+0xa8/0x120)
 r10:cf004000 r9:c0c029e0 r8:0044 r7: r6: r5:c0b6756c
 r4:c0c02b14
[] (irq_exit) from [] (__handle_domain_irq+0x78/0xe4)
 r4:c0c02b14 r3:c017a968
[] (__handle_domain_irq) from [] 
(omap_intc_handle_irq+0x38/0x98)
 r10:c0c029d8 r8:c0b68638 r7:c0c01f4c r6: r5:60010013 r4:c0cb00c0
[] (omap_intc_handle_irq) from [] (__irq_svc+0x54/0x70)
Exception stack(0xc0c01f18 to 0xc0c01f60)
1f00:   0001 
1f20: c0c01f78 

[PATCH] usb: musb: gadget: fix possible NULL pointer dereference

[John Ogness]

txstate() assumes that if the request buffer is mapped, a DMA channel
is allocated. There is a case here where the DMA channel is released
and then shortly thereafter (in general PIO code) the request buffer
is unmapped. However, in this case unmap_dma_buffer() silently fails
because the DMA channel is already gone. Thus, the next time txstate()
is called, there is a NULL pointer exception because the buffer is
mapped but no DMA channel is allocated.

This patch adds an extra call unmap_dma_buffer() before releasing the
channel.

Signed-off-by: John Ogness <john.ogn...@linutronix.de>
---
 patch against next-20160226

 drivers/usb/musb/musb_gadget.c |1 +
 1 file changed, 1 insertion(+)

diff --git a/drivers/usb/musb/musb_gadget.c b/drivers/usb/musb/musb_gadget.c
index 87bd578..c518d3c 100644
--- a/drivers/usb/musb/musb_gadget.c
+++ b/drivers/usb/musb/musb_gadget.c
@@ -393,6 +393,7 @@ static void txstate(struct musb *musb, struct musb_request 
*req)
request->dma + request->actual,
request_size);
if (!use_dma) {
+   unmap_dma_buffer(req, musb);
c->channel_release(musb_ep->dma);
musb_ep->dma = NULL;
csr &= ~MUSB_TXCSR_DMAENAB;
-- 
1.7.10.4
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html