On 19/02/2019 17:28, Sebastian Andrzej Siewior wrote:
On 2019-02-16 12:06:16 [+0100], Alain Chambron wrote:
Hello,
Hi,
I have a running environment using SAMA5D3, kernel 4.14.41, using alsa with
SSC peripheral.
I am looking into the benefits of using the RT patches to lower audio
latency.
Applying the patches and compiling kernel + modules went very smoothly and
the system boots up well, the devices mount correctly and the audio
interface is up.
Anyhow, trying to actually play audio using aplay triggers a BUG(), I
believe on the first DMA interrupt. The backtrace is below this message. I
have some questions:
- has the scc dai being successfully tested on that architecture?
maybe Ludovic can answer this.
- I know for a fact that DMA is being used successfully (for example with
SPI devices) on my system, and
atc_tx_status is probably being called from other places, what specifics of
the SSC driver would trigger this bug?
- any other hints from the traces, or other information I could gather from
the system that would help?
Can you try addr2line -i on <c038a580> / (atc_tasklet+0x1ec/0x1f0)?
It seems that atc_tasklet holds the lock and then atc_tx_status() later
tries to acquire the same lock. It might have been fixed in a later
kernel.
atc_tasklet+0x1ec/0x1f0 gives:
drivers/dma/dmaengine.h:136
drivers/dma/dmaengine.h:158
drivers/dma/at_hdmac.c:601
drivers/dma/at_hdmac.c:615
the call is inbetween spin lock so your assumption seems correct.
On the other hand, I have compared the code of at_hdmac.c version 4.14.41 with the newest linux version v4.20.10, there are very few changes and that part has definitely not evolved.
Without -RT but with lockdebugging you should see a similar error.
After that, first bug trace, I get other traces from interrupt 30 being
misshandled and that note:
"irq 30: nobody cared (try booting with the "irqpoll" option)" and the
system is no longer responsive.
regards,
Alain
[ 52.410000] kernel BUG at kernel/locking/rtmutex.c:1048!
[ 52.410000] Internal error: Oops - BUG: 0 [#1] PREEMPT ARM
[ 52.410000] Modules linked in: snd_atmel_soc_audiophil
snd_soc_atmel_ssc_dai snd_soc_atmel_pcm_dma atmel_ssc snd_soc_ak4115
snd_soc_igloo snd_soc_pcm1792a_codec rotary_encoder snd_soc_si570
snd_soc_core snd_pcm_dmaengine snd_pcm snd_timer snd soundcore ssd1322(O)
spi_atmel
[ 52.410000] CPU: 0 PID: 263 Comm: irq/30-at_hdmac Tainted: G O
4.14.41-rt31+ #43
[ 52.410000] Hardware name: Atmel SAMA5
[ 52.410000] task: df631e00 task.stack: df6b2000
[ 52.410000] PC is at rt_spin_lock_slowlock_locked+0x214/0x260
[ 52.410000] LR is at 0xdf445d08
[ 52.410000] pc : [<c063efd0>] lr : [<df445d08>] psr: 600f0093
[ 52.410000] sp : df6b3db8 ip : df631e00 fp : 000000c0
[ 52.410000] r10: c0a3c2c0 r9 : df75bc00 r8 : df6b3dd0
[ 52.410000] r7 : a00f0013 r6 : df631e00 r5 : a00f0013 r4 : df445d00
[ 52.410000] r3 : df631e00 r2 : 00000000 r1 : df631e00 r0 : 00000000
[ 52.410000] Flags: nZCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment
none
[ 52.410000] Control: 10c53c7d Table: 3ed48059 DAC: 00000051
[ 52.410000] Process irq/30-at_hdmac (pid: 263, stack limit = 0xdf6b2208)
[ 52.410000] Stack: (0xdf6b3db8 to 0xdf6b4000)
[ 52.410000] 3da0: 00000001 a00f0013
[ 52.410000] 3dc0: df445d00 df445d00 df445c74 c063f064 df6b3dd0 00000000
00000000 df6b3ddc
[ 52.410000] 3de0: 00000000 00000000 00000000 00000000 00000001 00000000
00000000 00000000
[ 52.410000] 3e00: df6b3e2c 00000002 df445c74 c038848c de9a7600 deef3800
de9a7600 00000000
[ 52.410000] 3e20: bf070f5c bf058244 00000001 00000001 00000002 00000000
dec65a00 bf06b2e4
[ 52.410000] 3e40: df75bc00 df75bc00 00000024 00000000 de9a7600 00000001
c0a3c2c0 bf045538
[ 52.410000] 3e60: 00000000 df4f7e80 a00a0113 e09d2e74 df445c60 000f4240
000000c0 c013ecc0
[ 52.410000] 3e80: 000000c0 c013f5c8 bf0006dc e09d2e58 df445bb8 c0388868
00000000 de9a7600
[ 52.410000] 3ea0: df75bc00 600f0013 00000000 000f4240 00000018 c0a3c2c0
000000c0 bf04592c
[ 52.410000] 3ec0: df445cbc df445c74 df445d00 c038a580 00000000 00000000
00000000 00000000
[ 52.410000] 3ee0: 00000000 00000000 df445cbc 00000000 df445cb8 00000000
000f4240 c011a380
[ 52.410000] 3f00: 00000006 df6b2000 c0a0b13c 00208040 c0a3c300 c011a06c
c0a0b13c 00000006
[ 52.410000] 3f20: df40801c 00000000 df445cb8 df7c3a00 df541b00 00000001
c014a7fc c0a35bd6
[ 52.410000] 3f40: df7c3ad8 df44bd6c 00000000 c011a194 00000104 c014a83c
df7c3a00 df6b2000
[ 52.410000] 3f60: df541b00 c014aa40 00000000 c014a884 c014a948 df7c3ac0
00000000 df7c3a40
[ 52.410000] 3f80: df7c3a00 c014a948 df7c3ad8 c0131674 df7c3a40 c0131554
00000000 00000000
[ 52.410000] 3fa0: 00000000 00000000 00000000 c0107830 00000000 00000000
00000000 00000000
[ 52.410000] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000
[ 52.410000] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000
00000000 00000000
[ 52.410000] [<c063efd0>] (rt_spin_lock_slowlock_locked) from [<c063f064>]
(rt_spin_lock_slowlock+0x48/0x98)
[ 52.410000] [<c063f064>] (rt_spin_lock_slowlock) from [<c038848c>]
(atc_tx_status+0x84/0x234)
[ 52.410000] [<c038848c>] (atc_tx_status) from [<bf058244>]
(snd_dmaengine_pcm_pointer+0x28/0x8c [snd_pcm_dmaengine])
[ 52.410000] [<bf058244>] (snd_dmaengine_pcm_pointer [snd_pcm_dmaengine])
from [<bf06b2e4>] (soc_pcm_pointer+0x38/0xd0 [snd_soc_core])
[ 52.410000] [<bf06b2e4>] (soc_pcm_pointer [snd_soc_core]) from
[<bf045538>] (snd_pcm_update_hw_ptr0+0x28/0x3a8 [snd_pcm])
[ 52.410000] [<bf045538>] (snd_pcm_update_hw_ptr0 [snd_pcm]) from
[<bf04592c>] (snd_pcm_period_elapsed+0x74/0xac [snd_pcm])
[ 52.410000] [<bf04592c>] (snd_pcm_period_elapsed [snd_pcm]) from
[<c038a580>] (atc_tasklet+0x1ec/0x1f0)
[ 52.410000] [<c038a580>] (atc_tasklet) from [<c011a380>]
(__tasklet_action+0x7c/0x164)
[ 52.410000] [<c011a380>] (__tasklet_action) from [<c011a06c>]
(do_current_softirqs+0x1ac/0x254)
[ 52.410000] [<c011a06c>] (do_current_softirqs) from [<c011a194>]
(__local_bh_enable+0x80/0x98)
[ 52.410000] [<c011a194>] (__local_bh_enable) from [<c014a83c>]
(irq_forced_thread_fn+0x40/0x54)
[ 52.410000] [<c014a83c>] (irq_forced_thread_fn) from [<c014aa40>]
(irq_thread+0xf8/0x1d4)
[ 52.410000] [<c014aa40>] (irq_thread) from [<c0131674>]
(kthread+0x120/0x150)
[ 52.410000] [<c0131674>] (kthread) from [<c0107830>]
(ret_from_fork+0x14/0x24)
[ 52.410000] Code: e5983000 e1580003 08bd81f0 e7f001f2 (e7f001f2)
[ 52.410000] ---[ end trace 0000000000000002 ]---
Sebastian
