Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Relevant Pages