Hi Takashi-san
On Thu, Dec 24, 2020 at 5:00 PM Takashi Sakamoto
<o-takashi@xxxxxxxxxxxxx> 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
