* [LOCKDEP] 33-rc8 Running aplay with pulse as the default [not found] <alpine.LFD.2.00.1002121142100.3922@localhost.localdomain> @ 2010-02-13 17:17 ` Ed Tomlinson 2010-02-13 19:18 ` Ed Tomlinson 2010-02-15 19:20 ` Takashi Iwai 0 siblings, 2 replies; 13+ messages in thread From: Ed Tomlinson @ 2010-02-13 17:17 UTC (permalink / raw) To: linux-kernel; +Cc: alsa-devel Hi, Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. --- pcm.pulse { type pulse } ctl.pulse { type pulse } pcm.!default { type pulse } ctl.!default { type pulse --- Try #1 Starting as root if I do: su - <id> aplay sound.wav <traceback inlined below> aplay sound.wav (silence) killall pulseaudio aplay sound.wav (works as expected now going thru pulseaudio) Try #2 Starting as root if I do: aplay sound.wav (works as expected using alsa alone) su - <id> aplay sound.wav <another lockdep traceback> aplay sound.wav (works as expected now going thru pulseaudio) With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. Ideas? Ed Tomlinson aplay -l **** List of PLAYBACK Hardware Devices **** card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] Subdevices: 0/1 Subdevice #0: subdevice #0 card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] Subdevices: 1/1 Subdevice #0: subdevice #0 card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] Subdevices: 1/1 Subdevice #0: subdevice #0 "ALC1200 Analog" is what has speakers connected The em28xx in the traceback is an input source from a usb hdtv dongle. pavucontrol setup has been verified. [ 91.070620] [ 91.070621] ======================================================= [ 91.071378] [ INFO: possible circular locking dependency detected ] [ 91.071378] 2.6.33-rc8-crc #106 [ 91.071378] ------------------------------------------------------- [ 91.071378] pulseaudio/2717 is trying to acquire lock: [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 91.071378] [ 91.071378] but task is already holding lock: [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] [ 91.071378] [ 91.071378] which lock already depends on the new lock. [ 91.071378] [ 91.071378] [ 91.071378] the existing dependency chain (in reverse order) is: [ 91.071378] [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 91.071378] [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 91.071378] [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 91.514885] [ 91.514885] -> #0 (&dev->lock){+.+.+.}: [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 91.514885] [ 91.514885] other info that might help us debug this: [ 91.514885] [ 91.514885] 1 lock held by pulseaudio/2717: [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] [ 91.514885] [ 91.514885] stack backtrace: [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 [ 91.514885] Call Trace: [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-13 17:17 ` [LOCKDEP] 33-rc8 Running aplay with pulse as the default Ed Tomlinson @ 2010-02-13 19:18 ` Ed Tomlinson 2010-02-15 19:20 ` Takashi Iwai 1 sibling, 0 replies; 13+ messages in thread From: Ed Tomlinson @ 2010-02-13 19:18 UTC (permalink / raw) To: linux-kernel; +Cc: alsa-devel On Saturday 13 February 2010 12:17:10 Ed Tomlinson wrote: Looks like can also trigger an opps that force me to reboot. I tried su - <id> pulseaudio -D and got the following lockdep traceback followed by an opps This is grover.unknown_domain (Linux x86_64 2.6.33-rc8-crc) 13:53:37 grover login: [ 87.254950] [ 87.254952] ======================================================= [ 87.255252] [ INFO: possible circular locking dependency detected ] [ 87.255252] 2.6.33-rc8-crc #106 [ 87.255252] ------------------------------------------------------- [ 87.255252] pulseaudio/2800 is trying to acquire lock: [ 87.255252] (&dev->lock){+.+.+.}, at: [<ffffffffa027d7f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 87.336024] [ 87.336024] but task is already holding lock: [ 87.336024] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa00ffcd2>] snd_pcm_open+0x182/0x450 [snd_pcm] [ 87.336024] [ 87.336024] which lock already depends on the new lock. [ 87.336024] [ 87.336024] [ 87.336024] the existing dependency chain (in reverse order) is: [ 87.336024] [ 87.336024] -> #3 (&pcm->open_mutex){+.+.+.}: [ 87.336024] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 [ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 87.336024] [<ffffffffa00fbd32>] snd_pcm_release+0x42/0xb0 [snd_pcm] [ 87.336024] [<ffffffff8112115d>] __fput+0x15d/0x290 [ 87.336024] [<ffffffff811212ad>] fput+0x1d/0x30 [ 87.336024] [<ffffffff810fe001>] remove_vma+0x51/0x80 [ 87.336024] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 [ 87.336024] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 [ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 87.336024] [ 87.336024] -> #2 (&mm->mmap_sem){++++++}: [ 87.336024] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 [ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 87.336024] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 [ 87.336024] [<ffffffff8113102b>] filldir+0x7b/0xe0 [ 87.336024] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 [ 87.336024] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 [ 87.336024] [<ffffffff8113144d>] sys_getdents+0xad/0x110 [ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 87.336024] [ 87.336024] -> #1 (sysfs_mutex){+.+.+.}: [ 87.336024] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 [ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 87.336024] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 [ 87.336024] [<ffffffff8118bc58>] create_dir+0x58/0xb0 [ 87.336024] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 [ 87.336024] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 [ 87.336024] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 [ 87.336024] [<ffffffff8123eee4>] kobject_add+0x44/0x70 [ 87.336024] [<ffffffff81392510>] device_add+0xb0/0x5e0 [ 87.336024] [<ffffffff81392a5e>] device_register+0x1e/0x30 [ 87.336024] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 [ 87.336024] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 [ 87.336024] [<ffffffffa0207ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] [ 87.336024] [<ffffffffa0209daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] [ 87.336024] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 [ 87.336024] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 [ 87.336024] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 [ 87.336024] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 [ 87.336024] [<ffffffff8139535e>] driver_attach+0x1e/0x20 [ 87.336024] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 [ 87.336024] [<ffffffff81395a58>] driver_register+0x98/0x140 [ 87.336024] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 [ 87.336024] [<ffffffffa021e023>] 0xffffffffa021e023 [ 87.336024] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 [ 87.336024] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 [ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 87.336024] [ 87.336024] -> #0 (&dev->lock){+.+.+.}: [ 87.336024] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 [ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 87.336024] [<ffffffffa027d7f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 87.336024] [<ffffffffa00fbdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] [ 87.336024] [<ffffffffa00ffce9>] snd_pcm_open+0x199/0x450 [snd_pcm] [ 87.336024] [<ffffffffa00fffd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] [ 87.336024] [<ffffffffa00da778>] snd_open+0x198/0x4e0 [snd] [ 87.336024] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 [ 87.336024] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 [ 87.336024] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 [ 87.336024] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 [ 87.336024] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 [ 87.336024] [<ffffffff8111ea70>] sys_open+0x20/0x30 [ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 87.336024] [ 87.336024] other info that might help us debug this: [ 87.336024] [ 87.336024] 1 lock held by pulseaudio/2800: [ 87.336024] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa00ffcd2>] snd_pcm_open+0x182/0x450 [snd_pcm] [ 87.336024] [ 87.336024] stack backtrace: [ 87.336024] Pid: 2800, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 [ 87.336024] Call Trace: [ 87.336024] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 [ 87.336024] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 [ 87.336024] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 [ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 [ 87.336024] [<ffffffffa027d7f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 [ 87.336024] [<ffffffffa027d7f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 87.336024] [<ffffffffa027d7f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 87.336024] [<ffffffffa00fac70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] [ 87.336024] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 [ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 [ 87.336024] [<ffffffffa027d7f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] [ 87.336024] [<ffffffffa00fbdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] [ 87.336024] [<ffffffffa00ffce9>] snd_pcm_open+0x199/0x450 [snd_pcm] [ 87.336024] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 [ 87.336024] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 [ 87.336024] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 [ 87.336024] [<ffffffffa00fffd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] [ 87.336024] [<ffffffffa00da778>] snd_open+0x198/0x4e0 [snd] [ 87.336024] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 [ 87.336024] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 [ 87.336024] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 [ 87.336024] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 [ 87.336024] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 [ 87.336024] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 [ 87.336024] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 [ 87.336024] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 [ 87.336024] [<ffffffff8111ea70>] sys_open+0x20/0x30 [ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 89.153381] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. [ 89.402672] BUG: unable to handle kernel NULL pointer dereference at (null) [ 89.403537] IP: [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0 [ 89.403537] PGD 16c019067 PUD 16c01a067 PMD 0 [ 89.403537] Oops: 0000 [#1] PREEMPT SMP [ 89.403537] last sysfs file: /sys/devices/pci0000:00/0000:00:14.2/sound/card0/uevent [ 89.403537] CPU 1 [ 89.403537] Pid: 2813, comm: console-kit-dae Not tainted 2.6.33-rc8-crc #106 M3A78-T/System Product Name [ 89.403537] RIP: 0010:[<ffffffff8104dfe6>] [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0 [ 89.403537] RSP: 0018:ffff88016dfcfe88 EFLAGS: 00010293 [ 89.403537] RAX: ffff88016d29c318 RBX: fffffffffffffcf8 RCX: ffff88016b77d800 [ 89.403537] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff81a7f4c8 [ 89.403537] RBP: ffff88016dfcfee8 R08: 0000000000000002 R09: 0000000000000000 [ 89.403537] R10: 0000000000000000 R11: 0000000000000246 R12: ffff88016dfcff08 [ 89.403537] R13: ffff88016d29c020 R14: ffff88016bd38000 R15: ffff88016bd38000 [ 89.403537] FS: 00007f7fd4a7b700(0000) GS:ffff880028280000(0000) knlGS:0000000000000000 [ 89.403537] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 89.403537] CR2: 0000000000000000 CR3: 000000016b12e000 CR4: 00000000000006e0 [ 89.403537] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 89.600024] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 89.600024] Process console-kit-dae (pid: 2813, threadinfo ffff88016dfce000, task ffff88016bd38000) [ 89.600024] Stack: [ 89.600024] ffff88016bd38000 ffff88016bd38000 ffff88016dfcff30 ffff88016d29c318 [ 89.600024] <0> ffff88016dfcfee8 0000000000000000 ffffffff81069880 00007fff88aaff4c [ 89.600024] <0> ffff88016b77d880 0000000000000000 000000000061ea60 00007fff88aaff9c [ 89.600024] Call Trace: [ 89.600024] [<ffffffff81069880>] ? find_get_pid+0x0/0x80 [ 89.600024] [<ffffffff8104e169>] sys_wait4+0x89/0xf0 [ 89.600024] [<ffffffff8104b650>] ? child_wait_callback+0x0/0x80 [ 89.600024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 89.600024] Code: eb 29 0f 1f 00 48 89 da be 01 00 00 00 4c 89 e7 e8 f0 f1 ff ff 85 c0 0f 85 d0 00 00 00 48 8b 9b 08 03 00 00 48 81 eb 08 03 00 00 <48> 8b 83 08 03 00 00 0f 18 08 48 8d 83 08 03 00 00 48 39 45 b8 [ 89.600024] RIP [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0 [ 89.600024] RSP <ffff88016dfcfe88> [ 89.600024] CR2: 0000000000000000 [ 89.600489] ---[ end trace 3efd4205cd3392b3 ]--- [ 89.600492] note: console-kit-dae[2813] exited with preempt_count 1 > Hi, > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > --- > pcm.pulse { > type pulse > } > > ctl.pulse { > type pulse > } > > pcm.!default { > type pulse > } > ctl.!default { > type pulse > --- > > Try #1 > Starting as root if I do: > su - <id> > aplay sound.wav > <traceback inlined below> > aplay sound.wav > (silence) > killall pulseaudio > aplay sound.wav > (works as expected now going thru pulseaudio) > > Try #2 > Starting as root if I do: > aplay sound.wav > (works as expected using alsa alone) > su - <id> > aplay sound.wav > <another lockdep traceback> > aplay sound.wav > (works as expected now going thru pulseaudio) > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > Ideas? > Ed Tomlinson > > aplay -l > **** List of PLAYBACK Hardware Devices **** > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > Subdevices: 0/1 > Subdevice #0: subdevice #0 > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > Subdevices: 1/1 > Subdevice #0: subdevice #0 > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > Subdevices: 1/1 > Subdevice #0: subdevice #0 > > "ALC1200 Analog" is what has speakers connected > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > pavucontrol setup has been verified. > > [ 91.070620] > [ 91.070621] ======================================================= > [ 91.071378] [ INFO: possible circular locking dependency detected ] > [ 91.071378] 2.6.33-rc8-crc #106 > [ 91.071378] ------------------------------------------------------- > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.071378] > [ 91.071378] but task is already holding lock: > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > [ 91.071378] > [ 91.071378] which lock already depends on the new lock. > [ 91.071378] > [ 91.071378] > [ 91.071378] the existing dependency chain (in reverse order) is: > [ 91.071378] > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.071378] > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.071378] > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.514885] > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.514885] > [ 91.514885] other info that might help us debug this: > [ 91.514885] > [ 91.514885] 1 lock held by pulseaudio/2717: > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > [ 91.514885] > [ 91.514885] stack backtrace: > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > [ 91.514885] Call Trace: > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. > > > > > > -- > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > Please read the FAQ at http://www.tux.org/lkml/ > > ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-13 17:17 ` [LOCKDEP] 33-rc8 Running aplay with pulse as the default Ed Tomlinson 2010-02-13 19:18 ` Ed Tomlinson @ 2010-02-15 19:20 ` Takashi Iwai 2010-02-15 19:21 ` Takashi Iwai 1 sibling, 1 reply; 13+ messages in thread From: Takashi Iwai @ 2010-02-15 19:20 UTC (permalink / raw) To: Ed Tomlinson; +Cc: alsa-devel, linux-kernel At Sat, 13 Feb 2010 12:17:10 -0500, Ed Tomlinson wrote: > > Hi, > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > --- > pcm.pulse { > type pulse > } > > ctl.pulse { > type pulse > } > > pcm.!default { > type pulse > } > ctl.!default { > type pulse > --- > > Try #1 > Starting as root if I do: > su - <id> > aplay sound.wav > <traceback inlined below> > aplay sound.wav > (silence) > killall pulseaudio > aplay sound.wav > (works as expected now going thru pulseaudio) > > Try #2 > Starting as root if I do: > aplay sound.wav > (works as expected using alsa alone) > su - <id> > aplay sound.wav > <another lockdep traceback> > aplay sound.wav > (works as expected now going thru pulseaudio) > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > Ideas? > Ed Tomlinson > > aplay -l > **** List of PLAYBACK Hardware Devices **** > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > Subdevices: 0/1 > Subdevice #0: subdevice #0 > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > Subdevices: 1/1 > Subdevice #0: subdevice #0 > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > Subdevices: 1/1 > Subdevice #0: subdevice #0 > > "ALC1200 Analog" is what has speakers connected > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > pavucontrol setup has been verified. > > [ 91.070620] > [ 91.070621] ======================================================= > [ 91.071378] [ INFO: possible circular locking dependency detected ] > [ 91.071378] 2.6.33-rc8-crc #106 > [ 91.071378] ------------------------------------------------------- > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.071378] > [ 91.071378] but task is already holding lock: > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > [ 91.071378] > [ 91.071378] which lock already depends on the new lock. > [ 91.071378] > [ 91.071378] > [ 91.071378] the existing dependency chain (in reverse order) is: > [ 91.071378] > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.071378] > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.071378] > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.514885] > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 91.514885] > [ 91.514885] other info that might help us debug this: > [ 91.514885] > [ 91.514885] 1 lock held by pulseaudio/2717: > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > [ 91.514885] > [ 91.514885] stack backtrace: > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > [ 91.514885] Call Trace: > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. It looks rather a bug of em28xx driver. Changing dev->lock with an individual one that is only for audio instance should fix the problem. Takashi ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-15 19:20 ` Takashi Iwai @ 2010-02-15 19:21 ` Takashi Iwai 2010-02-15 22:24 ` Ed Tomlinson 0 siblings, 1 reply; 13+ messages in thread From: Takashi Iwai @ 2010-02-15 19:21 UTC (permalink / raw) To: Ed Tomlinson; +Cc: Rafael J. Wysocki, alsa-devel, linux-kernel At Mon, 15 Feb 2010 20:20:22 +0100, I wrote: > > At Sat, 13 Feb 2010 12:17:10 -0500, > Ed Tomlinson wrote: > > > > Hi, > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > > > --- > > pcm.pulse { > > type pulse > > } > > > > ctl.pulse { > > type pulse > > } > > > > pcm.!default { > > type pulse > > } > > ctl.!default { > > type pulse > > --- > > > > Try #1 > > Starting as root if I do: > > su - <id> > > aplay sound.wav > > <traceback inlined below> > > aplay sound.wav > > (silence) > > killall pulseaudio > > aplay sound.wav > > (works as expected now going thru pulseaudio) > > > > Try #2 > > Starting as root if I do: > > aplay sound.wav > > (works as expected using alsa alone) > > su - <id> > > aplay sound.wav > > <another lockdep traceback> > > aplay sound.wav > > (works as expected now going thru pulseaudio) > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > > > Ideas? > > Ed Tomlinson > > > > aplay -l > > **** List of PLAYBACK Hardware Devices **** > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > > Subdevices: 0/1 > > Subdevice #0: subdevice #0 > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > > Subdevices: 1/1 > > Subdevice #0: subdevice #0 > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > > Subdevices: 1/1 > > Subdevice #0: subdevice #0 > > > > "ALC1200 Analog" is what has speakers connected > > > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > > > pavucontrol setup has been verified. > > > > [ 91.070620] > > [ 91.070621] ======================================================= > > [ 91.071378] [ INFO: possible circular locking dependency detected ] > > [ 91.071378] 2.6.33-rc8-crc #106 > > [ 91.071378] ------------------------------------------------------- > > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > [ 91.071378] > > [ 91.071378] but task is already holding lock: > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > [ 91.071378] > > [ 91.071378] which lock already depends on the new lock. > > [ 91.071378] > > [ 91.071378] > > [ 91.071378] the existing dependency chain (in reverse order) is: > > [ 91.071378] > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > [ 91.071378] > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > [ 91.071378] > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > [ 91.514885] > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > [ 91.514885] > > [ 91.514885] other info that might help us debug this: > > [ 91.514885] > > [ 91.514885] 1 lock held by pulseaudio/2717: > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > [ 91.514885] > > [ 91.514885] stack backtrace: > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > > [ 91.514885] Call Trace: > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. > > It looks rather a bug of em28xx driver. Changing dev->lock with an > individual one that is only for audio instance should fix the > problem. And, I believe this is no regression but a long-standing problem. It hits just occasionally by an app like pulseauiod which loves tight races. Takashi ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-15 19:21 ` Takashi Iwai @ 2010-02-15 22:24 ` Ed Tomlinson 2010-02-15 22:35 ` Takashi Iwai 0 siblings, 1 reply; 13+ messages in thread From: Ed Tomlinson @ 2010-02-15 22:24 UTC (permalink / raw) To: Takashi Iwai; +Cc: Rafael J. Wysocki, linux-kernel, alsa-devel On Monday 15 February 2010 14:21:55 Takashi Iwai wrote: > At Mon, 15 Feb 2010 20:20:22 +0100, > I wrote: > > > > At Sat, 13 Feb 2010 12:17:10 -0500, > > Ed Tomlinson wrote: > > > > > > Hi, > > > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > > > > > --- > > > pcm.pulse { > > > type pulse > > > } > > > > > > ctl.pulse { > > > type pulse > > > } > > > > > > pcm.!default { > > > type pulse > > > } > > > ctl.!default { > > > type pulse > > > --- > > > > > > Try #1 > > > Starting as root if I do: > > > su - <id> > > > aplay sound.wav > > > <traceback inlined below> > > > aplay sound.wav > > > (silence) > > > killall pulseaudio > > > aplay sound.wav > > > (works as expected now going thru pulseaudio) > > > > > > Try #2 > > > Starting as root if I do: > > > aplay sound.wav > > > (works as expected using alsa alone) > > > su - <id> > > > aplay sound.wav > > > <another lockdep traceback> > > > aplay sound.wav > > > (works as expected now going thru pulseaudio) > > > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > > > > > Ideas? > > > Ed Tomlinson > > > > > > aplay -l > > > **** List of PLAYBACK Hardware Devices **** > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > > > Subdevices: 0/1 > > > Subdevice #0: subdevice #0 > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > > > Subdevices: 1/1 > > > Subdevice #0: subdevice #0 > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > > > Subdevices: 1/1 > > > Subdevice #0: subdevice #0 > > > > > > "ALC1200 Analog" is what has speakers connected > > > > > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > > > > > pavucontrol setup has been verified. > > > > > > [ 91.070620] > > > [ 91.070621] ======================================================= > > > [ 91.071378] [ INFO: possible circular locking dependency detected ] > > > [ 91.071378] 2.6.33-rc8-crc #106 > > > [ 91.071378] ------------------------------------------------------- > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > [ 91.071378] > > > [ 91.071378] but task is already holding lock: > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > [ 91.071378] > > > [ 91.071378] which lock already depends on the new lock. > > > [ 91.071378] > > > [ 91.071378] > > > [ 91.071378] the existing dependency chain (in reverse order) is: > > > [ 91.071378] > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > [ 91.071378] > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > [ 91.071378] > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > [ 91.514885] > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > [ 91.514885] > > > [ 91.514885] other info that might help us debug this: > > > [ 91.514885] > > > [ 91.514885] 1 lock held by pulseaudio/2717: > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > [ 91.514885] > > > [ 91.514885] stack backtrace: > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > > > [ 91.514885] Call Trace: > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. > > > > It looks rather a bug of em28xx driver. Changing dev->lock with an > > individual one that is only for audio instance should fix the > > problem. > > And, I believe this is no regression but a long-standing problem. > It hits just occasionally by an app like pulseauiod which loves > tight races. I guess it depends on how you define a regression. From my POV it worked in all three cases on .32, its failing in .33-rc and in one case is oppsing. In my books thats a regression. There may have been races in .32 but they did not trigger lockdep and never oppsed. In any case, the real question is how do we fix the problem? Ed ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-15 22:24 ` Ed Tomlinson @ 2010-02-15 22:35 ` Takashi Iwai 2010-02-15 23:21 ` Takashi Iwai 0 siblings, 1 reply; 13+ messages in thread From: Takashi Iwai @ 2010-02-15 22:35 UTC (permalink / raw) To: Ed Tomlinson; +Cc: Rafael J. Wysocki, alsa-devel, linux-kernel At Mon, 15 Feb 2010 17:24:54 -0500, Ed Tomlinson wrote: > > On Monday 15 February 2010 14:21:55 Takashi Iwai wrote: > > At Mon, 15 Feb 2010 20:20:22 +0100, > > I wrote: > > > > > > At Sat, 13 Feb 2010 12:17:10 -0500, > > > Ed Tomlinson wrote: > > > > > > > > Hi, > > > > > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > > > > > > > --- > > > > pcm.pulse { > > > > type pulse > > > > } > > > > > > > > ctl.pulse { > > > > type pulse > > > > } > > > > > > > > pcm.!default { > > > > type pulse > > > > } > > > > ctl.!default { > > > > type pulse > > > > --- > > > > > > > > Try #1 > > > > Starting as root if I do: > > > > su - <id> > > > > aplay sound.wav > > > > <traceback inlined below> > > > > aplay sound.wav > > > > (silence) > > > > killall pulseaudio > > > > aplay sound.wav > > > > (works as expected now going thru pulseaudio) > > > > > > > > Try #2 > > > > Starting as root if I do: > > > > aplay sound.wav > > > > (works as expected using alsa alone) > > > > su - <id> > > > > aplay sound.wav > > > > <another lockdep traceback> > > > > aplay sound.wav > > > > (works as expected now going thru pulseaudio) > > > > > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > > > > > > > Ideas? > > > > Ed Tomlinson > > > > > > > > aplay -l > > > > **** List of PLAYBACK Hardware Devices **** > > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > > > > Subdevices: 0/1 > > > > Subdevice #0: subdevice #0 > > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > > > > Subdevices: 1/1 > > > > Subdevice #0: subdevice #0 > > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > > > > Subdevices: 1/1 > > > > Subdevice #0: subdevice #0 > > > > > > > > "ALC1200 Analog" is what has speakers connected > > > > > > > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > > > > > > > pavucontrol setup has been verified. > > > > > > > > [ 91.070620] > > > > [ 91.070621] ======================================================= > > > > [ 91.071378] [ INFO: possible circular locking dependency detected ] > > > > [ 91.071378] 2.6.33-rc8-crc #106 > > > > [ 91.071378] ------------------------------------------------------- > > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > [ 91.071378] > > > > [ 91.071378] but task is already holding lock: > > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > [ 91.071378] > > > > [ 91.071378] which lock already depends on the new lock. > > > > [ 91.071378] > > > > [ 91.071378] > > > > [ 91.071378] the existing dependency chain (in reverse order) is: > > > > [ 91.071378] > > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > [ 91.071378] > > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > [ 91.071378] > > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > [ 91.514885] > > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > [ 91.514885] > > > > [ 91.514885] other info that might help us debug this: > > > > [ 91.514885] > > > > [ 91.514885] 1 lock held by pulseaudio/2717: > > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > [ 91.514885] > > > > [ 91.514885] stack backtrace: > > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > > > > [ 91.514885] Call Trace: > > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. > > > > > > It looks rather a bug of em28xx driver. Changing dev->lock with an > > > individual one that is only for audio instance should fix the > > > problem. > > > > And, I believe this is no regression but a long-standing problem. > > It hits just occasionally by an app like pulseauiod which loves > > tight races. > > I guess it depends on how you define a regression. From my POV it worked > in all three cases on .32, its failing in .33-rc and in one case is oppsing. In > my books thats a regression. There may have been races in .32 but they > did not trigger lockdep and never oppsed. Is the kernel config really identical? Is only the kernel replaced? I haven't followed em28xx development, so it's possible that the bug came from that side, though. But, in the PCM core, there is no fundamental change that may trigger this bug during 2.6.33 development. > In any case, the real question is how do we fix the problem? As I mentioned, replace the mutex in em28xx code. Takashi ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-15 22:35 ` Takashi Iwai @ 2010-02-15 23:21 ` Takashi Iwai 2010-02-16 13:19 ` Ed Tomlinson 0 siblings, 1 reply; 13+ messages in thread From: Takashi Iwai @ 2010-02-15 23:21 UTC (permalink / raw) To: Ed Tomlinson; +Cc: Rafael J. Wysocki, alsa-devel, linux-kernel At Mon, 15 Feb 2010 23:35:26 +0100, I wrote: > > At Mon, 15 Feb 2010 17:24:54 -0500, > Ed Tomlinson wrote: > > > > On Monday 15 February 2010 14:21:55 Takashi Iwai wrote: > > > At Mon, 15 Feb 2010 20:20:22 +0100, > > > I wrote: > > > > > > > > At Sat, 13 Feb 2010 12:17:10 -0500, > > > > Ed Tomlinson wrote: > > > > > > > > > > Hi, > > > > > > > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > > > > > > > > > --- > > > > > pcm.pulse { > > > > > type pulse > > > > > } > > > > > > > > > > ctl.pulse { > > > > > type pulse > > > > > } > > > > > > > > > > pcm.!default { > > > > > type pulse > > > > > } > > > > > ctl.!default { > > > > > type pulse > > > > > --- > > > > > > > > > > Try #1 > > > > > Starting as root if I do: > > > > > su - <id> > > > > > aplay sound.wav > > > > > <traceback inlined below> > > > > > aplay sound.wav > > > > > (silence) > > > > > killall pulseaudio > > > > > aplay sound.wav > > > > > (works as expected now going thru pulseaudio) > > > > > > > > > > Try #2 > > > > > Starting as root if I do: > > > > > aplay sound.wav > > > > > (works as expected using alsa alone) > > > > > su - <id> > > > > > aplay sound.wav > > > > > <another lockdep traceback> > > > > > aplay sound.wav > > > > > (works as expected now going thru pulseaudio) > > > > > > > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > > > > > > > > > Ideas? > > > > > Ed Tomlinson > > > > > > > > > > aplay -l > > > > > **** List of PLAYBACK Hardware Devices **** > > > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > > > > > Subdevices: 0/1 > > > > > Subdevice #0: subdevice #0 > > > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > > > > > Subdevices: 1/1 > > > > > Subdevice #0: subdevice #0 > > > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > > > > > Subdevices: 1/1 > > > > > Subdevice #0: subdevice #0 > > > > > > > > > > "ALC1200 Analog" is what has speakers connected > > > > > > > > > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > > > > > > > > > pavucontrol setup has been verified. > > > > > > > > > > [ 91.070620] > > > > > [ 91.070621] ======================================================= > > > > > [ 91.071378] [ INFO: possible circular locking dependency detected ] > > > > > [ 91.071378] 2.6.33-rc8-crc #106 > > > > > [ 91.071378] ------------------------------------------------------- > > > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > > > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > [ 91.071378] > > > > > [ 91.071378] but task is already holding lock: > > > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > > [ 91.071378] > > > > > [ 91.071378] which lock already depends on the new lock. > > > > > [ 91.071378] > > > > > [ 91.071378] > > > > > [ 91.071378] the existing dependency chain (in reverse order) is: > > > > > [ 91.071378] > > > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > > > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > > > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > > > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > > > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > > > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > [ 91.071378] > > > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > > > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > > > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > > > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > > > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > [ 91.071378] > > > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > > > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > > > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > > > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > > > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > > > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > > > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > > > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > > > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > > > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > > > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > > > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > > > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > > > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > > > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > > > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > > > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > > > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > > > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > > > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > > > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > > > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > > > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > [ 91.514885] > > > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > [ 91.514885] > > > > > [ 91.514885] other info that might help us debug this: > > > > > [ 91.514885] > > > > > [ 91.514885] 1 lock held by pulseaudio/2717: > > > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > > [ 91.514885] > > > > > [ 91.514885] stack backtrace: > > > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > > > > > [ 91.514885] Call Trace: > > > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > > > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > > > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > > > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > > > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. > > > > > > > > It looks rather a bug of em28xx driver. Changing dev->lock with an > > > > individual one that is only for audio instance should fix the > > > > problem. > > > > > > And, I believe this is no regression but a long-standing problem. > > > It hits just occasionally by an app like pulseauiod which loves > > > tight races. > > > > I guess it depends on how you define a regression. From my POV it worked > > in all three cases on .32, its failing in .33-rc and in one case is oppsing. In > > my books thats a regression. There may have been races in .32 but they > > did not trigger lockdep and never oppsed. > > Is the kernel config really identical? Is only the kernel replaced? > > I haven't followed em28xx development, so it's possible that the bug > came from that side, though. But, in the PCM core, there is no > fundamental change that may trigger this bug during 2.6.33 > development. > > > In any case, the real question is how do we fix the problem? > > As I mentioned, replace the mutex in em28xx code. I mean, something like below (totally untested). Takashi --- diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c index bd78338..c2632c4 100644 --- a/drivers/media/video/em28xx/em28xx-audio.c +++ b/drivers/media/video/em28xx/em28xx-audio.c @@ -301,9 +301,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) /* Sets volume, mute, etc */ dev->mute = 0; - mutex_lock(&dev->lock); + mutex_lock(&dev->adev.mutex); ret = em28xx_audio_analog_set(dev); - mutex_unlock(&dev->lock); + mutex_unlock(&dev->adev.mutex); if (ret < 0) goto err; @@ -315,9 +315,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) dprintk("changing alternate number to 7\n"); } - mutex_lock(&dev->lock); + mutex_lock(&dev->adev.mutex); dev->adev.users++; - mutex_unlock(&dev->lock); + mutex_unlock(&dev->adev.mutex); snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS); dev->adev.capture_pcm_substream = substream; @@ -336,7 +336,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) dprintk("closing device\n"); dev->mute = 1; - mutex_lock(&dev->lock); + mutex_lock(&dev->adev.mutex); dev->adev.users--; em28xx_audio_analog_set(dev); if (substream->runtime->dma_area) { @@ -344,7 +344,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) vfree(substream->runtime->dma_area); substream->runtime->dma_area = NULL; } - mutex_unlock(&dev->lock); + mutex_unlock(&dev->adev.mutex); return 0; } @@ -479,6 +479,7 @@ static int em28xx_audio_init(struct em28xx *dev) return err; spin_lock_init(&adev->slock); + mutex_init(&adev->mutex); err = snd_pcm_new(card, "Em28xx Audio", 0, 0, 1, &pcm); if (err < 0) { snd_card_free(card); diff --git a/drivers/media/video/em28xx/em28xx.h b/drivers/media/video/em28xx/em28xx.h index 80d9b4f..bb1d754 100644 --- a/drivers/media/video/em28xx/em28xx.h +++ b/drivers/media/video/em28xx/em28xx.h @@ -461,6 +461,7 @@ struct em28xx_audio { int users; enum em28xx_stream_state capture_stream; spinlock_t slock; + struct mutex mutex; }; struct em28xx; ^ permalink raw reply related [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-15 23:21 ` Takashi Iwai @ 2010-02-16 13:19 ` Ed Tomlinson 2010-02-16 13:37 ` Takashi Iwai 0 siblings, 1 reply; 13+ messages in thread From: Ed Tomlinson @ 2010-02-16 13:19 UTC (permalink / raw) To: Takashi Iwai; +Cc: Rafael J. Wysocki, linux-kernel, alsa-devel On Monday 15 February 2010 18:21:17 Takashi Iwai wrote: > At Mon, 15 Feb 2010 23:35:26 +0100, > I wrote: > > > > At Mon, 15 Feb 2010 17:24:54 -0500, > > Ed Tomlinson wrote: > > > > > > On Monday 15 February 2010 14:21:55 Takashi Iwai wrote: > > > > At Mon, 15 Feb 2010 20:20:22 +0100, > > > > I wrote: > > > > > > > > > > At Sat, 13 Feb 2010 12:17:10 -0500, > > > > > Ed Tomlinson wrote: > > > > > > > > > > > > Hi, > > > > > > > > > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > > > > > > > > > > > --- > > > > > > pcm.pulse { > > > > > > type pulse > > > > > > } > > > > > > > > > > > > ctl.pulse { > > > > > > type pulse > > > > > > } > > > > > > > > > > > > pcm.!default { > > > > > > type pulse > > > > > > } > > > > > > ctl.!default { > > > > > > type pulse > > > > > > --- > > > > > > > > > > > > Try #1 > > > > > > Starting as root if I do: > > > > > > su - <id> > > > > > > aplay sound.wav > > > > > > <traceback inlined below> > > > > > > aplay sound.wav > > > > > > (silence) > > > > > > killall pulseaudio > > > > > > aplay sound.wav > > > > > > (works as expected now going thru pulseaudio) > > > > > > > > > > > > Try #2 > > > > > > Starting as root if I do: > > > > > > aplay sound.wav > > > > > > (works as expected using alsa alone) > > > > > > su - <id> > > > > > > aplay sound.wav > > > > > > <another lockdep traceback> > > > > > > aplay sound.wav > > > > > > (works as expected now going thru pulseaudio) > > > > > > > > > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > > > > > > > > > > > Ideas? > > > > > > Ed Tomlinson > > > > > > > > > > > > aplay -l > > > > > > **** List of PLAYBACK Hardware Devices **** > > > > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > > > > > > Subdevices: 0/1 > > > > > > Subdevice #0: subdevice #0 > > > > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > > > > > > Subdevices: 1/1 > > > > > > Subdevice #0: subdevice #0 > > > > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > > > > > > Subdevices: 1/1 > > > > > > Subdevice #0: subdevice #0 > > > > > > > > > > > > "ALC1200 Analog" is what has speakers connected > > > > > > > > > > > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > > > > > > > > > > > pavucontrol setup has been verified. > > > > > > > > > > > > [ 91.070620] > > > > > > [ 91.070621] ======================================================= > > > > > > [ 91.071378] [ INFO: possible circular locking dependency detected ] > > > > > > [ 91.071378] 2.6.33-rc8-crc #106 > > > > > > [ 91.071378] ------------------------------------------------------- > > > > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > > > > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > [ 91.071378] > > > > > > [ 91.071378] but task is already holding lock: > > > > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > > > [ 91.071378] > > > > > > [ 91.071378] which lock already depends on the new lock. > > > > > > [ 91.071378] > > > > > > [ 91.071378] > > > > > > [ 91.071378] the existing dependency chain (in reverse order) is: > > > > > > [ 91.071378] > > > > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > > > > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > > > > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > > > > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > > > > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > > > > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > [ 91.071378] > > > > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > > > > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > > > > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > > > > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > > > > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > [ 91.071378] > > > > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > > > > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > > > > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > > > > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > > > > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > > > > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > > > > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > > > > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > > > > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > > > > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > > > > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > > > > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > > > > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > > > > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > > > > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > > > > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > > > > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > > > > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > > > > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > > > > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > > > > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > > > > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > > > > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > [ 91.514885] > > > > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > [ 91.514885] > > > > > > [ 91.514885] other info that might help us debug this: > > > > > > [ 91.514885] > > > > > > [ 91.514885] 1 lock held by pulseaudio/2717: > > > > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > > > [ 91.514885] > > > > > > [ 91.514885] stack backtrace: > > > > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > > > > > > [ 91.514885] Call Trace: > > > > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > > > > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > > > > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > > > > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > > > > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. > > > > > > > > > > It looks rather a bug of em28xx driver. Changing dev->lock with an > > > > > individual one that is only for audio instance should fix the > > > > > problem. > > > > > > > > And, I believe this is no regression but a long-standing problem. > > > > It hits just occasionally by an app like pulseauiod which loves > > > > tight races. > > > > > > I guess it depends on how you define a regression. From my POV it worked > > > in all three cases on .32, its failing in .33-rc and in one case is oppsing. In > > > my books thats a regression. There may have been races in .32 but they > > > did not trigger lockdep and never oppsed. > > > > Is the kernel config really identical? Is only the kernel replaced? > > > > I haven't followed em28xx development, so it's possible that the bug > > came from that side, though. But, in the PCM core, there is no > > fundamental change that may trigger this bug during 2.6.33 > > development. > > > > > In any case, the real question is how do we fix the problem? > > > > As I mentioned, replace the mutex in em28xx code. > > I mean, something like below (totally untested). > > > Takashi > > --- > diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c > index bd78338..c2632c4 100644 > --- a/drivers/media/video/em28xx/em28xx-audio.c > +++ b/drivers/media/video/em28xx/em28xx-audio.c > @@ -301,9 +301,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) > /* Sets volume, mute, etc */ > > dev->mute = 0; > - mutex_lock(&dev->lock); > + mutex_lock(&dev->adev.mutex); > ret = em28xx_audio_analog_set(dev); > - mutex_unlock(&dev->lock); > + mutex_unlock(&dev->adev.mutex); > if (ret < 0) > goto err; > > @@ -315,9 +315,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) > dprintk("changing alternate number to 7\n"); > } > > - mutex_lock(&dev->lock); > + mutex_lock(&dev->adev.mutex); > dev->adev.users++; > - mutex_unlock(&dev->lock); > + mutex_unlock(&dev->adev.mutex); > > snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS); > dev->adev.capture_pcm_substream = substream; > @@ -336,7 +336,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) > dprintk("closing device\n"); > > dev->mute = 1; > - mutex_lock(&dev->lock); > + mutex_lock(&dev->adev.mutex); > dev->adev.users--; > em28xx_audio_analog_set(dev); > if (substream->runtime->dma_area) { > @@ -344,7 +344,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) > vfree(substream->runtime->dma_area); > substream->runtime->dma_area = NULL; > } > - mutex_unlock(&dev->lock); > + mutex_unlock(&dev->adev.mutex); > > return 0; > } > @@ -479,6 +479,7 @@ static int em28xx_audio_init(struct em28xx *dev) > return err; > > spin_lock_init(&adev->slock); > + mutex_init(&adev->mutex); > err = snd_pcm_new(card, "Em28xx Audio", 0, 0, 1, &pcm); > if (err < 0) { > snd_card_free(card); > diff --git a/drivers/media/video/em28xx/em28xx.h b/drivers/media/video/em28xx/em28xx.h > index 80d9b4f..bb1d754 100644 > --- a/drivers/media/video/em28xx/em28xx.h > +++ b/drivers/media/video/em28xx/em28xx.h > @@ -461,6 +461,7 @@ struct em28xx_audio { > int users; > enum em28xx_stream_state capture_stream; > spinlock_t slock; > + struct mutex mutex; > }; > > struct em28xx; > -- Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails. Here is the new traceback. Feb 16 07:55:23 grover kernel: [ 110.920632] Feb 16 07:55:23 grover kernel: [ 110.920634] ======================================================= Feb 16 07:55:23 grover kernel: [ 110.921571] [ INFO: possible circular locking dependency detected ] Feb 16 07:55:23 grover kernel: [ 110.921571] 2.6.33-rc8-crc #109 Feb 16 07:55:23 grover kernel: [ 110.921571] ------------------------------------------------------- Feb 16 07:55:23 grover kernel: [ 110.921571] pulseaudio/2713 is trying to acquire lock: Feb 16 07:55:23 grover kernel: [ 110.921571] (sysfs_mutex){+.+.+.}, at: [<ffffffff8118b900>] sysfs_get_dirent+0x20/0xa0 Feb 16 07:55:23 grover kernel: [ 110.921571] Feb 16 07:55:23 grover kernel: [ 110.921571] but task is already holding lock: Feb 16 07:55:23 grover kernel: [ 110.921571] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa0103cd2>] snd_pcm_open+0x182/0x450 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 110.921571] Feb 16 07:55:23 grover kernel: [ 110.921571] which lock already depends on the new lock. Feb 16 07:55:23 grover kernel: [ 110.921571] Feb 16 07:55:23 grover kernel: [ 110.921571] Feb 16 07:55:23 grover kernel: [ 110.921571] the existing dependency chain (in reverse order) is: Feb 16 07:55:23 grover kernel: [ 110.921571] Feb 16 07:55:23 grover kernel: [ 110.921571] -> #2 (&pcm->open_mutex){+.+.+.}: Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffffa00ffd32>] snd_pcm_release+0x42/0xb0 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff8112115d>] __fput+0x15d/0x290 Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff811212ad>] fput+0x1d/0x30 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810fe001>] remove_vma+0x51/0x80 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b Feb 16 07:55:23 grover kernel: [ 111.114188] Feb 16 07:55:23 grover kernel: [ 111.114188] -> #1 (&mm->mmap_sem){++++++}: Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8113102b>] filldir+0x7b/0xe0 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8113144d>] sys_getdents+0xad/0x110 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b Feb 16 07:55:23 grover kernel: [ 111.114188] Feb 16 07:55:23 grover kernel: [ 111.114188] -> #0 (sysfs_mutex){+.+.+.}: Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8118b900>] sysfs_get_dirent+0x20/0xa0 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8118d280>] sysfs_remove_group+0x30/0x140 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81399e09>] dpm_sysfs_remove+0x19/0x20 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8139206c>] device_del+0x4c/0x1a0 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813921d6>] device_unregister+0x16/0x30 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813ef533>] usb_remove_ep_devs+0x23/0x40 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813e6d4a>] remove_intf_ep_devs+0x4a/0x70 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813e84d7>] usb_set_interface+0x167/0x2a0 Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffffa027c8cd>] snd_em28xx_capture_open+0x11d/0x190 [em28xx_alsa] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00ffdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffffa027c8cd>] snd_em28xx_capture_open+0x11d/0x190 [em28xx_alsa] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00ffdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103ce9>] snd_pcm_open+0x199/0x450 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103fd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00a0778>] snd_open+0x198/0x4e0 [snd] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111ea70>] sys_open+0x20/0x30 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b Feb 16 07:55:23 grover kernel: [ 111.397291] Feb 16 07:55:23 grover kernel: [ 111.397291] other info that might help us debug this: Feb 16 07:55:23 grover kernel: [ 111.397291] Feb 16 07:55:23 grover kernel: [ 111.397291] 1 lock held by pulseaudio/2713: Feb 16 07:55:23 grover kernel: [ 111.397291] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa0103cd2>] snd_pcm_open+0x182/0x450 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.397291] Feb 16 07:55:23 grover kernel: [ 111.397291] stack backtrace: Feb 16 07:55:23 grover kernel: [ 111.397291] Pid: 2713, comm: pulseaudio Not tainted 2.6.33-rc8-crc #109 Feb 16 07:55:23 grover kernel: [ 111.397291] Call Trace: Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] ? sysfs_get_dirent+0x20/0xa0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] ? sysfs_get_dirent+0x20/0xa0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] ? sysfs_get_dirent+0x20/0xa0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff810819ce>] ? mark_held_locks+0x6e/0xa0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bbc50>] ? _raw_spin_unlock_irq+0x30/0x80 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] sysfs_get_dirent+0x20/0xa0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118d280>] sysfs_remove_group+0x30/0x140 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81399e09>] dpm_sysfs_remove+0x19/0x20 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8139206c>] device_del+0x4c/0x1a0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813921d6>] device_unregister+0x16/0x30 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813ef533>] usb_remove_ep_devs+0x23/0x40 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813e6d4a>] remove_intf_ep_devs+0x4a/0x70 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813e84d7>] usb_set_interface+0x167/0x2a0 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa027c8cd>] snd_em28xx_capture_open+0x11d/0x190 [em28xx_alsa] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00ffdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103ce9>] snd_pcm_open+0x199/0x450 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103fd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00a0778>] snd_open+0x198/0x4e0 [snd] Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111ea70>] sys_open+0x20/0x30 Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b Hope this helps, Ed ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-16 13:19 ` Ed Tomlinson @ 2010-02-16 13:37 ` Takashi Iwai 2010-02-17 13:16 ` Ed Tomlinson 0 siblings, 1 reply; 13+ messages in thread From: Takashi Iwai @ 2010-02-16 13:37 UTC (permalink / raw) To: Ed Tomlinson; +Cc: Rafael J. Wysocki, alsa-devel, linux-kernel At Tue, 16 Feb 2010 08:19:21 -0500, Ed Tomlinson wrote: > > On Monday 15 February 2010 18:21:17 Takashi Iwai wrote: > > At Mon, 15 Feb 2010 23:35:26 +0100, > > I wrote: > > > > > > At Mon, 15 Feb 2010 17:24:54 -0500, > > > Ed Tomlinson wrote: > > > > > > > > On Monday 15 February 2010 14:21:55 Takashi Iwai wrote: > > > > > At Mon, 15 Feb 2010 20:20:22 +0100, > > > > > I wrote: > > > > > > > > > > > > At Sat, 13 Feb 2010 12:17:10 -0500, > > > > > > Ed Tomlinson wrote: > > > > > > > > > > > > > > Hi, > > > > > > > > > > > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid. > > > > > > > > > > > > > > --- > > > > > > > pcm.pulse { > > > > > > > type pulse > > > > > > > } > > > > > > > > > > > > > > ctl.pulse { > > > > > > > type pulse > > > > > > > } > > > > > > > > > > > > > > pcm.!default { > > > > > > > type pulse > > > > > > > } > > > > > > > ctl.!default { > > > > > > > type pulse > > > > > > > --- > > > > > > > > > > > > > > Try #1 > > > > > > > Starting as root if I do: > > > > > > > su - <id> > > > > > > > aplay sound.wav > > > > > > > <traceback inlined below> > > > > > > > aplay sound.wav > > > > > > > (silence) > > > > > > > killall pulseaudio > > > > > > > aplay sound.wav > > > > > > > (works as expected now going thru pulseaudio) > > > > > > > > > > > > > > Try #2 > > > > > > > Starting as root if I do: > > > > > > > aplay sound.wav > > > > > > > (works as expected using alsa alone) > > > > > > > su - <id> > > > > > > > aplay sound.wav > > > > > > > <another lockdep traceback> > > > > > > > aplay sound.wav > > > > > > > (works as expected now going thru pulseaudio) > > > > > > > > > > > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence. > > > > > > > > > > > > > > Ideas? > > > > > > > Ed Tomlinson > > > > > > > > > > > > > > aplay -l > > > > > > > **** List of PLAYBACK Hardware Devices **** > > > > > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog] > > > > > > > Subdevices: 0/1 > > > > > > > Subdevice #0: subdevice #0 > > > > > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital] > > > > > > > Subdevices: 1/1 > > > > > > > Subdevice #0: subdevice #0 > > > > > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI] > > > > > > > Subdevices: 1/1 > > > > > > > Subdevice #0: subdevice #0 > > > > > > > > > > > > > > "ALC1200 Analog" is what has speakers connected > > > > > > > > > > > > > > The em28xx in the traceback is an input source from a usb hdtv dongle. > > > > > > > > > > > > > > pavucontrol setup has been verified. > > > > > > > > > > > > > > [ 91.070620] > > > > > > > [ 91.070621] ======================================================= > > > > > > > [ 91.071378] [ INFO: possible circular locking dependency detected ] > > > > > > > [ 91.071378] 2.6.33-rc8-crc #106 > > > > > > > [ 91.071378] ------------------------------------------------------- > > > > > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock: > > > > > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > > [ 91.071378] > > > > > > > [ 91.071378] but task is already holding lock: > > > > > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > > > > [ 91.071378] > > > > > > > [ 91.071378] which lock already depends on the new lock. > > > > > > > [ 91.071378] > > > > > > > [ 91.071378] > > > > > > > [ 91.071378] the existing dependency chain (in reverse order) is: > > > > > > > [ 91.071378] > > > > > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}: > > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm] > > > > > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290 > > > > > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30 > > > > > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80 > > > > > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390 > > > > > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80 > > > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > > [ 91.071378] > > > > > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}: > > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0 > > > > > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0 > > > > > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0 > > > > > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0 > > > > > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110 > > > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > > [ 91.071378] > > > > > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}: > > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550 > > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30 > > > > > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0 > > > > > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70 > > > > > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0 > > > > > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60 > > > > > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70 > > > > > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0 > > > > > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30 > > > > > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250 > > > > > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0 > > > > > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx] > > > > > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx] > > > > > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0 > > > > > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0 > > > > > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0 > > > > > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0 > > > > > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20 > > > > > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280 > > > > > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140 > > > > > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0 > > > > > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023 > > > > > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0 > > > > > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250 > > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > > [ 91.514885] > > > > > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}: > > > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > > [ 91.514885] > > > > > > > [ 91.514885] other info that might help us debug this: > > > > > > > [ 91.514885] > > > > > > > [ 91.514885] 1 lock held by pulseaudio/2717: > > > > > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm] > > > > > > > [ 91.514885] > > > > > > > [ 91.514885] stack backtrace: > > > > > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106 > > > > > > > [ 91.514885] Call Trace: > > > > > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0 > > > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550 > > > > > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150 > > > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140 > > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610 > > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm] > > > > > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130 > > > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50 > > > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa] > > > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm] > > > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm] > > > > > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10 > > > > > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20 > > > > > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10 > > > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm] > > > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd] > > > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320 > > > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400 > > > > > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320 > > > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70 > > > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00 > > > > > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60 > > > > > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70 > > > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180 > > > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30 > > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b > > > > > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. > > > > > > > > > > > > It looks rather a bug of em28xx driver. Changing dev->lock with an > > > > > > individual one that is only for audio instance should fix the > > > > > > problem. > > > > > > > > > > And, I believe this is no regression but a long-standing problem. > > > > > It hits just occasionally by an app like pulseauiod which loves > > > > > tight races. > > > > > > > > I guess it depends on how you define a regression. From my POV it worked > > > > in all three cases on .32, its failing in .33-rc and in one case is oppsing. In > > > > my books thats a regression. There may have been races in .32 but they > > > > did not trigger lockdep and never oppsed. > > > > > > Is the kernel config really identical? Is only the kernel replaced? > > > > > > I haven't followed em28xx development, so it's possible that the bug > > > came from that side, though. But, in the PCM core, there is no > > > fundamental change that may trigger this bug during 2.6.33 > > > development. > > > > > > > In any case, the real question is how do we fix the problem? > > > > > > As I mentioned, replace the mutex in em28xx code. > > > > I mean, something like below (totally untested). > > > > > > Takashi > > > > --- > > diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c > > index bd78338..c2632c4 100644 > > --- a/drivers/media/video/em28xx/em28xx-audio.c > > +++ b/drivers/media/video/em28xx/em28xx-audio.c > > @@ -301,9 +301,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) > > /* Sets volume, mute, etc */ > > > > dev->mute = 0; > > - mutex_lock(&dev->lock); > > + mutex_lock(&dev->adev.mutex); > > ret = em28xx_audio_analog_set(dev); > > - mutex_unlock(&dev->lock); > > + mutex_unlock(&dev->adev.mutex); > > if (ret < 0) > > goto err; > > > > @@ -315,9 +315,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) > > dprintk("changing alternate number to 7\n"); > > } > > > > - mutex_lock(&dev->lock); > > + mutex_lock(&dev->adev.mutex); > > dev->adev.users++; > > - mutex_unlock(&dev->lock); > > + mutex_unlock(&dev->adev.mutex); > > > > snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS); > > dev->adev.capture_pcm_substream = substream; > > @@ -336,7 +336,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) > > dprintk("closing device\n"); > > > > dev->mute = 1; > > - mutex_lock(&dev->lock); > > + mutex_lock(&dev->adev.mutex); > > dev->adev.users--; > > em28xx_audio_analog_set(dev); > > if (substream->runtime->dma_area) { > > @@ -344,7 +344,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) > > vfree(substream->runtime->dma_area); > > substream->runtime->dma_area = NULL; > > } > > - mutex_unlock(&dev->lock); > > + mutex_unlock(&dev->adev.mutex); > > > > return 0; > > } > > @@ -479,6 +479,7 @@ static int em28xx_audio_init(struct em28xx *dev) > > return err; > > > > spin_lock_init(&adev->slock); > > + mutex_init(&adev->mutex); > > err = snd_pcm_new(card, "Em28xx Audio", 0, 0, 1, &pcm); > > if (err < 0) { > > snd_card_free(card); > > diff --git a/drivers/media/video/em28xx/em28xx.h b/drivers/media/video/em28xx/em28xx.h > > index 80d9b4f..bb1d754 100644 > > --- a/drivers/media/video/em28xx/em28xx.h > > +++ b/drivers/media/video/em28xx/em28xx.h > > @@ -461,6 +461,7 @@ struct em28xx_audio { > > int users; > > enum em28xx_stream_state capture_stream; > > spinlock_t slock; > > + struct mutex mutex; > > }; > > > > struct em28xx; > > -- > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails. > Here is the new traceback. Hmm, fixing this isn't so trivial. The same problem occurs on other subsystems like NFS over years. And it's still there, AFAIK. The mmap mutex appears suddenly in the strange code path at close. The patch below might fix, but I'm not 100% sure whether this has no side effect. Anyway, I doubt very much it being a regression. There is no change in ALSA core side, and also in V4L em28xx code. Maybe the lockdep wasn't triggered by some reason. And, this lockdep warning is almost harmless... thanks, Takashi --- diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c index bd78338..1759e1f 100644 --- a/drivers/media/video/em28xx/em28xx-audio.c +++ b/drivers/media/video/em28xx/em28xx-audio.c @@ -301,23 +301,12 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) /* Sets volume, mute, etc */ dev->mute = 0; - mutex_lock(&dev->lock); ret = em28xx_audio_analog_set(dev); - mutex_unlock(&dev->lock); if (ret < 0) goto err; runtime->hw = snd_em28xx_hw_capture; - if (dev->alt == 0 && dev->adev.users == 0) { - int errCode; - dev->alt = 7; - errCode = usb_set_interface(dev->udev, 0, 7); - dprintk("changing alternate number to 7\n"); - } - - mutex_lock(&dev->lock); dev->adev.users++; - mutex_unlock(&dev->lock); snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS); dev->adev.capture_pcm_substream = substream; @@ -336,7 +325,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) dprintk("closing device\n"); dev->mute = 1; - mutex_lock(&dev->lock); dev->adev.users--; em28xx_audio_analog_set(dev); if (substream->runtime->dma_area) { @@ -344,7 +332,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) vfree(substream->runtime->dma_area); substream->runtime->dma_area = NULL; } - mutex_unlock(&dev->lock); return 0; } @@ -366,6 +353,14 @@ static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream, /* TODO: set up em28xx audio chip to deliver the correct audio format, current default is 48000hz multiplexed => 96000hz mono which shouldn't matter since analogue TV only supports mono */ + + if (dev->alt == 0 && dev->adev.users == 1) { + int errCode; + dev->alt = 7; + errCode = usb_set_interface(dev->udev, 0, 7); + dprintk("changing alternate number to 7\n"); + } + return 0; } ^ permalink raw reply related [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-16 13:37 ` Takashi Iwai @ 2010-02-17 13:16 ` Ed Tomlinson 2010-02-17 14:29 ` Takashi Iwai 0 siblings, 1 reply; 13+ messages in thread From: Ed Tomlinson @ 2010-02-17 13:16 UTC (permalink / raw) To: Takashi Iwai; +Cc: Rafael J. Wysocki, linux-kernel, alsa-devel On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote: > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails. > > Here is the new traceback. > > Hmm, fixing this isn't so trivial. The same problem occurs on other > subsystems like NFS over years. And it's still there, AFAIK. > The mmap mutex appears suddenly in the strange code path at close. > > The patch below might fix, but I'm not 100% sure whether this has no > side effect. > > Anyway, I doubt very much it being a regression. There is no change > in ALSA core side, and also in V4L em28xx code. Maybe the lockdep > wasn't triggered by some reason. And, this lockdep warning is almost > harmless... Takashi, The second patch eliminating the lock causes oppes every time (one follows just in case its helpful). Suggest that the first patch might suffice to get rid of the opps. The only worry I have is _once_ after getting the lockdep traceback starting X stalled the box (no opps, no sysRQ, no log on the serial console). Ideas? --- [ 66.200497] BUG: unable to handle kernel NULL pointer dereference at (null) [ 66.201377] IP: [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0 [ 66.201377] PGD 16d25a067 PUD 16d25b067 PMD 0 [ 66.201377] Oops: 0000 [#1] PREEMPT SMP [ 66.201377] last sysfs file: /sys/devices/pci0000:00/0000:00:14.2/sound/card0/uevent [ 66.252431] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. [ 66.201377] CPU 3 [ 66.201377] Pid: 2816, comm: console-kit-dae Not tainted 2.6.33-rc8-crc #110 M3A78-T/System Product Name [ 66.201377] RIP: 0010:[<ffffffff8104dfe6>] [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0 [ 66.201377] RSP: 0018:ffff88016d149e88 EFLAGS: 00010293 [ 66.201377] RAX: ffff88016b644318 RBX: fffffffffffffcf8 RCX: ffff88016d133e00 [ 66.201377] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff81a7fa88 [ 66.201377] RBP: ffff88016d149ee8 R08: ffffffff821478d0 R09: 0000000000000000 [ 66.201377] R10: 0000000000000052 R11: 0000000000000246 R12: ffff88016d149f08 [ 66.365887] R13: ffff88016b644020 R14: ffff88016c108000 R15: ffff88016c108000 [ 66.365887] FS: 00007fc780a0f700(0000) GS:ffff880028380000(0000) knlGS:0000000000000000 [ 66.365887] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 66.365887] CR2: 0000000000000000 CR3: 000000016a044000 CR4: 00000000000006e0 [ 66.365887] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 66.365887] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 66.365887] Process console-kit-dae (pid: 2816, threadinfo ffff88016d148000, task ffff88016c108000) [ 66.365887] Stack: [ 66.365887] ffff88016c108000 ffff88016c108000 ffff88016d149f30 ffff88016b644318 [ 66.365887] <0> ffff88016d149ee8 0000000000000000 ffffffff81069880 00007fff01e7223c [ 66.365887] <0> ffff88016d133e80 0000000000000000 000000000061ea60 00007fff01e7228c [ 66.365887] Call Trace: [ 66.365887] [<ffffffff81069880>] ? find_get_pid+0x0/0x80 [ 66.365887] [<ffffffff8104e169>] sys_wait4+0x89/0xf0 [ 66.365887] [<ffffffff8104b650>] ? child_wait_callback+0x0/0x80 [ 66.365887] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b [ 66.365887] Code: eb 29 0f 1f 00 48 89 da be 01 00 00 00 4c 89 e7 e8 f0 f1 ff ff 85 c0 0f 85 d0 00 00 00 48 8b 9b 08 03 00 00 48 81 eb 08 03 00 00 <48> 8b 83 08 03 00 00 0f 18 08 48 8d 83 08 03 00 00 48 39 45 b8 [ 66.365887] RIP [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0 [ 66.365887] RSP <ffff88016d149e88> [ 66.365887] CR2: 0000000000000000 [ 66.610733] ---[ end trace 7b7cfa53172184c4 ]--- [ 66.620906] note: console-kit-dae[2816] exited with preempt_count 1 ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-17 13:16 ` Ed Tomlinson @ 2010-02-17 14:29 ` Takashi Iwai 2010-02-18 12:25 ` Ed Tomlinson 0 siblings, 1 reply; 13+ messages in thread From: Takashi Iwai @ 2010-02-17 14:29 UTC (permalink / raw) To: Ed Tomlinson; +Cc: Rafael J. Wysocki, alsa-devel, linux-kernel At Wed, 17 Feb 2010 08:16:32 -0500, Ed Tomlinson wrote: > > On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote: > > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails. > > > Here is the new traceback. > > > > Hmm, fixing this isn't so trivial. The same problem occurs on other > > subsystems like NFS over years. And it's still there, AFAIK. > > The mmap mutex appears suddenly in the strange code path at close. > > > > The patch below might fix, but I'm not 100% sure whether this has no > > side effect. > > > > Anyway, I doubt very much it being a regression. There is no change > > in ALSA core side, and also in V4L em28xx code. Maybe the lockdep > > wasn't triggered by some reason. And, this lockdep warning is almost > > harmless... > > Takashi, > > The second patch eliminating the lock causes oppes every time (one follows just in case > its helpful). Are you sure? The patch should causes a compile error, so you must have patched manually in a wrong place ;) Try the patch below (again untested, though). thanks, Takashi --- diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c index bd78338..c51e623 100644 --- a/drivers/media/video/em28xx/em28xx-audio.c +++ b/drivers/media/video/em28xx/em28xx-audio.c @@ -301,23 +301,12 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) /* Sets volume, mute, etc */ dev->mute = 0; - mutex_lock(&dev->lock); ret = em28xx_audio_analog_set(dev); - mutex_unlock(&dev->lock); if (ret < 0) goto err; runtime->hw = snd_em28xx_hw_capture; - if (dev->alt == 0 && dev->adev.users == 0) { - int errCode; - dev->alt = 7; - errCode = usb_set_interface(dev->udev, 0, 7); - dprintk("changing alternate number to 7\n"); - } - - mutex_lock(&dev->lock); dev->adev.users++; - mutex_unlock(&dev->lock); snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS); dev->adev.capture_pcm_substream = substream; @@ -336,7 +325,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) dprintk("closing device\n"); dev->mute = 1; - mutex_lock(&dev->lock); dev->adev.users--; em28xx_audio_analog_set(dev); if (substream->runtime->dma_area) { @@ -344,7 +332,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) vfree(substream->runtime->dma_area); substream->runtime->dma_area = NULL; } - mutex_unlock(&dev->lock); return 0; } @@ -352,6 +339,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream, struct snd_pcm_hw_params *hw_params) { + struct em28xx *dev = snd_pcm_substream_chip(substream); unsigned int channels, rate, format; int ret; @@ -366,6 +354,14 @@ static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream, /* TODO: set up em28xx audio chip to deliver the correct audio format, current default is 48000hz multiplexed => 96000hz mono which shouldn't matter since analogue TV only supports mono */ + + if (dev->alt == 0 && dev->adev.users == 1) { + int errCode; + dev->alt = 7; + errCode = usb_set_interface(dev->udev, 0, 7); + dprintk("changing alternate number to 7\n"); + } + return 0; } ^ permalink raw reply related [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-17 14:29 ` Takashi Iwai @ 2010-02-18 12:25 ` Ed Tomlinson 2010-02-18 13:21 ` Takashi Iwai 0 siblings, 1 reply; 13+ messages in thread From: Ed Tomlinson @ 2010-02-18 12:25 UTC (permalink / raw) To: Takashi Iwai; +Cc: Rafael J. Wysocki, linux-kernel, alsa-devel On Wednesday 17 February 2010 09:29:37 Takashi Iwai wrote: > At Wed, 17 Feb 2010 08:16:32 -0500, > Ed Tomlinson wrote: > > > > On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote: > > > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails. > > > > Here is the new traceback. > > > > > > Hmm, fixing this isn't so trivial. The same problem occurs on other > > > subsystems like NFS over years. And it's still there, AFAIK. > > > The mmap mutex appears suddenly in the strange code path at close. > > > > > > The patch below might fix, but I'm not 100% sure whether this has no > > > side effect. > > > > > > Anyway, I doubt very much it being a regression. There is no change > > > in ALSA core side, and also in V4L em28xx code. Maybe the lockdep > > > wasn't triggered by some reason. And, this lockdep warning is almost > > > harmless... > > > > Takashi, > > > > The second patch eliminating the lock causes oppes every time (one follows just in case > > its helpful). > > Are you sure? The patch should causes a compile error, so you must have > patched manually in a wrong place ;) Yes I am sure. I fixed the compile error the same way it is fixed below. Ed > Try the patch below (again untested, though). > > > thanks, > > Takashi > > --- > diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c > index bd78338..c51e623 100644 > --- a/drivers/media/video/em28xx/em28xx-audio.c > +++ b/drivers/media/video/em28xx/em28xx-audio.c > @@ -301,23 +301,12 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream) > /* Sets volume, mute, etc */ > > dev->mute = 0; > - mutex_lock(&dev->lock); > ret = em28xx_audio_analog_set(dev); > - mutex_unlock(&dev->lock); > if (ret < 0) > goto err; > > runtime->hw = snd_em28xx_hw_capture; > - if (dev->alt == 0 && dev->adev.users == 0) { > - int errCode; > - dev->alt = 7; > - errCode = usb_set_interface(dev->udev, 0, 7); > - dprintk("changing alternate number to 7\n"); > - } > - > - mutex_lock(&dev->lock); > dev->adev.users++; > - mutex_unlock(&dev->lock); > > snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS); > dev->adev.capture_pcm_substream = substream; > @@ -336,7 +325,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) > dprintk("closing device\n"); > > dev->mute = 1; > - mutex_lock(&dev->lock); > dev->adev.users--; > em28xx_audio_analog_set(dev); > if (substream->runtime->dma_area) { > @@ -344,7 +332,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) > vfree(substream->runtime->dma_area); > substream->runtime->dma_area = NULL; > } > - mutex_unlock(&dev->lock); > > return 0; > } > @@ -352,6 +339,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream) > static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream, > struct snd_pcm_hw_params *hw_params) > { > + struct em28xx *dev = snd_pcm_substream_chip(substream); > unsigned int channels, rate, format; > int ret; > > @@ -366,6 +354,14 @@ static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream, > /* TODO: set up em28xx audio chip to deliver the correct audio format, > current default is 48000hz multiplexed => 96000hz mono > which shouldn't matter since analogue TV only supports mono */ > + > + if (dev->alt == 0 && dev->adev.users == 1) { > + int errCode; > + dev->alt = 7; > + errCode = usb_set_interface(dev->udev, 0, 7); > + dprintk("changing alternate number to 7\n"); > + } > + > return 0; > } > > > ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default 2010-02-18 12:25 ` Ed Tomlinson @ 2010-02-18 13:21 ` Takashi Iwai 0 siblings, 0 replies; 13+ messages in thread From: Takashi Iwai @ 2010-02-18 13:21 UTC (permalink / raw) To: Ed Tomlinson; +Cc: Rafael J. Wysocki, alsa-devel, linux-kernel At Thu, 18 Feb 2010 07:25:38 -0500, Ed Tomlinson wrote: > > On Wednesday 17 February 2010 09:29:37 Takashi Iwai wrote: > > At Wed, 17 Feb 2010 08:16:32 -0500, > > Ed Tomlinson wrote: > > > > > > On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote: > > > > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails. > > > > > Here is the new traceback. > > > > > > > > Hmm, fixing this isn't so trivial. The same problem occurs on other > > > > subsystems like NFS over years. And it's still there, AFAIK. > > > > The mmap mutex appears suddenly in the strange code path at close. > > > > > > > > The patch below might fix, but I'm not 100% sure whether this has no > > > > side effect. > > > > > > > > Anyway, I doubt very much it being a regression. There is no change > > > > in ALSA core side, and also in V4L em28xx code. Maybe the lockdep > > > > wasn't triggered by some reason. And, this lockdep warning is almost > > > > harmless... > > > > > > Takashi, > > > > > > The second patch eliminating the lock causes oppes every time (one follows just in case > > > its helpful). > > > > Are you sure? The patch should causes a compile error, so you must have > > patched manually in a wrong place ;) > > Yes I am sure. I fixed the compile error the same way it is fixed below. But the Oops looks pretty irrelevant from the code path. Takashi ^ permalink raw reply [flat|nested] 13+ messages in thread
end of thread, other threads:[~2010-02-18 13:21 UTC | newest]
Thread overview: 13+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <alpine.LFD.2.00.1002121142100.3922@localhost.localdomain>
2010-02-13 17:17 ` [LOCKDEP] 33-rc8 Running aplay with pulse as the default Ed Tomlinson
2010-02-13 19:18 ` Ed Tomlinson
2010-02-15 19:20 ` Takashi Iwai
2010-02-15 19:21 ` Takashi Iwai
2010-02-15 22:24 ` Ed Tomlinson
2010-02-15 22:35 ` Takashi Iwai
2010-02-15 23:21 ` Takashi Iwai
2010-02-16 13:19 ` Ed Tomlinson
2010-02-16 13:37 ` Takashi Iwai
2010-02-17 13:16 ` Ed Tomlinson
2010-02-17 14:29 ` Takashi Iwai
2010-02-18 12:25 ` Ed Tomlinson
2010-02-18 13:21 ` Takashi Iwai
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).