Fixed
Created: Sep 11, 2014
Updated: Dec 3, 2018
Resolved Date: Sep 15, 2014
Found In Version: 6.0
Fix Version: 6.0.0.12
Severity: Standard
Applicable for: Wind River Linux 6
Component/s: BSP - Async
Be able to hear sound by headphone, but generate call trace after executing audio playback test, Logs:
root@localhost:~# speaker-test -c2 -twav -Dplughw:ADAU1761
speaker-test 1.0.27.2
Playback device is plughw:ADAU1761
Stream parameters are 48000Hz, S16_LE, 2 channels
WAV file(s)
Rate set to 48000Hz (requested 48000Hz)
Buffer size range from 64 to 65536
Period size range from 32 to 8192
Using max buffer size 65536
Periods = 4
was set period_size = 8192
was set buffer_size = 65536
0 - Front Left
=========================================================
[ INFO: possible irq lock inversion dependency detected ]
3.10.38-ltsi-WR6.0.0.0_standard #1 Not tainted
---------------------------------------------------------
swapper/0/0 just changed the state of lock:
(&(&substream->self_group.lock)->rlock){..-...}, at: [<805390b0>] snd_pcm_period_elapsed+0x50/0xe8
but this lock took another, SOFTIRQ-unsafe lock in the past:
(&(&map->spinlock)->rlock){+.+...}
and interrupts could create inverse lock ordering between them.
other info that might help us debug this:
Possible interrupt unsafe locking scenario:
CPU0 CPU1
---- ----
lock(&(&map->spinlock)->rlock);
local_irq_disable();
lock(&(&substream->self_group.lock)->rlock);
lock(&(&map->spinlock)->rlock);
<Interrupt>
lock(&(&substream->self_group.lock)->rlock);
*** DEADLOCK ***
1 lock held by swapper/0/0:
#0: (snd_pcm_link_rwlock){...-..}, at: [<805390a4>] snd_pcm_period_elapsed+0x44/0xe8
the shortest dependencies between 2nd lock and 1st lock:
-> (&(&map->spinlock)->rlock){+.+...} ops: 5 {
HARDIRQ-ON-W at:
[<80085668>] mark_lock+0x2dc/0x720
[<80087c70>] __lock_acquire+0x84c/0x1b0c
[<80089614>] lock_acquire+0x10c/0x214
[<806ac7e8>] _raw_spin_lock+0x48/0x58
[<803e9278>] regmap_lock_spinlock+0x1c/0x20
[<803e90a0>] regmap_read+0x40/0x70
[<8001f8ec>] zynq_slcr_read+0x30/0x54
[<8001fa64>] zynq_slcr_get_ocm_config+0x24/0x30
[<8001fc28>] zynq_ocm_probe+0x20/0x280
[<803dba3c>] platform_drv_probe+0x24/0x28
[<803da610>] driver_probe_device+0xb4/0x200
[<803da830>] __driver_attach+0x80/0xa4
[<803d8978>] bus_for_each_dev+0x84/0x98
[<803da0fc>] driver_attach+0x28/0x30
[<803d9c4c>] bus_add_driver+0xf0/0x258
[<803daf10>] driver_register+0xac/0xf0
[<803dc01c>] platform_driver_register+0x54/0x68
[<80962a0c>] zynq_ocm_init+0x14/0x1c
[<800088c8>] do_one_initcall+0xa0/0x144
[<8095acc4>] kernel_init_freeable+0x180/0x278
[<8069b160>] kernel_init+0x1c/0xf4
[<8000dea8>] ret_from_fork+0x14/0x20
SOFTIRQ-ON-W at:
[<80085668>] mark_lock+0x2dc/0x720
[<80087c94>] __lock_acquire+0x870/0x1b0c
[<80089614>] lock_acquire+0x10c/0x214
[<806ac7e8>] _raw_spin_lock+0x48/0x58
[<803e9278>] regmap_lock_spinlock+0x1c/0x20
[<803e90a0>] regmap_read+0x40/0x70
[<8001f8ec>] zynq_slcr_read+0x30/0x54
[<8001fa64>] zynq_slcr_get_ocm_config+0x24/0x30
[<8001fc28>] zynq_ocm_probe+0x20/0x280
[<803dba3c>] platform_drv_probe+0x24/0x28
[<803da610>] driver_probe_device+0xb4/0x200
[<803da830>] __driver_attach+0x80/0xa4
[<803d8978>] bus_for_each_dev+0x84/0x98
[<803da0fc>] driver_attach+0x28/0x30
[<803d9c4c>] bus_add_driver+0xf0/0x258
[<803daf10>] driver_register+0xac/0xf0
[<803dc01c>] platform_driver_register+0x54/0x68
[<80962a0c>] zynq_ocm_init+0x14/0x1c
[<800088c8>] do_one_initcall+0xa0/0x144
[<8095acc4>] kernel_init_freeable+0x180/0x278
[<8069b160>] kernel_init+0x1c/0xf4
[<8000dea8>] ret_from_fork+0x14/0x20
INITIAL USE at:
[<80085668>] mark_lock+0x2dc/0x720
[<80087ce0>] __lock_acquire+0x8bc/0x1b0c
[<80089614>] lock_acquire+0x10c/0x214
[<806ac7e8>] _raw_spin_lock+0x48/0x58
[<803e9278>] regmap_lock_spinlock+0x1c/0x20
[<803e90a0>] regmap_read+0x40/0x70
[<8001f8ec>] zynq_slcr_read+0x30/0x54
[<8001fa64>] zynq_slcr_get_ocm_config+0x24/0x30
[<8001fc28>] zynq_ocm_probe+0x20/0x280
[<803dba3c>] platform_drv_probe+0x24/0x28
[<803da610>] driver_probe_device+0xb4/0x200
[<803da830>] __driver_attach+0x80/0xa4
[<803d8978>] bus_for_each_dev+0x84/0x98
[<803da0fc>] driver_attach+0x28/0x30
[<803d9c4c>] bus_add_driver+0xf0/0x258
[<803daf10>] driver_register+0xac/0xf0
[<803dc01c>] platform_driver_register+0x54/0x68
[<80962a0c>] zynq_ocm_init+0x14/0x1c
[<800088c8>] do_one_initcall+0xa0/0x144
[<8095acc4>] kernel_init_freeable+0x180/0x278
[<8069b160>] kernel_init+0x1c/0xf4
[<8000dea8>] ret_from_fork+0x14/0x20
}
... key at: [<8113f3a4>] __key.26038+0x0/0x8
... acquired at:
[<80088b60>] __lock_acquire+0x173c/0x1b0c
[<80089614>] lock_acquire+0x10c/0x214
[<806ac7e8>] _raw_spin_lock+0x48/0x58
[<803e9278>] regmap_lock_spinlock+0x1c/0x20
[<803ebed4>] regmap_update_bits+0x34/0x6c
[<80552668>] axi_i2s_trigger+0x6c/0x7c
[<8054c178>] soc_pcm_trigger+0xb4/0xbc
[<805338b8>] snd_pcm_do_start+0x34/0x40
[<805335ac>] snd_pcm_action_single+0x48/0x74
[<805337f8>] snd_pcm_action_lock_irq+0x84/0xa4
[<80534648>] snd_pcm_common_ioctl1+0x9c/0xd38
[<80535754>] snd_pcm_playback_ioctl1+0x470/0x494
[<805357b0>] snd_pcm_playback_ioctl+0x38/0x44
[<80151ca0>] vfs_ioctl+0x38/0x4c
[<801527ec>] do_vfs_ioctl+0x4f8/0x5a4
[<801528f8>] SyS_ioctl+0x60/0x8c
[<8000dde0>] ret_fast_syscall+0x0/0x48
-> (&(&substream->self_group.lock)->rlock){..-...} ops: 59 {
IN-SOFTIRQ-W at:
[<80085668>] mark_lock+0x2dc/0x720
[<80087bcc>] __lock_acquire+0x7a8/0x1b0c
[<80089614>] lock_acquire+0x10c/0x214
[<806ac7e8>] _raw_spin_lock+0x48/0x58
[<805390b0>] snd_pcm_period_elapsed+0x50/0xe8
[<8055066c>] dmaengine_pcm_dma_complete+0x54/0x58
[<80385f84>] pl330_tasklet+0x414/0x564
[<80032f7c>] tasklet_action+0xb0/0x11c
[<800320ac>] __do_softirq+0x178/0x478
[<80032478>] do_softirq+0x58/0x7c
[<800327a8>] irq_exit+0x94/0xe0
[<8000ee28>] handle_IRQ+0x7c/0xa0
[<80008764>] gic_handle_irq+0x4c/0x70
[<806ad6c4>] __irq_svc+0x44/0x78
[<804f9994>] cpuidle_enter_state+0x64/0xf4
[<804f9ba4>] cpuidle_idle_call+0x180/0x3e4
[<8000f1d8>] arch_cpu_idle+0x18/0x4c
[<80077a00>] cpu_startup_entry+0x1d4/0x3a8
[<8069b10c>] rest_init+0x138/0x170
[<8095aae8>] start_kernel+0x2ec/0x348
INITIAL USE at:
[<80085668>] mark_lock+0x2dc/0x720
[<80087ce0>] __lock_acquire+0x8bc/0x1b0c
[<80089614>] lock_acquire+0x10c/0x214
[<806ac7e8>] _raw_spin_lock+0x48/0x58
[<80532afc>] snd_pcm_sync_ptr+0xd8/0x1a0
[<80534768>] snd_pcm_common_ioctl1+0x1bc/0xd38
[<80535754>] snd_pcm_playback_ioctl1+0x470/0x494
[<805357b0>] snd_pcm_playback_ioctl+0x38/0x44
[<80151ca0>] vfs_ioctl+0x38/0x4c
[<801527ec>] do_vfs_ioctl+0x4f8/0x5a4
[<801528f8>] SyS_ioctl+0x60/0x8c
[<8000dde0>] ret_fast_syscall+0x0/0x48
}
... key at: [<81141e14>] __key.24505+0x0/0x8
... acquired at:
[<800849b8>] print_irq_inversion_bug+0x188/0x1ec
[<80084b04>] check_usage_forwards+0xe8/0x10c
[<8008574c>] mark_lock+0x3c0/0x720
[<80087bcc>] __lock_acquire+0x7a8/0x1b0c
[<80089614>] lock_acquire+0x10c/0x214
[<806ac7e8>] _raw_spin_lock+0x48/0x58
[<805390b0>] snd_pcm_period_elapsed+0x50/0xe8
[<8055066c>] dmaengine_pcm_dma_complete+0x54/0x58
[<80385f84>] pl330_tasklet+0x414/0x564
[<80032f7c>] tasklet_action+0xb0/0x11c
[<800320ac>] __do_softirq+0x178/0x478
[<80032478>] do_softirq+0x58/0x7c
[<800327a8>] irq_exit+0x94/0xe0
[<8000ee28>] handle_IRQ+0x7c/0xa0
[<80008764>] gic_handle_irq+0x4c/0x70
[<806ad6c4>] __irq_svc+0x44/0x78
[<804f9994>] cpuidle_enter_state+0x64/0xf4
[<804f9ba4>] cpuidle_idle_call+0x180/0x3e4
[<8000f1d8>] arch_cpu_idle+0x18/0x4c
[<80077a00>] cpu_startup_entry+0x1d4/0x3a8
[<8069b10c>] rest_init+0x138/0x170
[<8095aae8>] start_kernel+0x2ec/0x348
stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.10.38-ltsi-WR6.0.0.0_standard #1
[<800170e0>] (unwind_backtrace+0x0/0xec) from [<800125ec>] (show_stack+0x20/0x24)
[<800125ec>] (show_stack+0x20/0x24) from [<806a718c>] (dump_stack+0x20/0x28)
[<806a718c>] (dump_stack+0x20/0x28) from [<800849d8>] (print_irq_inversion_bug+0x1a8/0x1ec)
[<800849d8>] (print_irq_inversion_bug+0x1a8/0x1ec) from [<80084b04>] (check_usage_forwards+0xe8/0x10c)
[<80084b04>] (check_usage_forwards+0xe8/0x10c) from [<8008574c>] (mark_lock+0x3c0/0x720)
[<8008574c>] (mark_lock+0x3c0/0x720) from [<80087bcc>] (__lock_acquire+0x7a8/0x1b0c)
[<80087bcc>] (__lock_acquire+0x7a8/0x1b0c) from [<80089614>] (lock_acquire+0x10c/0x214)
[<80089614>] (lock_acquire+0x10c/0x214) from [<806ac7e8>] (_raw_spin_lock+0x48/0x58)
[<806ac7e8>] (_raw_spin_lock+0x48/0x58) from [<805390b0>] (snd_pcm_period_elapsed+0x50/0xe8)
[<805390b0>] (snd_pcm_period_elapsed+0x50/0xe8) from [<8055066c>] (dmaengine_pcm_dma_complete+0x54/0x58)
[<8055066c>] (dmaengine_pcm_dma_complete+0x54/0x58) from [<80385f84>] (pl330_tasklet+0x414/0x564)
[<80385f84>] (pl330_tasklet+0x414/0x564) from [<80032f7c>] (tasklet_action+0xb0/0x11c)
[<80032f7c>] (tasklet_action+0xb0/0x11c) from [<800320ac>] (__do_softirq+0x178/0x478)
[<800320ac>] (__do_softirq+0x178/0x478) from [<80032478>] (do_softirq+0x58/0x7c)
[<80032478>] (do_softirq+0x58/0x7c) from [<800327a8>] (irq_exit+0x94/0xe0)
[<800327a8>] (irq_exit+0x94/0xe0) from [<8000ee28>] (handle_IRQ+0x7c/0xa0)
[<8000ee28>] (handle_IRQ+0x7c/0xa0) from [<80008764>] (gic_handle_irq+0x4c/0x70)
[<80008764>] (gic_handle_irq+0x4c/0x70) from [<806ad6c4>] (__irq_svc+0x44/0x78)
Exception stack(0x80a0bea8 to 0x80a0bef0)
bea0: 00000001 00382b8e 00000000 80a16c88 bf4bdba9 0000002d
bec0: 00000000 8196d2f8 bfb50be5 0000002d 80a0a000 80a0bf24 80a0bec0 80a0bef0
bee0: 80085d9c 804f9994 20000013 ffffffff
[<806ad6c4>] (__irq_svc+0x44/0x78) from [<804f9994>] (cpuidle_enter_state+0x64/0xf4)
[<804f9994>] (cpuidle_enter_state+0x64/0xf4) from [<804f9ba4>] (cpuidle_idle_call+0x180/0x3e4)
[<804f9ba4>] (cpuidle_idle_call+0x180/0x3e4) from [<8000f1d8>] (arch_cpu_idle+0x18/0x4c)
[<8000f1d8>] (arch_cpu_idle+0x18/0x4c) from [<80077a00>] (cpu_startup_entry+0x1d4/0x3a8)
[<80077a00>] (cpu_startup_entry+0x1d4/0x3a8) from [<8069b10c>] (rest_init+0x138/0x170)
[<8069b10c>] (rest_init+0x138/0x170) from [<8095aae8>] (start_kernel+0x2ec/0x348)
1 - Front Right
Time per period = 2.590659
0 - Front Left
1 - Front Right
Time per period = 3.071148
0 - Front Left
1 - Front Right
Time per period = 2.901849
0 - Front Left
1 - Front Right
Time per period = 3.071996
0 - Front Left
1 - Front Right
Time per period = 3.070780
0 - Front Left
1 - Front Right
Time per period = 2.902328
0 - Front Left
1 - Front Right
Time per period = 3.071240
0 - Front Left
1 - Front Right
Time per period = 3.071462
0 - Front Left
^CWrite error: -4,Interrupted system call
xrun_recovery failed: -4,Interrupted system call
Transfer failed: Interrupted system call
root@localhost:~#
1. build
--enable-board=xilinx-zynq --enable-kernel=standard --enable-rootfs=glibc-std --enable-test=yes --with-layer=/wr-testing/kts-test,/lpg-build/cdc/xdong/wr-testing/bts,/lpg-build/cdc/xdong/wr-testing/ltp --with-template=feature/kts-basic,feature/kts-extended,feature/kts-standard --enable-parallel-pkgbuilds=16 --enable-jobs=16 && make fs
2. boot from SD
# fatload mmc 0 0x2a00000 devicetree.dtb ; fatload mmc 0 0x3000000 uImageSD
# setenv bootargs console=ttyPS0,115200 earlyprintk root=/dev/mmcblk0p2 ro rootwait; bootm 0x3000000 - 0x2a00000
3.
# amixer cset name='Headphone Playback Volume' 57,57 -c1 && amixer cset name='DAC Playback Mux' 0 -c1 && amixer cset name='Right Playback Mixer Left DAC Switch' 1 -c1
# amixer cset name='Right Playback Mixer Right DAC Switch' 1 -c1 && amixer cset name='Left Playback Mixer Left DAC Switch' 1 -c1 && amixer cset name='Left Playback Mixer Right DAC Switch' 1 -c1
# speaker-test -c2 -twav -Dplughw:ADAU1761
