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