Wind River Support Network

HomeDefectsLIN6-8401
Fixed

LIN6-8401 : Generate call trace after executing audio playback test

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

Description

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:~#

Steps to Reproduce

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

Other Downloads


Live chat
Online