Hello, moreover, I have added some simple logic so that atc_tx_status does not try to acquire the lock if it is already hold by atc_tasklet. The same must then apply to atc_terminate_all. But once this is done, it works well. regards, Alain Le 19/02/2019 à 21:46, Alain Chambron a écrit : > > 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 >> >> > > >
