question about alsa tracepoints and alsa debugging

[Bert Schiettecatte]

Hi Takashi-san

On Thu, Dec 24, 2020 at 5:00 PM Takashi Sakamoto
<o-takashi at sakamocchi.jp> wrote:
> With records of tracepoints events for capture PCM substream
> which Bert's SDIO driver handles as well as for the playback PCM
> substream which speaker-test starts, we can get more details of
> runtimes.

Thanks so much for your detailed explanation. I tried capturing a new
trace for both speaker-test and arecord by running perf from a
different console and keeping an eye on /var/log/messages and it's
clear there is a deadlock, please see below. In my code I can see that
spin_lock_irqsave() is being called in the dw_mci_interrupt() which
then calls some other code which again calls spin_lock_irqsave() so I
guess that is what the problem is, and I have to restructure my code
to avoid that. What I don't understand, is why it says speaker-test is
trying to acquire the lock, while it's arecord that is using the
capture device to record (which uses my sdio driver). I guess it
doesn't matter because playback and capture are a single device (?).

Thanks!
Bert

[  187.653313]
[  187.656519] ============================================
[  187.663958] WARNING: possible recursive locking detected
[  187.671392] 5.9.12-00015-g3d36682d8cdf-dirty #74 Not tainted
[  187.679214] --------------------------------------------
[  187.686613] speaker-test/193 is trying to acquire lock:
[  187.693886] ed337cbc (&host->irq_lock#2){-...}-{2:2}, at:
dw_mci_set_drto+0xa0/0xf8
[  187.703898]
[  187.703898] but task is already holding lock:
[  187.713189] ed337cbc (&host->irq_lock#2){-...}-{2:2}, at:
dw_mci_interrupt+0x468/0x4e4
[  187.723463]
[  187.723463] other info that might help us debug this:
[  187.733531]  Possible unsafe locking scenario:
[  187.733531]
[  187.742727]        CPU0
[  187.746692]        ----
[  187.750624]   lock(&host->irq_lock#2);
[  187.755998]   lock(&host->irq_lock#2);
[  187.761326]
[  187.761326]  *** DEADLOCK ***
[  187.761326]
[  187.771203]  May be due to missing lock nesting notation
[  187.771203]
[  187.780964] 1 lock held by speaker-test/193:
[  187.786799]  #0: ed337cbc (&host->irq_lock#2){-...}-{2:2}, at:
dw_mci_interrupt+0x468/0x4e4
[  187.797239]
[  187.797239] stack backtrace:
[  187.804121] CPU: 0 PID: 193 Comm: speaker-test Not tainted
5.9.12-00015-g3d36682d8cdf-dirty #74
[  187.814905] Hardware name: Rockchip (Device Tree)
[  187.821204] [<c0311930>] (unwind_backtrace) from [<c030c200>]
(show_stack+0x10/0x14)
[  187.830964] [<c030c200>] (show_stack) from [<c0f4b9b0>]
(dump_stack+0xd0/0xf0)
[  187.840147] [<c0f4b9b0>] (dump_stack) from [<c03adc34>]
(__lock_acquire+0xff0/0x3394)
[  187.850018] [<c03adc34>] (__lock_acquire) from [<c03b0c74>]
(lock_acquire+0x134/0x56c)
[  187.859997] [<c03b0c74>] (lock_acquire) from [<c0f62900>]
(_raw_spin_lock_irqsave+0x4c/0x94)
[  187.870578] [<c0f62900>] (_raw_spin_lock_irqsave) from [<c0d0fca8>]
(dw_mci_set_drto+0xa0/0xf8)
[  187.881474] [<c0d0fca8>] (dw_mci_set_drto) from [<c0d10208>]
(dw_mci_interrupt+0x484/0x4e4)
[  187.891976] [<c0d10208>] (dw_mci_interrupt) from [<c03bf90c>]
(__handle_irq_event_percpu+0x70/0x484)
[  187.903363] [<c03bf90c>] (__handle_irq_event_percpu) from
[<c03bfd50>] (handle_irq_event_percpu+0x30/0x8c)
[  187.915376] [<c03bfd50>] (handle_irq_event_percpu) from
[<c03bfde4>] (handle_irq_event+0x38/0x5c)
[  187.926515] [<c03bfde4>] (handle_irq_event) from [<c03c46fc>]
(handle_fasteoi_irq+0xcc/0x124)
[  187.937255] [<c03c46fc>] (handle_fasteoi_irq) from [<c03be990>]
(generic_handle_irq+0x34/0x44)
[  187.948107] [<c03be990>] (generic_handle_irq) from [<c03befe4>]
(__handle_domain_irq+0x7c/0xe8)
[  187.959073] [<c03befe4>] (__handle_domain_irq) from [<c07a1340>]
(gic_handle_irq+0x58/0x9c)
[  187.969677] [<c07a1340>] (gic_handle_irq) from [<c0300f74>]
(__irq_usr+0x54/0x80)
[  187.979345] Exception stack(0xec40ffb0 to 0xec40fff8)
[  187.986316] ffa0:                                     bff0a126
b6ef7ef0 00000044 b6ef7670
[  187.996843] ffc0: 00000000 00000000 b6bfea54 b6bfb008 00000003
b6bfb008 000252a0 00025140
[  188.007419] ffe0: 000250b0 beb2484c 00012f44 b6ebc26c 60030010 ffffffff