Hi, On Wed, Feb 20, 2019 at 08:40:28AM +0100, Alain Chambron wrote: > 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. > It's almost the same with the serial driver excepting that tx_status is called from a tasklet scheduled by a callback. That's probably why we didn't notice it. Regards Ludovic > 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 > >> > >> > > > > > > > >
