Hi Shawn,
On Mon, May 28, 2012 at 11:51 AM, Mark Brown broonie@opensource.wolfsonmicro.com wrote:
On Fri, May 25, 2012 at 08:14:56PM -0300, Fabio Estevam wrote:
From: Fabio Estevam fabio.estevam@freescale.com
Prepare the clock before enabling it.
Applied, thanks.
With this patch applied I have just realized the following (only during the first 'aplay', subsequent 'aplay's do not show it):
root@freescale /home$ aplay audio48k16S.wav Playing WAVE 'audio48k16S.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo [ 16.170000] [ 16.170000] ========================================================= [ 16.170000] [ INFO: possible irq lock inversion dependency detected ] [ 16.170000] 3.4.0-next-20120524-00008-g5e6603c-dirty #962 Not tainted [ 16.170000] --------------------------------------------------------- [ 16.170000] swapper/0 just changed the state of lock: [ 16.170000] (&(&substream->self_group.lock)->rlock){..-...}, at: [<c022fda8>] snd_pcm_period_elapsed+0x34/0xd0 [ 16.170000] but this lock took another, SOFTIRQ-unsafe lock in the past: [ 16.170000] (prepare_lock){+.+...} [ 16.170000] [ 16.170000] and interrupts could create inverse lock ordering between them. [ 16.170000] [ 16.170000] [ 16.170000] other info that might help us debug this: [ 16.170000] Possible interrupt unsafe locking scenario: [ 16.170000] [ 16.170000] CPU0 CPU1 [ 16.170000] ---- ---- [ 16.170000] lock(prepare_lock); [ 16.170000] local_irq_disable(); [ 16.170000] lock(&(&substream->self_group.lock)->rlock); [ 16.170000] lock(prepare_lock); [ 16.170000] <Interrupt> [ 16.170000] lock(&(&substream->self_group.lock)->rlock); [ 16.170000] [ 16.170000] *** DEADLOCK *** [ 16.170000] [ 16.170000] 1 lock held by swapper/0: [ 16.170000] #0: (snd_pcm_link_rwlock){...-..}, at: [<c022fd98>] snd_pcm_period_elapsed+0x24/0xd0 [ 16.170000] [ 16.170000] the shortest dependencies between 2nd lock and 1st lock: [ 16.170000] -> (prepare_lock){+.+...} ops: 110 { [ 16.170000] HARDIRQ-ON-W at: [ 16.170000] [<c005bc10>] __lock_acquire+0xb04/0x1b98 [ 16.170000] [<c005cd44>] lock_acquire+0xa0/0x108 [ 16.170000] [<c02e4c20>] mutex_lock_nested+0x54/0x29c [ 16.170000] [<c021d250>] clk_prepare+0x18/0x38 [ 16.170000] [<c04029f8>] mxs_machine_init+0x30/0x74 [ 16.170000] [<c03ff7b8>] customize_machine+0x1c/0x28 [ 16.170000] [<c000874c>] do_one_initcall+0x30/0x17c [ 16.170000] [<c03fe340>] kernel_init+0x114/0x1f0 [ 16.170000] [<c001014c>] kernel_thread_exit+0x0/0x8 [ 16.170000] SOFTIRQ-ON-W at: [ 16.170000] [<c005bc34>] __lock_acquire+0xb28/0x1b98 [ 16.170000] [<c005cd44>] lock_acquire+0xa0/0x108 [ 16.170000] [<c02e4c20>] mutex_lock_nested+0x54/0x29c [ 16.170000] [<c021d250>] clk_prepare+0x18/0x38 [ 16.170000] [<c04029f8>] mxs_machine_init+0x30/0x74 [ 16.170000] [<c03ff7b8>] customize_machine+0x1c/0x28 [ 16.170000] [<c000874c>] do_one_initcall+0x30/0x17c [ 16.170000] [<c03fe340>] kernel_init+0x114/0x1f0 [ 16.170000] [<c001014c>] kernel_thread_exit+0x0/0x8 [ 16.170000] INITIAL USE at: [ 16.170000] [<c005b4d4>] __lock_acquire+0x3c8/0x1b98 [ 16.170000] [<c005cd44>] lock_acquire+0xa0/0x108 [ 16.170000] [<c02e4c20>] mutex_lock_nested+0x54/0x29c [ 16.170000] [<c021c7b8>] __clk_init+0x20/0x3e4 [ 16.170000] [<c021cc64>] clk_register+0xe8/0x1b0 [ 16.170000] [<c021d570>] clk_register_fixed_rate+0x8c/0xe0 [ 16.170000] [<c04107b8>] mx28_clocks_init+0x7c/0xdac [ 16.170000] [<c0400270>] time_init+0x20/0x30 [ 16.170000] [<c03fe794>] start_kernel+0x1a0/0x2a0 [ 16.170000] [<40008040>] 0x40008040 [ 16.170000] } [ 16.170000] ... key at: [<c044fb9c>] prepare_lock+0x38/0x48 [ 16.170000] ... acquired at: [ 16.170000] [<c005cd44>] lock_acquire+0xa0/0x108 [ 16.170000] [<c02e4c20>] mutex_lock_nested+0x54/0x29c [ 16.170000] [<c021d250>] clk_prepare+0x18/0x38 [ 16.170000] [<c024474c>] mxs_saif_trigger+0xd8/0x184 [ 16.170000] [<c023f8c0>] soc_pcm_trigger+0x94/0x9c [ 16.170000] [<c0228804>] snd_pcm_do_start+0x28/0x2c [ 16.170000] [<c0228718>] snd_pcm_action_single+0x38/0x78 [ 16.170000] [<c02306fc>] snd_pcm_lib_write1+0x2e4/0x340 [ 16.170000] [<c02307f8>] snd_pcm_lib_write+0x44/0x64 [ 16.170000] [<c022d0e0>] snd_pcm_playback_ioctl1+0xec/0x46c [ 16.170000] [<c00d8834>] do_vfs_ioctl+0x7c/0x584 [ 16.170000] [<c00d8d74>] sys_ioctl+0x38/0x60 [ 16.170000] [<c000f180>] ret_fast_syscall+0x0/0x38 [ 16.170000] [ 16.170000] -> (&(&substream->self_group.lock)->rlock){..-...} ops: 36 { [ 16.170000] IN-SOFTIRQ-W at: [ 16.170000] [<c005bbf4>] __lock_acquire+0xae8/0x1b98 [ 16.170000] [<c005cd44>] lock_acquire+0xa0/0x108 [ 16.170000] [<c02e67fc>] _raw_spin_lock+0x2c/0x3c [ 16.170000] [<c022fda8>] snd_pcm_period_elapsed+0x34/0xd0 [ 16.170000] [<c01bed28>] mxs_dma_tasklet+0x18/0x1c [ 16.170000] [<c00235e4>] tasklet_action+0xc8/0xd8 [ 16.170000] [<c0023b38>] __do_softirq+0xa0/0x1e0 [ 16.170000] [<c0023e10>] irq_exit+0x8c/0x94 [ 16.170000] [<c0010080>] handle_IRQ+0x34/0x84 [ 16.170000] [<c000edd8>] __irq_svc+0x38/0x60 [ 16.170000] [<c001029c>] default_idle+0x40/0x48 [ 16.170000] [<c00105b8>] cpu_idle+0x68/0xd0 [ 16.170000] [<c03fe854>] start_kernel+0x260/0x2a0 [ 16.170000] INITIAL USE at: [ 16.170000] [<c005b4d4>] __lock_acquire+0x3c8/0x1b98 [ 16.170000] [<c005cd44>] lock_acquire+0xa0/0x108 [ 16.170000] [<c02e67fc>] _raw_spin_lock+0x2c/0x3c [ 16.170000] [<c022978c>] snd_pcm_sync_ptr+0xb8/0x16c [ 16.170000] [<c022c038>] snd_pcm_common_ioctl1+0x204/0xd48 [ 16.170000] [<c022d024>] snd_pcm_playback_ioctl1+0x30/0x46c [ 16.170000] [<c00d8834>] do_vfs_ioctl+0x7c/0x584 [ 16.170000] [<c00d8d74>] sys_ioctl+0x38/0x60 [ 16.170000] [<c000f180>] ret_fast_syscall+0x0/0x38 [ 16.170000] } [ 16.170000] ... key at: [<c099e694>] __key.25802+0x0/0x8 [ 16.170000] ... acquired at: [ 16.170000] [<c005a030>] check_usage_forwards+0xa0/0x10c [ 16.170000] [<c0059120>] mark_lock+0x1d4/0x62c [ 16.170000] [<c005bbf4>] __lock_acquire+0xae8/0x1b98 [ 16.170000] [<c005cd44>] lock_acquire+0xa0/0x108 [ 16.170000] [<c02e67fc>] _raw_spin_lock+0x2c/0x3c [ 16.170000] [<c022fda8>] snd_pcm_period_elapsed+0x34/0xd0 [ 16.170000] [<c01bed28>] mxs_dma_tasklet+0x18/0x1c [ 16.170000] [<c00235e4>] tasklet_action+0xc8/0xd8 [ 16.170000] [<c0023b38>] __do_softirq+0xa0/0x1e0 [ 16.170000] [<c0023e10>] irq_exit+0x8c/0x94 [ 16.170000] [<c0010080>] handle_IRQ+0x34/0x84 [ 16.170000] [<c000edd8>] __irq_svc+0x38/0x60 [ 16.170000] [<c001029c>] default_idle+0x40/0x48 [ 16.170000] [<c00105b8>] cpu_idle+0x68/0xd0 [ 16.170000] [<c03fe854>] start_kernel+0x260/0x2a0 [ 16.170000] [ 16.170000] [ 16.170000] stack backtrace: [ 16.170000] [<c00148f0>] (unwind_backtrace+0x0/0xf4) from [<c0059f20>] (print_irq_inversion_bug+0x1a0/0x210) [ 16.170000] [<c0059f20>] (print_irq_inversion_bug+0x1a0/0x210) from [<c005a030>] (check_usage_forwards+0xa0/0x10c) [ 16.170000] [<c005a030>] (check_usage_forwards+0xa0/0x10c) from [<c0059120>] (mark_lock+0x1d4/0x62c) [ 16.170000] [<c0059120>] (mark_lock+0x1d4/0x62c) from [<c005bbf4>] (__lock_acquire+0xae8/0x1b98) [ 16.170000] [<c005bbf4>] (__lock_acquire+0xae8/0x1b98) from [<c005cd44>] (lock_acquire+0xa0/0x108) [ 16.170000] [<c005cd44>] (lock_acquire+0xa0/0x108) from [<c02e67fc>] (_raw_spin_lock+0x2c/0x3c) [ 16.170000] [<c02e67fc>] (_raw_spin_lock+0x2c/0x3c) from [<c022fda8>] (snd_pcm_period_elapsed+0x34/0xd0) [ 16.170000] [<c022fda8>] (snd_pcm_period_elapsed+0x34/0xd0) from [<c01bed28>] (mxs_dma_tasklet+0x18/0x1c) [ 16.170000] [<c01bed28>] (mxs_dma_tasklet+0x18/0x1c) from [<c00235e4>] (tasklet_action+0xc8/0xd8) [ 16.170000] [<c00235e4>] (tasklet_action+0xc8/0xd8) from [<c0023b38>] (__do_softirq+0xa0/0x1e0) [ 16.170000] [<c0023b38>] (__do_softirq+0xa0/0x1e0) from [<c0023e10>] (irq_exit+0x8c/0x94) [ 16.170000] [<c0023e10>] (irq_exit+0x8c/0x94) from [<c0010080>] (handle_IRQ+0x34/0x84) [ 16.170000] [<c0010080>] (handle_IRQ+0x34/0x84) from [<c000edd8>] (__irq_svc+0x38/0x60) [ 16.170000] [<c000edd8>] (__irq_svc+0x38/0x60) from [<c001029c>] (default_idle+0x40/0x48) [ 16.170000] [<c001029c>] (default_idle+0x40/0x48) from [<c00105b8>] (cpu_idle+0x68/0xd0) [ 16.170000] [<c00105b8>] (cpu_idle+0x68/0xd0) from [<c03fe854>] (start_kernel+0x260/0x2a0)
Will debug this, but any suggestion is appreaciated.
Thanks,
Fabio Estevam