Hello,
first visible symptom is that ppp over UMTS connection "stops working", connection
did not die. Trying to restart the connection fails and the related processes hang.
After that one after another everything stops working, "telinit 6" does not do its
job and SysRQ sync-umount-reboot is logged in messages but has no visible effect.
Attaching messages and .config.
Regards
Richard
On Sun, 6 Dec 2009 15:14:19 +0100
Richard Zidlicky <[email protected]> wrote:
> Hello,
>
> first visible symptom is that ppp over UMTS connection "stops working", connection
> did not die. Trying to restart the connection fails and the related processes hang.
>
> After that one after another everything stops working, "telinit 6" does not do its
> job and SysRQ sync-umount-reboot is logged in messages but has no visible effect.
>
> Attaching messages and .config.
>
I uploaded your dmesg output to
http://userweb.kernel.org/~akpm/stuff/messages.txt
I'm looking at those traces and am not able to develop a theory to
explain it :(
There's some libata implication at timestamp 13203.385345 but that
looks like it's just a fluke.
So I'm stumped, sorry. Maybe someone else can think of a way to attack
this.
btw, why does your kernel say "To Be Filled By O.E.M." in the traces?
The kernel.org kernel doesn't do that. Is that kernel patched at all?
Thanks.
> > first visible symptom is that ppp over UMTS connection "stops working", connection
> > did not die. Trying to restart the connection fails and the related processes hang.
> >
> > After that one after another everything stops working, "telinit 6" does not do its
> > job and SysRQ sync-umount-reboot is logged in messages but has no visible effect.
> >
> > Attaching messages and .config.
> >
>
> I uploaded your dmesg output to
> http://userweb.kernel.org/~akpm/stuff/messages.txt
>
> I'm looking at those traces and am not able to develop a theory to
> explain it :(
thanks for looking at it.
I did revert to 2.31.5 and to my big surprise found a similar thing happened
so it is not a regression, at least not from 2.6.31.
No idea why it did not occur anytime sooner while running earlier kernels, however
the most recently plugged in device is an USB webcam with micro which I am suspecting
to play a role in this message (posted more details about it earlier):
Dec 6 10:31:39 localhost kernel: [ 162.087836] =======================================================
Dec 6 10:31:39 localhost kernel: [ 162.087839] [ INFO: possible circular locking dependency detected ]
Dec 6 10:31:39 localhost kernel: [ 162.087842] 2.6.32v0 #1
Dec 6 10:31:39 localhost kernel: [ 162.087844] -------------------------------------------------------
Dec 6 10:31:39 localhost kernel: [ 162.087846] pulseaudio/4506 is trying to acquire lock:
Dec 6 10:31:39 localhost kernel: [ 162.087848] (sysfs_mutex){+.+.+.}, at: [<c050c99d>] sysfs_get_dirent+0x15/0x35
Dec 6 10:31:39 localhost kernel: [ 162.087857]
Dec 6 10:31:39 localhost kernel: [ 162.087858] but task is already holding lock:
Dec 6 10:31:39 localhost kernel: [ 162.087860] (&pcm->open_mutex){+.+.+.}, at: [<f80f4b2a>] snd_pcm_release+0x55/0x9e [snd_pcm]
Dec 6 10:31:39 localhost kernel: [ 162.087873]
Dec 6 10:31:39 localhost kernel: [ 162.087874] which lock already depends on the new lock.
Dec 6 10:31:39 localhost kernel: [ 162.087875]
Dec 6 10:31:39 localhost kernel: [ 162.087876]
Dec 6 10:31:39 localhost kernel: [ 162.087877] the existing dependency chain (in reverse order) is:
Dec 6 10:31:39 localhost kernel: [ 162.087879]
Dec 6 10:31:39 localhost kernel: [ 162.087880] -> #2 (&pcm->open_mutex){+.+.+.}:
Dec 6 10:31:39 localhost kernel: [ 162.087884] [<c045a703>] __lock_acquire+0xa2a/0xbb5
Dec 6 10:31:39 localhost kernel: [ 162.087890] [<c045a922>] lock_acquire+0x94/0xb1
Dec 6 10:31:39 localhost kernel: [ 162.087893] [<c07324a6>] __mutex_lock_common+0x35/0x2dc
Dec 6 10:31:39 localhost kernel: [ 162.087898] [<c07327eb>] mutex_lock_nested+0x30/0x38
Dec 6 10:31:39 localhost kernel: [ 162.087901] [<f80f4b2a>] snd_pcm_release+0x55/0x9e [snd_pcm]
Dec 6 10:31:39 localhost kernel: [ 162.087913] [<c04ca0b5>] __fput+0xf0/0x187
Dec 6 10:31:39 localhost kernel: [ 162.087918] [<c04ca165>] fput+0x19/0x1b
Dec 6 10:31:39 localhost kernel: [ 162.087921] [<c04b0d6b>] remove_vma+0x3e/0x5d
Dec 6 10:31:39 localhost kernel: [ 162.087926] [<c04b19f0>] do_munmap+0x21c/0x237
Dec 6 10:31:39 localhost kernel: [ 162.087929] [<c04b1a3b>] sys_munmap+0x30/0x3f
Dec 6 10:31:39 localhost kernel: [ 162.087932] [<c040321d>] syscall_call+0x7/0xb
Dec 6 10:31:39 localhost kernel: [ 162.087937]
Dec 6 10:31:39 localhost kernel: [ 162.087938] -> #1 (&mm->mmap_sem){++++++}:
Dec 6 10:31:39 localhost kernel: [ 162.087942] [<c045a703>] __lock_acquire+0xa2a/0xbb5
Dec 6 10:31:39 localhost kernel: [ 162.087946] [<c045a922>] lock_acquire+0x94/0xb1
Dec 6 10:31:39 localhost kernel: [ 162.087949] [<c04aba42>] might_fault+0x64/0x81
Dec 6 10:31:39 localhost kernel: [ 162.087952] [<c05b34cc>] copy_to_user+0x2c/0xfc
Dec 6 10:31:39 localhost kernel: [ 162.087957] [<c04d4879>] filldir+0x78/0xb7
Dec 6 10:31:39 localhost kernel: [ 162.087961] [<c050c88d>] sysfs_readdir+0x117/0x14b
Dec 6 10:31:39 localhost kernel: [ 162.087964] [<c04d49dd>] vfs_readdir+0x68/0x94
Dec 6 10:31:39 localhost kernel: [ 162.087968] [<c04d4b0b>] sys_getdents+0x62/0xa1
Dec 6 10:31:39 localhost kernel: [ 162.087971] [<c040321d>] syscall_call+0x7/0xb
Dec 6 10:31:39 localhost kernel: [ 162.087975]
Dec 6 10:31:39 localhost kernel: [ 162.087975] -> #0 (sysfs_mutex){+.+.+.}:
Dec 6 10:31:39 localhost kernel: [ 162.087979] [<c045a610>] __lock_acquire+0x937/0xbb5
Dec 6 10:31:39 localhost kernel: [ 162.087983] [<c045a922>] lock_acquire+0x94/0xb1
Dec 6 10:31:39 localhost kernel: [ 162.087986] [<c07324a6>] __mutex_lock_common+0x35/0x2dc
Dec 6 10:31:39 localhost kernel: [ 162.087990] [<c07327eb>] mutex_lock_nested+0x30/0x38
Dec 6 10:31:39 localhost kernel: [ 162.087993] [<c050c99d>] sysfs_get_dirent+0x15/0x35
Dec 6 10:31:39 localhost kernel: [ 162.087996] [<c050e03e>] sysfs_remove_group+0x1e/0xa3
Dec 6 10:31:39 localhost kernel: [ 162.088000] [<c062bf50>] dpm_sysfs_remove+0x10/0x12
Dec 6 10:31:39 localhost kernel: [ 162.088006] [<c0627108>] device_del+0x33/0x154
Dec 6 10:31:39 localhost kernel: [ 162.088010] [<c0627251>] device_unregister+0x28/0x4b
Dec 6 10:31:39 localhost kernel: [ 162.088014] [<c0678499>] usb_remove_ep_devs+0x15/0x1f
Dec 6 10:31:39 localhost kernel: [ 162.088018] [<c0672ba2>] remove_intf_ep_devs+0x21/0x32
Dec 6 10:31:39 localhost kernel: [ 162.088023] [<c0673b3a>] usb_set_interface+0x10c/0x19f
Dec 6 10:31:39 localhost kernel: [ 162.088027] [<f832dce6>] snd_usb_capture_close+0x1e/0x37 [snd_usb_audio]
Dec 6 10:31:39 localhost kernel: [ 162.088040] [<f80f4aac>] snd_pcm_release_substream+0x3d/0x66 [snd_pcm]
Dec 6 10:31:39 localhost kernel: [ 162.088050] [<f80f4b31>] snd_pcm_release+0x5c/0x9e [snd_pcm]
Dec 6 10:31:39 localhost kernel: [ 162.088058] [<c04ca0b5>] __fput+0xf0/0x187
Dec 6 10:31:39 localhost kernel: [ 162.088062] [<c04ca165>] fput+0x19/0x1b
Dec 6 10:31:39 localhost kernel: [ 162.088065] [<c04b0d6b>] remove_vma+0x3e/0x5d
Dec 6 10:31:39 localhost kernel: [ 162.088069] [<c04b19f0>] do_munmap+0x21c/0x237
Dec 6 10:31:39 localhost kernel: [ 162.088072] [<c04b1a3b>] sys_munmap+0x30/0x3f
Dec 6 10:31:39 localhost kernel: [ 162.088076] [<c040321d>] syscall_call+0x7/0xb
Dec 6 10:31:39 localhost kernel: [ 162.088079]
Dec 6 10:31:39 localhost kernel: [ 162.088080] other info that might help us debug this:
Dec 6 10:31:39 localhost kernel: [ 162.088080]
Dec 6 10:31:39 localhost kernel: [ 162.088083] 2 locks held by pulseaudio/4506:
Dec 6 10:31:39 localhost kernel: [ 162.088085] #0: (&mm->mmap_sem){++++++}, at: [<c04b1a2e>] sys_munmap+0x23/0x3f
Dec 6 10:31:39 localhost kernel: [ 162.088090] #1: (&pcm->open_mutex){+.+.+.}, at: [<f80f4b2a>] snd_pcm_release+0x55/0x9e [snd_pcm]
Dec 6 10:31:39 localhost kernel: [ 162.088104]
Dec 6 10:31:39 localhost kernel: [ 162.088105] stack backtrace:
Dec 6 10:31:39 localhost kernel: [ 162.088108] Pid: 4506, comm: pulseaudio Not tainted 2.6.32v0 #1
Dec 6 10:31:39 localhost kernel: [ 162.088110] Call Trace:
Dec 6 10:31:39 localhost kernel: [ 162.088113] [<c07312cc>] ? printk+0xf/0x13
Dec 6 10:31:39 localhost kernel: [ 162.088117] [<c045999b>] print_circular_bug+0x91/0x9d
Dec 6 10:31:39 localhost kernel: [ 162.088121] [<c045a610>] __lock_acquire+0x937/0xbb5
Dec 6 10:31:39 localhost kernel: [ 162.088124] [<c04584f5>] ? save_trace+0x37/0xa3
Dec 6 10:31:39 localhost kernel: [ 162.088128] [<c045a922>] lock_acquire+0x94/0xb1
Dec 6 10:31:39 localhost kernel: [ 162.088131] [<c050c99d>] ? sysfs_get_dirent+0x15/0x35
Dec 6 10:31:39 localhost kernel: [ 162.088135] [<c07324a6>] __mutex_lock_common+0x35/0x2dc
Dec 6 10:31:39 localhost kernel: [ 162.088138] [<c050c99d>] ? sysfs_get_dirent+0x15/0x35
Dec 6 10:31:39 localhost kernel: [ 162.088141] [<c0458f23>] ? mark_held_locks+0x43/0x5b
Dec 6 10:31:39 localhost kernel: [ 162.088145] [<c04591bf>] ? trace_hardirqs_on+0xb/0xd
Dec 6 10:31:39 localhost kernel: [ 162.088148] [<c07327eb>] mutex_lock_nested+0x30/0x38
Dec 6 10:31:39 localhost kernel: [ 162.088151] [<c050c99d>] ? sysfs_get_dirent+0x15/0x35
Dec 6 10:31:39 localhost kernel: [ 162.088154] [<c050c99d>] sysfs_get_dirent+0x15/0x35
Dec 6 10:31:39 localhost kernel: [ 162.088157] [<c050e03e>] sysfs_remove_group+0x1e/0xa3
Dec 6 10:31:39 localhost kernel: [ 162.088161] [<c062bf50>] dpm_sysfs_remove+0x10/0x12
Dec 6 10:31:39 localhost kernel: [ 162.088164] [<c0627108>] device_del+0x33/0x154
Dec 6 10:31:39 localhost kernel: [ 162.088168] [<c0627251>] device_unregister+0x28/0x4b
Dec 6 10:31:39 localhost kernel: [ 162.088171] [<c0678499>] usb_remove_ep_devs+0x15/0x1f
Dec 6 10:31:39 localhost kernel: [ 162.088174] [<c0672ba2>] remove_intf_ep_devs+0x21/0x32
Dec 6 10:31:39 localhost kernel: [ 162.088178] [<c0673b3a>] usb_set_interface+0x10c/0x19f
Dec 6 10:31:39 localhost kernel: [ 162.088190] [<f832dce6>] snd_usb_capture_close+0x1e/0x37 [snd_usb_audio]
Dec 6 10:31:39 localhost kernel: [ 162.088199] [<f80f4aac>] snd_pcm_release_substream+0x3d/0x66 [snd_pcm]
Dec 6 10:31:39 localhost kernel: [ 162.088208] [<f80f4b31>] snd_pcm_release+0x5c/0x9e [snd_pcm]
Dec 6 10:31:39 localhost kernel: [ 162.088211] [<c04ca0b5>] __fput+0xf0/0x187
Dec 6 10:31:39 localhost kernel: [ 162.088215] [<c04ca165>] fput+0x19/0x1b
Dec 6 10:31:39 localhost kernel: [ 162.088218] [<c04b0d6b>] remove_vma+0x3e/0x5d
Dec 6 10:31:39 localhost kernel: [ 162.088221] [<c04b19f0>] do_munmap+0x21c/0x237
Dec 6 10:31:39 localhost kernel: [ 162.088225] [<c04b1a3b>] sys_munmap+0x30/0x3f
Dec 6 10:31:39 localhost kernel: [ 162.088228] [<c040321d>] syscall_call+0x7/0xb
> There's some libata implication at timestamp 13203.385345 but that
> looks like it's just a fluke.
hm.. I am running everything on a dm-crypted device with LVM, my ata is a mix
of ancient 40/80 wire-flat-cable disks and sata.
> btw, why does your kernel say "To Be Filled By O.E.M." in the traces?
> The kernel.org kernel doesn't do that. Is that kernel patched at all?
strange, this was the first kernel in months that was not patched - even difffed
it against kernel.org to make sure.
Richard
On Mon, Dec 07, 2009 at 02:30:57PM -0800, Andrew Morton wrote:
> btw, why does your kernel say "To Be Filled By O.E.M." in the traces?
> The kernel.org kernel doesn't do that. Is that kernel patched at all?
That's traditional for DMI_PRODUCT_NAME in dodgy vendor BIOSes. I
routinely see it on Intel evaluation boards and less frequently on
Taiwanese Brand X boards.
-andy
On Tue, 8 Dec 2009 01:23:53 +0100
Richard Zidlicky <[email protected]> wrote:
>
> > > first visible symptom is that ppp over UMTS connection "stops working", connection
> > > did not die. Trying to restart the connection fails and the related processes hang.
> > >
> > > After that one after another everything stops working, "telinit 6" does not do its
> > > job and SysRQ sync-umount-reboot is logged in messages but has no visible effect.
> > >
> > > Attaching messages and .config.
> > >
> >
> > I uploaded your dmesg output to
> > http://userweb.kernel.org/~akpm/stuff/messages.txt
>
> >
> > I'm looking at those traces and am not able to develop a theory to
> > explain it :(
>
> thanks for looking at it.
>
> I did revert to 2.31.5 and to my big surprise found a similar thing happened
> so it is not a regression, at least not from 2.6.31.
This trace is different. It's a lock ranking warning and is surely
unrelated to the IRQs-off lockup which you earlier experienced.
> No idea why it did not occur anytime sooner while running earlier kernels, however
> the most recently plugged in device is an USB webcam with micro which I am suspecting
> to play a role in this message (posted more details about it earlier):
>
> Dec 6 10:31:39 localhost kernel: [ 162.087836] =======================================================
> Dec 6 10:31:39 localhost kernel: [ 162.087839] [ INFO: possible circular locking dependency detected ]
> Dec 6 10:31:39 localhost kernel: [ 162.087842] 2.6.32v0 #1
> Dec 6 10:31:39 localhost kernel: [ 162.087844] -------------------------------------------------------
> Dec 6 10:31:39 localhost kernel: [ 162.087846] pulseaudio/4506 is trying to acquire lock:
> Dec 6 10:31:39 localhost kernel: [ 162.087848] (sysfs_mutex){+.+.+.}, at: [<c050c99d>] sysfs_get_dirent+0x15/0x35
> Dec 6 10:31:39 localhost kernel: [ 162.087857]
> Dec 6 10:31:39 localhost kernel: [ 162.087858] but task is already holding lock:
> Dec 6 10:31:39 localhost kernel: [ 162.087860] (&pcm->open_mutex){+.+.+.}, at: [<f80f4b2a>] snd_pcm_release+0x55/0x9e [snd_pcm]
> Dec 6 10:31:39 localhost kernel: [ 162.087873]
> Dec 6 10:31:39 localhost kernel: [ 162.087874] which lock already depends on the new lock.
> Dec 6 10:31:39 localhost kernel: [ 162.087875]
> Dec 6 10:31:39 localhost kernel: [ 162.087876]
> Dec 6 10:31:39 localhost kernel: [ 162.087877] the existing dependency chain (in reverse order) is:
> Dec 6 10:31:39 localhost kernel: [ 162.087879]
> Dec 6 10:31:39 localhost kernel: [ 162.087880] -> #2 (&pcm->open_mutex){+.+.+.}:
> Dec 6 10:31:39 localhost kernel: [ 162.087884] [<c045a703>] __lock_acquire+0xa2a/0xbb5
>
> Dec 6 10:31:39 localhost kernel: [ 162.087890] [<c045a922>] lock_acquire+0x94/0xb1
> Dec 6 10:31:39 localhost kernel: [ 162.087893] [<c07324a6>] __mutex_lock_common+0x35/0x2dc
> Dec 6 10:31:39 localhost kernel: [ 162.087898] [<c07327eb>] mutex_lock_nested+0x30/0x38
> Dec 6 10:31:39 localhost kernel: [ 162.087901] [<f80f4b2a>] snd_pcm_release+0x55/0x9e [snd_pcm]
> Dec 6 10:31:39 localhost kernel: [ 162.087913] [<c04ca0b5>] __fput+0xf0/0x187
> Dec 6 10:31:39 localhost kernel: [ 162.087918] [<c04ca165>] fput+0x19/0x1b
> Dec 6 10:31:39 localhost kernel: [ 162.087921] [<c04b0d6b>] remove_vma+0x3e/0x5d
> Dec 6 10:31:39 localhost kernel: [ 162.087926] [<c04b19f0>] do_munmap+0x21c/0x237
> Dec 6 10:31:39 localhost kernel: [ 162.087929] [<c04b1a3b>] sys_munmap+0x30/0x3f
> Dec 6 10:31:39 localhost kernel: [ 162.087932] [<c040321d>] syscall_call+0x7/0xb
> Dec 6 10:31:39 localhost kernel: [ 162.087937]
> Dec 6 10:31:39 localhost kernel: [ 162.087938] -> #1 (&mm->mmap_sem){++++++}:
> Dec 6 10:31:39 localhost kernel: [ 162.087942] [<c045a703>] __lock_acquire+0xa2a/0xbb5
> Dec 6 10:31:39 localhost kernel: [ 162.087946] [<c045a922>] lock_acquire+0x94/0xb1
> Dec 6 10:31:39 localhost kernel: [ 162.087949] [<c04aba42>] might_fault+0x64/0x81
> Dec 6 10:31:39 localhost kernel: [ 162.087952] [<c05b34cc>] copy_to_user+0x2c/0xfc
> Dec 6 10:31:39 localhost kernel: [ 162.087957] [<c04d4879>] filldir+0x78/0xb7
> Dec 6 10:31:39 localhost kernel: [ 162.087961] [<c050c88d>] sysfs_readdir+0x117/0x14b
> Dec 6 10:31:39 localhost kernel: [ 162.087964] [<c04d49dd>] vfs_readdir+0x68/0x94
> Dec 6 10:31:39 localhost kernel: [ 162.087968] [<c04d4b0b>] sys_getdents+0x62/0xa1
> Dec 6 10:31:39 localhost kernel: [ 162.087971] [<c040321d>] syscall_call+0x7/0xb
> Dec 6 10:31:39 localhost kernel: [ 162.087975]
> Dec 6 10:31:39 localhost kernel: [ 162.087975] -> #0 (sysfs_mutex){+.+.+.}:
> Dec 6 10:31:39 localhost kernel: [ 162.087979] [<c045a610>] __lock_acquire+0x937/0xbb5
> Dec 6 10:31:39 localhost kernel: [ 162.087983] [<c045a922>] lock_acquire+0x94/0xb1
> Dec 6 10:31:39 localhost kernel: [ 162.087986] [<c07324a6>] __mutex_lock_common+0x35/0x2dc
> Dec 6 10:31:39 localhost kernel: [ 162.087990] [<c07327eb>] mutex_lock_nested+0x30/0x38
> Dec 6 10:31:39 localhost kernel: [ 162.087993] [<c050c99d>] sysfs_get_dirent+0x15/0x35
> Dec 6 10:31:39 localhost kernel: [ 162.087996] [<c050e03e>] sysfs_remove_group+0x1e/0xa3
> Dec 6 10:31:39 localhost kernel: [ 162.088000] [<c062bf50>] dpm_sysfs_remove+0x10/0x12
> Dec 6 10:31:39 localhost kernel: [ 162.088006] [<c0627108>] device_del+0x33/0x154
> Dec 6 10:31:39 localhost kernel: [ 162.088010] [<c0627251>] device_unregister+0x28/0x4b
> Dec 6 10:31:39 localhost kernel: [ 162.088014] [<c0678499>] usb_remove_ep_devs+0x15/0x1f
> Dec 6 10:31:39 localhost kernel: [ 162.088018] [<c0672ba2>] remove_intf_ep_devs+0x21/0x32
> Dec 6 10:31:39 localhost kernel: [ 162.088023] [<c0673b3a>] usb_set_interface+0x10c/0x19f
> Dec 6 10:31:39 localhost kernel: [ 162.088027] [<f832dce6>] snd_usb_capture_close+0x1e/0x37 [snd_usb_audio]
> Dec 6 10:31:39 localhost kernel: [ 162.088040] [<f80f4aac>] snd_pcm_release_substream+0x3d/0x66 [snd_pcm]
> Dec 6 10:31:39 localhost kernel: [ 162.088050] [<f80f4b31>] snd_pcm_release+0x5c/0x9e [snd_pcm]
> Dec 6 10:31:39 localhost kernel: [ 162.088058] [<c04ca0b5>] __fput+0xf0/0x187
> Dec 6 10:31:39 localhost kernel: [ 162.088062] [<c04ca165>] fput+0x19/0x1b
> Dec 6 10:31:39 localhost kernel: [ 162.088065] [<c04b0d6b>] remove_vma+0x3e/0x5d
> Dec 6 10:31:39 localhost kernel: [ 162.088069] [<c04b19f0>] do_munmap+0x21c/0x237
> Dec 6 10:31:39 localhost kernel: [ 162.088072] [<c04b1a3b>] sys_munmap+0x30/0x3f
> Dec 6 10:31:39 localhost kernel: [ 162.088076] [<c040321d>] syscall_call+0x7/0xb
> Dec 6 10:31:39 localhost kernel: [ 162.088079]
> Dec 6 10:31:39 localhost kernel: [ 162.088080] other info that might help us debug this:
> Dec 6 10:31:39 localhost kernel: [ 162.088080]
> Dec 6 10:31:39 localhost kernel: [ 162.088083] 2 locks held by pulseaudio/4506:
> Dec 6 10:31:39 localhost kernel: [ 162.088085] #0: (&mm->mmap_sem){++++++}, at: [<c04b1a2e>] sys_munmap+0x23/0x3f
> Dec 6 10:31:39 localhost kernel: [ 162.088090] #1: (&pcm->open_mutex){+.+.+.}, at: [<f80f4b2a>] snd_pcm_release+0x55/0x9e [snd_pcm]
> Dec 6 10:31:39 localhost kernel: [ 162.088104]
> Dec 6 10:31:39 localhost kernel: [ 162.088105] stack backtrace:
> Dec 6 10:31:39 localhost kernel: [ 162.088108] Pid: 4506, comm: pulseaudio Not tainted 2.6.32v0 #1
> Dec 6 10:31:39 localhost kernel: [ 162.088110] Call Trace:
> Dec 6 10:31:39 localhost kernel: [ 162.088113] [<c07312cc>] ? printk+0xf/0x13
> Dec 6 10:31:39 localhost kernel: [ 162.088117] [<c045999b>] print_circular_bug+0x91/0x9d
> Dec 6 10:31:39 localhost kernel: [ 162.088121] [<c045a610>] __lock_acquire+0x937/0xbb5
> Dec 6 10:31:39 localhost kernel: [ 162.088124] [<c04584f5>] ? save_trace+0x37/0xa3
> Dec 6 10:31:39 localhost kernel: [ 162.088128] [<c045a922>] lock_acquire+0x94/0xb1
> Dec 6 10:31:39 localhost kernel: [ 162.088131] [<c050c99d>] ? sysfs_get_dirent+0x15/0x35
> Dec 6 10:31:39 localhost kernel: [ 162.088135] [<c07324a6>] __mutex_lock_common+0x35/0x2dc
> Dec 6 10:31:39 localhost kernel: [ 162.088138] [<c050c99d>] ? sysfs_get_dirent+0x15/0x35
> Dec 6 10:31:39 localhost kernel: [ 162.088141] [<c0458f23>] ? mark_held_locks+0x43/0x5b
> Dec 6 10:31:39 localhost kernel: [ 162.088145] [<c04591bf>] ? trace_hardirqs_on+0xb/0xd
> Dec 6 10:31:39 localhost kernel: [ 162.088148] [<c07327eb>] mutex_lock_nested+0x30/0x38
> Dec 6 10:31:39 localhost kernel: [ 162.088151] [<c050c99d>] ? sysfs_get_dirent+0x15/0x35
> Dec 6 10:31:39 localhost kernel: [ 162.088154] [<c050c99d>] sysfs_get_dirent+0x15/0x35
> Dec 6 10:31:39 localhost kernel: [ 162.088157] [<c050e03e>] sysfs_remove_group+0x1e/0xa3
> Dec 6 10:31:39 localhost kernel: [ 162.088161] [<c062bf50>] dpm_sysfs_remove+0x10/0x12
> Dec 6 10:31:39 localhost kernel: [ 162.088164] [<c0627108>] device_del+0x33/0x154
> Dec 6 10:31:39 localhost kernel: [ 162.088168] [<c0627251>] device_unregister+0x28/0x4b
> Dec 6 10:31:39 localhost kernel: [ 162.088171] [<c0678499>] usb_remove_ep_devs+0x15/0x1f
> Dec 6 10:31:39 localhost kernel: [ 162.088174] [<c0672ba2>] remove_intf_ep_devs+0x21/0x32
> Dec 6 10:31:39 localhost kernel: [ 162.088178] [<c0673b3a>] usb_set_interface+0x10c/0x19f
> Dec 6 10:31:39 localhost kernel: [ 162.088190] [<f832dce6>] snd_usb_capture_close+0x1e/0x37 [snd_usb_audio]
> Dec 6 10:31:39 localhost kernel: [ 162.088199] [<f80f4aac>] snd_pcm_release_substream+0x3d/0x66 [snd_pcm]
> Dec 6 10:31:39 localhost kernel: [ 162.088208] [<f80f4b31>] snd_pcm_release+0x5c/0x9e [snd_pcm]
> Dec 6 10:31:39 localhost kernel: [ 162.088211] [<c04ca0b5>] __fput+0xf0/0x187
> Dec 6 10:31:39 localhost kernel: [ 162.088215] [<c04ca165>] fput+0x19/0x1b
> Dec 6 10:31:39 localhost kernel: [ 162.088218] [<c04b0d6b>] remove_vma+0x3e/0x5d
> Dec 6 10:31:39 localhost kernel: [ 162.088221] [<c04b19f0>] do_munmap+0x21c/0x237
> Dec 6 10:31:39 localhost kernel: [ 162.088225] [<c04b1a3b>] sys_munmap+0x30/0x3f
> Dec 6 10:31:39 localhost kernel: [ 162.088228] [<c040321d>] syscall_call+0x7/0xb
And fortunately I know who to cc on this one ;)
On 12/07/2009 06:42 PM, Andy Isaacson wrote:
> On Mon, Dec 07, 2009 at 02:30:57PM -0800, Andrew Morton wrote:
>> btw, why does your kernel say "To Be Filled By O.E.M." in the traces?
>> The kernel.org kernel doesn't do that. Is that kernel patched at all?
>
> That's traditional for DMI_PRODUCT_NAME in dodgy vendor BIOSes. I
> routinely see it on Intel evaluation boards and less frequently on
> Taiwanese Brand X boards.
It seems like the DMI board product name would be more useful than the
system product name to print out in those messages (for kerneloops.org
use, etc) as the system name is so frequently populated with such dummy
values. My Asus P7P55D has the product name set to "System Product Name"
which obviously isn't very unique or useful. Most likely only big-name
manufactured systems would have a chance of filling that in properly.
Unify x86_32 and x86_64 implementations of __show_regs header,
standardizing on the x86_64 format string in the process. Also,
32-bit will now call print_modules.
Signed-off-by: Andy Isaacson <[email protected]>
---
I cast about for a good place to stick the show_regs_common prototype;
suggestions appreciated.
Compile-tested on 32-bit and 64-bit.
arch/x86/include/asm/system.h | 1 +
arch/x86/kernel/process.c | 18 ++++++++++++++++++
arch/x86/kernel/process_32.c | 14 +-------------
arch/x86/kernel/process_64.c | 16 ++--------------
4 files changed, 22 insertions(+), 27 deletions(-)
diff --git a/arch/x86/include/asm/system.h b/arch/x86/include/asm/system.h
index 022a843..ecb544e 100644
--- a/arch/x86/include/asm/system.h
+++ b/arch/x86/include/asm/system.h
@@ -23,6 +23,7 @@ struct task_struct *__switch_to(struct task_struct *prev,
struct tss_struct;
void __switch_to_xtra(struct task_struct *prev_p, struct task_struct *next_p,
struct tss_struct *tss);
+extern void show_regs_common(void);
#ifdef CONFIG_X86_32
diff --git a/arch/x86/kernel/process.c b/arch/x86/kernel/process.c
index 744508e..a93f319 100644
--- a/arch/x86/kernel/process.c
+++ b/arch/x86/kernel/process.c
@@ -9,6 +9,8 @@
#include <linux/pm.h>
#include <linux/clockchips.h>
#include <linux/random.h>
+#include <linux/dmi.h>
+#include <linux/utsname.h>
#include <trace/events/power.h>
#include <linux/hw_breakpoint.h>
#include <asm/system.h>
@@ -89,6 +91,22 @@ void exit_thread(void)
}
}
+void show_regs_common(void)
+{
+ const char *board;
+
+ board = dmi_get_system_info(DMI_PRODUCT_NAME);
+ if (!board)
+ board = "";
+
+ printk("\n");
+ printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s\n",
+ current->pid, current->comm, print_tainted(),
+ init_utsname()->release,
+ (int)strcspn(init_utsname()->version, " "),
+ init_utsname()->version, board);
+}
+
void flush_thread(void)
{
struct task_struct *tsk = current;
diff --git a/arch/x86/kernel/process_32.c b/arch/x86/kernel/process_32.c
index 075580b..120b887 100644
--- a/arch/x86/kernel/process_32.c
+++ b/arch/x86/kernel/process_32.c
@@ -23,7 +23,6 @@
#include <linux/vmalloc.h>
#include <linux/user.h>
#include <linux/interrupt.h>
-#include <linux/utsname.h>
#include <linux/delay.h>
#include <linux/reboot.h>
#include <linux/init.h>
@@ -35,7 +34,6 @@
#include <linux/tick.h>
#include <linux/percpu.h>
#include <linux/prctl.h>
-#include <linux/dmi.h>
#include <linux/ftrace.h>
#include <linux/uaccess.h>
#include <linux/io.h>
@@ -128,7 +126,6 @@ void __show_regs(struct pt_regs *regs, int all)
unsigned long d0, d1, d2, d3, d6, d7;
unsigned long sp;
unsigned short ss, gs;
- const char *board;
if (user_mode_vm(regs)) {
sp = regs->sp;
@@ -140,16 +137,7 @@ void __show_regs(struct pt_regs *regs, int all)
savesegment(gs, gs);
}
- printk("\n");
-
- board = dmi_get_system_info(DMI_PRODUCT_NAME);
- if (!board)
- board = "";
- printk("Pid: %d, comm: %s %s (%s %.*s) %s\n",
- task_pid_nr(current), current->comm,
- print_tainted(), init_utsname()->release,
- (int)strcspn(init_utsname()->version, " "),
- init_utsname()->version, board);
+ show_regs_common();
printk("EIP: %04x:[<%08lx>] EFLAGS: %08lx CPU: %d\n",
(u16)regs->cs, regs->ip, regs->flags,
diff --git a/arch/x86/kernel/process_64.c b/arch/x86/kernel/process_64.c
index a98fe88..d0570b9 100644
--- a/arch/x86/kernel/process_64.c
+++ b/arch/x86/kernel/process_64.c
@@ -26,7 +26,6 @@
#include <linux/slab.h>
#include <linux/user.h>
#include <linux/interrupt.h>
-#include <linux/utsname.h>
#include <linux/delay.h>
#include <linux/module.h>
#include <linux/ptrace.h>
@@ -38,7 +37,6 @@
#include <linux/uaccess.h>
#include <linux/io.h>
#include <linux/ftrace.h>
-#include <linux/dmi.h>
#include <asm/pgtable.h>
#include <asm/system.h>
@@ -163,18 +161,8 @@ void __show_regs(struct pt_regs *regs, int all)
unsigned long d0, d1, d2, d3, d6, d7;
unsigned int fsindex, gsindex;
unsigned int ds, cs, es;
- const char *board;
-
- printk("\n");
- print_modules();
- board = dmi_get_system_info(DMI_PRODUCT_NAME);
- if (!board)
- board = "";
- printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s\n",
- current->pid, current->comm, print_tainted(),
- init_utsname()->release,
- (int)strcspn(init_utsname()->version, " "),
- init_utsname()->version, board);
+
+ show_regs_common();
printk(KERN_INFO "RIP: %04lx:[<%016lx>] ", regs->cs & 0xffff, regs->ip);
printk_address(regs->ip, 1);
printk(KERN_INFO "RSP: %04lx:%016lx EFLAGS: %08lx\n", regs->ss,
--
1.6.5.3
Robert Hancock observes that DMI_BOARD_NAME is often more useful
than DMI_PRODUCT_NAME, especially on standalone motherboards.
So, print both.
Signed-off-by: Andy Isaacson <[email protected]>
Cc: Robert Hancock <[email protected]>
LKML-Reference: <[email protected]>
---
arch/x86/kernel/process.c | 11 +++++++----
1 files changed, 7 insertions(+), 4 deletions(-)
diff --git a/arch/x86/kernel/process.c b/arch/x86/kernel/process.c
index a93f319..520d9d1 100644
--- a/arch/x86/kernel/process.c
+++ b/arch/x86/kernel/process.c
@@ -93,18 +93,21 @@ void exit_thread(void)
void show_regs_common(void)
{
- const char *board;
+ const char *board, *product;
- board = dmi_get_system_info(DMI_PRODUCT_NAME);
+ board = dmi_get_system_info(DMI_BOARD_NAME);
if (!board)
board = "";
+ product = dmi_get_system_info(DMI_PRODUCT_NAME);
+ if (!product)
+ product = "";
printk("\n");
- printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s\n",
+ printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s/%s\n",
current->pid, current->comm, print_tainted(),
init_utsname()->release,
(int)strcspn(init_utsname()->version, " "),
- init_utsname()->version, board);
+ init_utsname()->version, board, product);
}
void flush_thread(void)
--
1.6.5.3
> > I did revert to 2.31.5 and to my big surprise found a similar thing happened
> > so it is not a regression, at least not from 2.6.31.
I will compare the messages in the 2 kernel versions. In 2.6.31 the symptoms were slightly
different, the ppp connection worked long after first processes became unresponsive.
"gnome-do" was apparently the first process to hang on the spinlock and tcptrack was
running again.
Richard
At Mon, 7 Dec 2009 16:48:26 -0800,
Andrew Morton wrote:
>
> On Tue, 8 Dec 2009 01:23:53 +0100
> Richard Zidlicky <[email protected]> wrote:
>
> >
> > > > first visible symptom is that ppp over UMTS connection "stops working", connection
> > > > did not die. Trying to restart the connection fails and the related processes hang.
> > > >
> > > > After that one after another everything stops working, "telinit 6" does not do its
> > > > job and SysRQ sync-umount-reboot is logged in messages but has no visible effect.
> > > >
> > > > Attaching messages and .config.
> > > >
> > >
> > > I uploaded your dmesg output to
> > > http://userweb.kernel.org/~akpm/stuff/messages.txt
> >
> > >
> > > I'm looking at those traces and am not able to develop a theory to
> > > explain it :(
> >
> > thanks for looking at it.
> >
> > I did revert to 2.31.5 and to my big surprise found a similar thing happened
> > so it is not a regression, at least not from 2.6.31.
>
> This trace is different. It's a lock ranking warning and is surely
> unrelated to the IRQs-off lockup which you earlier experienced.
>
(snip)
> And fortunately I know who to cc on this one ;)
Oh, it's a pity to me that you know that ;)
It's a known issue for several kernel releases. (There are a few
subsystems that have the similar lockdep pattern involving with
mm->mmap_sem, too.)
But, as Andrew pointed, this should be irrelevant with the IRQ
lockup. At most it could be a dead-locking of PA and other
sound-related processes, but I've never heard the real issue.
thanks,
Takashi
On Tue, Dec 08, 2009 at 12:15:45PM +0100, Takashi Iwai wrote:
>
> But, as Andrew pointed, this should be irrelevant with the IRQ
> lockup. At most it could be a dead-locking of PA and other
> sound-related processes, but I've never heard the real issue.
indeed, had to kill and restart PA on a few occassions but no other
ill effects so far.
Richard
Hi,
here the messages from a similar 2.6.31 problem, this time I have included all startup
and PM related messages.
Let me know if you have any hints how I could debug this.
Richard
Commit-ID: 814e2c84a722c45650a9b8f52285d7ba6874f63b
Gitweb: http://git.kernel.org/tip/814e2c84a722c45650a9b8f52285d7ba6874f63b
Author: Andy Isaacson <[email protected]>
AuthorDate: Tue, 8 Dec 2009 00:29:42 -0800
Committer: Ingo Molnar <[email protected]>
CommitDate: Wed, 9 Dec 2009 10:17:58 +0100
x86: Factor duplicated code out of __show_regs() into show_regs_common()
Unify x86_32 and x86_64 implementations of __show_regs() header,
standardizing on the x86_64 format string in the process. Also,
32-bit will now call print_modules.
Signed-off-by: Andy Isaacson <[email protected]>
Cc: Arjan van de Ven <[email protected]>
Cc: Robert Hancock <[email protected]>
Cc: Richard Zidlicky <[email protected]>
Cc: Andrew Morton <[email protected]>
LKML-Reference: <[email protected]>
[ v2: resolved conflict ]
Signed-off-by: Ingo Molnar <[email protected]>
---
arch/x86/include/asm/system.h | 1 +
arch/x86/kernel/process.c | 18 ++++++++++++++++++
arch/x86/kernel/process_32.c | 14 +-------------
arch/x86/kernel/process_64.c | 16 ++--------------
4 files changed, 22 insertions(+), 27 deletions(-)
diff --git a/arch/x86/include/asm/system.h b/arch/x86/include/asm/system.h
index 022a843..ecb544e 100644
--- a/arch/x86/include/asm/system.h
+++ b/arch/x86/include/asm/system.h
@@ -23,6 +23,7 @@ struct task_struct *__switch_to(struct task_struct *prev,
struct tss_struct;
void __switch_to_xtra(struct task_struct *prev_p, struct task_struct *next_p,
struct tss_struct *tss);
+extern void show_regs_common(void);
#ifdef CONFIG_X86_32
diff --git a/arch/x86/kernel/process.c b/arch/x86/kernel/process.c
index 5e2ba63..90cf125 100644
--- a/arch/x86/kernel/process.c
+++ b/arch/x86/kernel/process.c
@@ -10,6 +10,8 @@
#include <linux/clockchips.h>
#include <linux/random.h>
#include <linux/user-return-notifier.h>
+#include <linux/dmi.h>
+#include <linux/utsname.h>
#include <trace/events/power.h>
#include <linux/hw_breakpoint.h>
#include <asm/system.h>
@@ -90,6 +92,22 @@ void exit_thread(void)
}
}
+void show_regs_common(void)
+{
+ const char *board;
+
+ board = dmi_get_system_info(DMI_PRODUCT_NAME);
+ if (!board)
+ board = "";
+
+ printk("\n");
+ printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s\n",
+ current->pid, current->comm, print_tainted(),
+ init_utsname()->release,
+ (int)strcspn(init_utsname()->version, " "),
+ init_utsname()->version, board);
+}
+
void flush_thread(void)
{
struct task_struct *tsk = current;
diff --git a/arch/x86/kernel/process_32.c b/arch/x86/kernel/process_32.c
index 075580b..120b887 100644
--- a/arch/x86/kernel/process_32.c
+++ b/arch/x86/kernel/process_32.c
@@ -23,7 +23,6 @@
#include <linux/vmalloc.h>
#include <linux/user.h>
#include <linux/interrupt.h>
-#include <linux/utsname.h>
#include <linux/delay.h>
#include <linux/reboot.h>
#include <linux/init.h>
@@ -35,7 +34,6 @@
#include <linux/tick.h>
#include <linux/percpu.h>
#include <linux/prctl.h>
-#include <linux/dmi.h>
#include <linux/ftrace.h>
#include <linux/uaccess.h>
#include <linux/io.h>
@@ -128,7 +126,6 @@ void __show_regs(struct pt_regs *regs, int all)
unsigned long d0, d1, d2, d3, d6, d7;
unsigned long sp;
unsigned short ss, gs;
- const char *board;
if (user_mode_vm(regs)) {
sp = regs->sp;
@@ -140,16 +137,7 @@ void __show_regs(struct pt_regs *regs, int all)
savesegment(gs, gs);
}
- printk("\n");
-
- board = dmi_get_system_info(DMI_PRODUCT_NAME);
- if (!board)
- board = "";
- printk("Pid: %d, comm: %s %s (%s %.*s) %s\n",
- task_pid_nr(current), current->comm,
- print_tainted(), init_utsname()->release,
- (int)strcspn(init_utsname()->version, " "),
- init_utsname()->version, board);
+ show_regs_common();
printk("EIP: %04x:[<%08lx>] EFLAGS: %08lx CPU: %d\n",
(u16)regs->cs, regs->ip, regs->flags,
diff --git a/arch/x86/kernel/process_64.c b/arch/x86/kernel/process_64.c
index c95c8f4..e5ab0cd 100644
--- a/arch/x86/kernel/process_64.c
+++ b/arch/x86/kernel/process_64.c
@@ -26,7 +26,6 @@
#include <linux/slab.h>
#include <linux/user.h>
#include <linux/interrupt.h>
-#include <linux/utsname.h>
#include <linux/delay.h>
#include <linux/module.h>
#include <linux/ptrace.h>
@@ -38,7 +37,6 @@
#include <linux/uaccess.h>
#include <linux/io.h>
#include <linux/ftrace.h>
-#include <linux/dmi.h>
#include <asm/pgtable.h>
#include <asm/system.h>
@@ -163,18 +161,8 @@ void __show_regs(struct pt_regs *regs, int all)
unsigned long d0, d1, d2, d3, d6, d7;
unsigned int fsindex, gsindex;
unsigned int ds, cs, es;
- const char *board;
-
- printk("\n");
- print_modules();
- board = dmi_get_system_info(DMI_PRODUCT_NAME);
- if (!board)
- board = "";
- printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s\n",
- current->pid, current->comm, print_tainted(),
- init_utsname()->release,
- (int)strcspn(init_utsname()->version, " "),
- init_utsname()->version, board);
+
+ show_regs_common();
printk(KERN_INFO "RIP: %04lx:[<%016lx>] ", regs->cs & 0xffff, regs->ip);
printk_address(regs->ip, 1);
printk(KERN_INFO "RSP: %04lx:%016lx EFLAGS: %08lx\n", regs->ss,
Commit-ID: a1884b8e558ef6395f6033f9e1b69b332dd040e0
Gitweb: http://git.kernel.org/tip/a1884b8e558ef6395f6033f9e1b69b332dd040e0
Author: Andy Isaacson <[email protected]>
AuthorDate: Tue, 8 Dec 2009 00:30:21 -0800
Committer: Ingo Molnar <[email protected]>
CommitDate: Wed, 9 Dec 2009 10:17:59 +0100
x86: Print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs()
Robert Hancock observes that DMI_BOARD_NAME is often more useful
than DMI_PRODUCT_NAME, especially on standalone motherboards.
So, print both.
Signed-off-by: Andy Isaacson <[email protected]>
Cc: Arjan van de Ven <[email protected]>
Cc: Robert Hancock <[email protected]>
Cc: Richard Zidlicky <[email protected]>
Cc: Andrew Morton <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
arch/x86/kernel/process.c | 11 +++++++----
1 files changed, 7 insertions(+), 4 deletions(-)
diff --git a/arch/x86/kernel/process.c b/arch/x86/kernel/process.c
index 90cf125..7a7bd4e 100644
--- a/arch/x86/kernel/process.c
+++ b/arch/x86/kernel/process.c
@@ -94,18 +94,21 @@ void exit_thread(void)
void show_regs_common(void)
{
- const char *board;
+ const char *board, *product;
- board = dmi_get_system_info(DMI_PRODUCT_NAME);
+ board = dmi_get_system_info(DMI_BOARD_NAME);
if (!board)
board = "";
+ product = dmi_get_system_info(DMI_PRODUCT_NAME);
+ if (!product)
+ product = "";
printk("\n");
- printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s\n",
+ printk(KERN_INFO "Pid: %d, comm: %.20s %s %s %.*s %s/%s\n",
current->pid, current->comm, print_tainted(),
init_utsname()->release,
(int)strcspn(init_utsname()->version, " "),
- init_utsname()->version, board);
+ init_utsname()->version, board, product);
}
void flush_thread(void)
Hi,
is this the same old issue? Any way to fix it? Seeing it triggered in a sync
syscall does not make me comfortable.
Apr 13 02:01:36 localhost kernel: [ 8569.449882] PM: Syncing filesystems ...
Apr 13 02:01:36 localhost kernel: [ 8569.449998] =======================================================
Apr 13 02:01:36 localhost kernel: [ 8569.450049] [ INFO: possible circular locking dependency detected ]
Apr 13 02:01:36 localhost kernel: [ 8569.450078] 2.6.33.2v2 #4
Apr 13 02:01:36 localhost kernel: [ 8569.450101] -------------------------------------------------------
Apr 13 02:01:36 localhost kernel: [ 8569.450130] pm-hibernate/17348 is trying to acquire lock:
Apr 13 02:01:36 localhost kernel: [ 8569.450158] (mutex){+.+...}, at: [<c04e6670>] sync_filesystems+0x14/0xd6
Apr 13 02:01:36 localhost kernel: [ 8569.450252]
Apr 13 02:01:36 localhost kernel: [ 8569.450253] but task is already holding lock:
Apr 13 02:01:36 localhost kernel: [ 8569.450266] (pm_mutex){+.+.+.}, at: [<c0466658>] hibernate+0x13/0x18d
Apr 13 02:01:36 localhost kernel: [ 8569.450266]
Apr 13 02:01:36 localhost kernel: [ 8569.450266] which lock already depends on the new lock.
Apr 13 02:01:36 localhost kernel: [ 8569.450266]
Apr 13 02:01:36 localhost kernel: [ 8569.450266]
Apr 13 02:01:36 localhost kernel: [ 8569.450266] the existing dependency chain (in reverse order) is:
Apr 13 02:01:36 localhost kernel: [ 8569.450266]
Apr 13 02:01:36 localhost kernel: [ 8569.450266] -> #6 (pm_mutex){+.+.+.}:
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c07370e0>] mutex_lock_nested+0x30/0x38
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0466658>] hibernate+0x13/0x18d
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c046551c>] state_store+0x56/0xa8
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c05acb19>] kobj_attr_store+0x1a/0x22
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c050f306>] sysfs_write_file+0xb9/0xe4
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c04cc821>] vfs_write+0x84/0xdf
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c04cc915>] sys_write+0x3b/0x60
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0738295>] syscall_call+0x7/0xb
Apr 13 02:01:36 localhost kernel: [ 8569.450266]
Apr 13 02:01:36 localhost kernel: [ 8569.450266] -> #5 (s_active){++++.+}:
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c05102f8>] sysfs_addrm_finish+0x89/0xde
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c050eaf7>] sysfs_hash_and_remove+0x3d/0x4f
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0511100>] sysfs_remove_group+0x74/0xa3
Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c062e16c>] dpm_sysfs_remove+0x10/0x12
Apr 13 09:39:32 localhost kernel: [ 8569.450266] [<c062933f>] device_del+0x33/0x154
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0629488>] device_unregister+0x28/0x4b
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c067b7c5>] usb_remove_ep_devs+0x15/0x1f
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0675c92>] remove_intf_ep_devs+0x21/0x32
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0676d53>] usb_set_interface+0x18c/0x22c
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<f8302c46>] snd_usb_capture_close+0x26/0x3f [snd_usb_audio]
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<f80fbb08>] snd_pcm_release_substream+0x3d/0x66 [snd_pcm]
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<f80fbb8d>] snd_pcm_release+0x5c/0x9e [snd_pcm]
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04cd12a>] __fput+0xf0/0x187
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04cd1da>] fput+0x19/0x1b
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04b2e9f>] remove_vma+0x3e/0x5d
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04b3b2a>] do_munmap+0x23c/0x259
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04b3b77>] sys_munmap+0x30/0x3f
Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0738295>] syscall_call+0x7/0xb
Apr 13 09:39:34 localhost kernel: [ 8569.450266]
Apr 13 09:39:34 localhost kernel: [ 8569.450266] -> #4 (&pcm->open_mutex){+.+.+.}:
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c07370e0>] mutex_lock_nested+0x30/0x38
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<f80fbb86>] snd_pcm_release+0x55/0x9e [snd_pcm]
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04cd12a>] __fput+0xf0/0x187
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04cd1da>] fput+0x19/0x1b
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04b2e9f>] remove_vma+0x3e/0x5d
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04b3b2a>] do_munmap+0x23c/0x259
Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04b3b77>] sys_munmap+0x30/0x3f
Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c0738295>] syscall_call+0x7/0xb
Apr 13 09:39:34 localhost kernel: [ 8569.455127]
Apr 13 09:39:34 localhost kernel: [ 8569.455127] -> #3 (&mm->mmap_sem){++++++}:
Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c04add1a>] might_fault+0x64/0x81
Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c05b3828>] copy_to_user+0x2c/0xfc
Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c04d784b>] filldir64+0x97/0xcd
Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c04e299c>] dcache_readdir+0x5a/0x1af
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04d7a5d>] vfs_readdir+0x68/0x94
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04d7aec>] sys_getdents64+0x63/0xa0
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c0738295>] syscall_call+0x7/0xb
Apr 13 09:39:34 localhost kernel: [ 8569.456129]
Apr 13 09:39:34 localhost kernel: [ 8569.456129] -> #2 (&sb->s_type->i_mutex_key#3){+.+.+.}:
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c07370e0>] mutex_lock_nested+0x30/0x38
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c051164f>] devpts_get_sb+0x1c0/0x29f
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04ce0db>] vfs_kern_mount+0x86/0x11f
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04ce1b8>] do_kern_mount+0x32/0xbe
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04e02c2>] do_mount+0x671/0x6d0
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04e0382>] sys_mount+0x61/0x8f
Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c0738295>] syscall_call+0x7/0xb
Apr 13 09:39:34 localhost kernel: [ 8569.456129]
Apr 13 09:39:34 localhost kernel: [ 8569.456129] -> #1 (&type->s_umount_key#19){++++..}:
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c0737310>] down_read+0x31/0x45
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e66cf>] sync_filesystems+0x73/0xd6
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e676e>] sys_sync+0x11/0x2d
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c0738295>] syscall_call+0x7/0xb
Apr 13 09:39:34 localhost kernel: [ 8569.458127]
Apr 13 09:39:34 localhost kernel: [ 8569.458127] -> #0 (mutex){+.+...}:
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b517>] __lock_acquire+0x93a/0xbb7
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c07370e0>] mutex_lock_nested+0x30/0x38
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e6670>] sync_filesystems+0x14/0xd6
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e676e>] sys_sync+0x11/0x2d
Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04666c2>] hibernate+0x7d/0x18d
Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c046551c>] state_store+0x56/0xa8
Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c05acb19>] kobj_attr_store+0x1a/0x22
Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c050f306>] sysfs_write_file+0xb9/0xe4
Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c04cc821>] vfs_write+0x84/0xdf
Apr 13 09:39:34 localhost kernel: [ 8569.460128] [<c04cc915>] sys_write+0x3b/0x60
Apr 13 09:39:34 localhost kernel: [ 8569.460128] [<c0738295>] syscall_call+0x7/0xb
Apr 13 09:39:34 localhost kernel: [ 8569.460128]
Apr 13 09:39:34 localhost kernel: [ 8569.460128] other info that might help us debug this:
Apr 13 09:39:34 localhost kernel: [ 8569.460128]
Apr 13 09:39:34 localhost kernel: [ 8569.460128] 4 locks held by pm-hibernate/17348:
Apr 13 09:39:34 localhost kernel: [ 8569.460128] #0: (&buffer->mutex){+.+.+.}, at: [<c050f272>] sysfs_write_file+0x25/0xe4
Apr 13 09:39:34 localhost kernel: [ 8569.460128] #1: (s_active){++++.+}, at: [<c0510544>] sysfs_get_active_two+0x16/0x36
Apr 13 09:39:34 localhost kernel: [ 8569.461127] #2: (s_active){++++.+}, at: [<c051054f>] sysfs_get_active_two+0x21/0x36
Apr 13 09:39:34 localhost kernel: [ 8569.461127] #3: (pm_mutex){+.+.+.}, at: [<c0466658>] hibernate+0x13/0x18d
Apr 13 09:39:34 localhost kernel: [ 8569.461127]
Apr 13 09:39:34 localhost kernel: [ 8569.461127] stack backtrace:
Apr 13 09:39:34 localhost kernel: [ 8569.461127] Pid: 17348, comm: pm-hibernate Not tainted 2.6.33.2v2 #4
Apr 13 09:39:34 localhost kernel: [ 8569.461127] Call Trace:
Apr 13 09:39:34 localhost kernel: [ 8569.461127] [<c0735b79>] ? printk+0xf/0x16
Apr 13 09:39:34 localhost kernel: [ 8569.461127] [<c045a8a0>] print_circular_bug+0x90/0x9c
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c045b517>] __lock_acquire+0x93a/0xbb7
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c042730d>] ? update_curr+0x177/0x17f
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c0459bf5>] ? mark_lock+0x1e/0x1ea
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c045b828>] lock_acquire+0x94/0xb1
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] ? sync_filesystems+0x14/0xd6
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] ? sync_filesystems+0x14/0xd6
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e3423>] ? bdi_alloc_queue_work+0x84/0xa0
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c07370e0>] mutex_lock_nested+0x30/0x38
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] ? sync_filesystems+0x14/0xd6
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] sync_filesystems+0x14/0xd6
Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e676e>] sys_sync+0x11/0x2d
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04666c2>] hibernate+0x7d/0x18d
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04654c6>] ? state_store+0x0/0xa8
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c046551c>] state_store+0x56/0xa8
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04654c6>] ? state_store+0x0/0xa8
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c05acb19>] kobj_attr_store+0x1a/0x22
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c050f306>] sysfs_write_file+0xb9/0xe4
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c050f24d>] ? sysfs_write_file+0x0/0xe4
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04cc821>] vfs_write+0x84/0xdf
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04cc915>] sys_write+0x3b/0x60
Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c0738295>] syscall_call+0x7/0xb
Apr 13 09:39:34 localhost kernel: [ 8569.484133] done.
Apr 13 09:39:34 localhost kernel: [ 8569.484223] Freezing user space processes ... (elapsed 0.04 seconds) done.
Apr 13 09:39:34 localhost kernel: [ 8569.528142] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Apr 13 09:39:34 localhost kernel: [ 8569.539272] PM: Preallocating image memory... done (allocated 349210 pages)
Apr 13 09:39:34 localhost kernel: [ 8583.627118] PM: Allocated 1396840 kbytes in 14.08 seconds (99.20 MB/s)
Regards,
Richard
At Tue, 13 Apr 2010 22:30:39 +0200,
Richard Zidlicky wrote:
>
> Hi,
>
> is this the same old issue?
I think so. It appears relatively new since a sysfs lockdep check was
introduced.
thanks,
Takashi
> Any way to fix it? Seeing it triggered in a sync
> syscall does not make me comfortable.
>
> Apr 13 02:01:36 localhost kernel: [ 8569.449882] PM: Syncing filesystems ...
> Apr 13 02:01:36 localhost kernel: [ 8569.449998] =======================================================
> Apr 13 02:01:36 localhost kernel: [ 8569.450049] [ INFO: possible circular locking dependency detected ]
> Apr 13 02:01:36 localhost kernel: [ 8569.450078] 2.6.33.2v2 #4
> Apr 13 02:01:36 localhost kernel: [ 8569.450101] -------------------------------------------------------
> Apr 13 02:01:36 localhost kernel: [ 8569.450130] pm-hibernate/17348 is trying to acquire lock:
> Apr 13 02:01:36 localhost kernel: [ 8569.450158] (mutex){+.+...}, at: [<c04e6670>] sync_filesystems+0x14/0xd6
> Apr 13 02:01:36 localhost kernel: [ 8569.450252]
> Apr 13 02:01:36 localhost kernel: [ 8569.450253] but task is already holding lock:
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] (pm_mutex){+.+.+.}, at: [<c0466658>] hibernate+0x13/0x18d
> Apr 13 02:01:36 localhost kernel: [ 8569.450266]
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] which lock already depends on the new lock.
> Apr 13 02:01:36 localhost kernel: [ 8569.450266]
> Apr 13 02:01:36 localhost kernel: [ 8569.450266]
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] the existing dependency chain (in reverse order) is:
> Apr 13 02:01:36 localhost kernel: [ 8569.450266]
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] -> #6 (pm_mutex){+.+.+.}:
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c07370e0>] mutex_lock_nested+0x30/0x38
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0466658>] hibernate+0x13/0x18d
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c046551c>] state_store+0x56/0xa8
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c05acb19>] kobj_attr_store+0x1a/0x22
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c050f306>] sysfs_write_file+0xb9/0xe4
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c04cc821>] vfs_write+0x84/0xdf
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c04cc915>] sys_write+0x3b/0x60
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 02:01:36 localhost kernel: [ 8569.450266]
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] -> #5 (s_active){++++.+}:
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c05102f8>] sysfs_addrm_finish+0x89/0xde
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c050eaf7>] sysfs_hash_and_remove+0x3d/0x4f
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c0511100>] sysfs_remove_group+0x74/0xa3
> Apr 13 02:01:36 localhost kernel: [ 8569.450266] [<c062e16c>] dpm_sysfs_remove+0x10/0x12
> Apr 13 09:39:32 localhost kernel: [ 8569.450266] [<c062933f>] device_del+0x33/0x154
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0629488>] device_unregister+0x28/0x4b
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c067b7c5>] usb_remove_ep_devs+0x15/0x1f
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0675c92>] remove_intf_ep_devs+0x21/0x32
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0676d53>] usb_set_interface+0x18c/0x22c
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<f8302c46>] snd_usb_capture_close+0x26/0x3f [snd_usb_audio]
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<f80fbb08>] snd_pcm_release_substream+0x3d/0x66 [snd_pcm]
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<f80fbb8d>] snd_pcm_release+0x5c/0x9e [snd_pcm]
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04cd12a>] __fput+0xf0/0x187
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04cd1da>] fput+0x19/0x1b
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04b2e9f>] remove_vma+0x3e/0x5d
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04b3b2a>] do_munmap+0x23c/0x259
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c04b3b77>] sys_munmap+0x30/0x3f
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 09:39:34 localhost kernel: [ 8569.450266]
> Apr 13 09:39:34 localhost kernel: [ 8569.450266] -> #4 (&pcm->open_mutex){+.+.+.}:
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c07370e0>] mutex_lock_nested+0x30/0x38
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<f80fbb86>] snd_pcm_release+0x55/0x9e [snd_pcm]
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04cd12a>] __fput+0xf0/0x187
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04cd1da>] fput+0x19/0x1b
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04b2e9f>] remove_vma+0x3e/0x5d
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04b3b2a>] do_munmap+0x23c/0x259
> Apr 13 09:39:34 localhost kernel: [ 8569.454127] [<c04b3b77>] sys_munmap+0x30/0x3f
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 09:39:34 localhost kernel: [ 8569.455127]
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] -> #3 (&mm->mmap_sem){++++++}:
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c04add1a>] might_fault+0x64/0x81
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c05b3828>] copy_to_user+0x2c/0xfc
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c04d784b>] filldir64+0x97/0xcd
> Apr 13 09:39:34 localhost kernel: [ 8569.455127] [<c04e299c>] dcache_readdir+0x5a/0x1af
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04d7a5d>] vfs_readdir+0x68/0x94
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04d7aec>] sys_getdents64+0x63/0xa0
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 09:39:34 localhost kernel: [ 8569.456129]
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] -> #2 (&sb->s_type->i_mutex_key#3){+.+.+.}:
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c07370e0>] mutex_lock_nested+0x30/0x38
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c051164f>] devpts_get_sb+0x1c0/0x29f
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04ce0db>] vfs_kern_mount+0x86/0x11f
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04ce1b8>] do_kern_mount+0x32/0xbe
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04e02c2>] do_mount+0x671/0x6d0
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c04e0382>] sys_mount+0x61/0x8f
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 09:39:34 localhost kernel: [ 8569.456129]
> Apr 13 09:39:34 localhost kernel: [ 8569.456129] -> #1 (&type->s_umount_key#19){++++..}:
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b60a>] __lock_acquire+0xa2d/0xbb7
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c0737310>] down_read+0x31/0x45
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e66cf>] sync_filesystems+0x73/0xd6
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e676e>] sys_sync+0x11/0x2d
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 09:39:34 localhost kernel: [ 8569.458127]
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] -> #0 (mutex){+.+...}:
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b517>] __lock_acquire+0x93a/0xbb7
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c07370e0>] mutex_lock_nested+0x30/0x38
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e6670>] sync_filesystems+0x14/0xd6
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04e676e>] sys_sync+0x11/0x2d
> Apr 13 09:39:34 localhost kernel: [ 8569.458127] [<c04666c2>] hibernate+0x7d/0x18d
> Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c046551c>] state_store+0x56/0xa8
> Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c05acb19>] kobj_attr_store+0x1a/0x22
> Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c050f306>] sysfs_write_file+0xb9/0xe4
> Apr 13 09:39:34 localhost kernel: [ 8569.459761] [<c04cc821>] vfs_write+0x84/0xdf
> Apr 13 09:39:34 localhost kernel: [ 8569.460128] [<c04cc915>] sys_write+0x3b/0x60
> Apr 13 09:39:34 localhost kernel: [ 8569.460128] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 09:39:34 localhost kernel: [ 8569.460128]
> Apr 13 09:39:34 localhost kernel: [ 8569.460128] other info that might help us debug this:
> Apr 13 09:39:34 localhost kernel: [ 8569.460128]
> Apr 13 09:39:34 localhost kernel: [ 8569.460128] 4 locks held by pm-hibernate/17348:
> Apr 13 09:39:34 localhost kernel: [ 8569.460128] #0: (&buffer->mutex){+.+.+.}, at: [<c050f272>] sysfs_write_file+0x25/0xe4
> Apr 13 09:39:34 localhost kernel: [ 8569.460128] #1: (s_active){++++.+}, at: [<c0510544>] sysfs_get_active_two+0x16/0x36
> Apr 13 09:39:34 localhost kernel: [ 8569.461127] #2: (s_active){++++.+}, at: [<c051054f>] sysfs_get_active_two+0x21/0x36
> Apr 13 09:39:34 localhost kernel: [ 8569.461127] #3: (pm_mutex){+.+.+.}, at: [<c0466658>] hibernate+0x13/0x18d
> Apr 13 09:39:34 localhost kernel: [ 8569.461127]
> Apr 13 09:39:34 localhost kernel: [ 8569.461127] stack backtrace:
> Apr 13 09:39:34 localhost kernel: [ 8569.461127] Pid: 17348, comm: pm-hibernate Not tainted 2.6.33.2v2 #4
> Apr 13 09:39:34 localhost kernel: [ 8569.461127] Call Trace:
> Apr 13 09:39:34 localhost kernel: [ 8569.461127] [<c0735b79>] ? printk+0xf/0x16
> Apr 13 09:39:34 localhost kernel: [ 8569.461127] [<c045a8a0>] print_circular_bug+0x90/0x9c
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c045b517>] __lock_acquire+0x93a/0xbb7
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c042730d>] ? update_curr+0x177/0x17f
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c0459bf5>] ? mark_lock+0x1e/0x1ea
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c045b828>] lock_acquire+0x94/0xb1
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] ? sync_filesystems+0x14/0xd6
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c0736d84>] __mutex_lock_common+0x35/0x2f3
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] ? sync_filesystems+0x14/0xd6
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e3423>] ? bdi_alloc_queue_work+0x84/0xa0
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c07370e0>] mutex_lock_nested+0x30/0x38
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] ? sync_filesystems+0x14/0xd6
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e6670>] sync_filesystems+0x14/0xd6
> Apr 13 09:39:34 localhost kernel: [ 8569.462128] [<c04e676e>] sys_sync+0x11/0x2d
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04666c2>] hibernate+0x7d/0x18d
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04654c6>] ? state_store+0x0/0xa8
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c046551c>] state_store+0x56/0xa8
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04654c6>] ? state_store+0x0/0xa8
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c05acb19>] kobj_attr_store+0x1a/0x22
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c050f306>] sysfs_write_file+0xb9/0xe4
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c050f24d>] ? sysfs_write_file+0x0/0xe4
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04cc821>] vfs_write+0x84/0xdf
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c04cc915>] sys_write+0x3b/0x60
> Apr 13 09:39:34 localhost kernel: [ 8569.463127] [<c0738295>] syscall_call+0x7/0xb
> Apr 13 09:39:34 localhost kernel: [ 8569.484133] done.
>
> Apr 13 09:39:34 localhost kernel: [ 8569.484223] Freezing user space processes ... (elapsed 0.04 seconds) done.
> Apr 13 09:39:34 localhost kernel: [ 8569.528142] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
> Apr 13 09:39:34 localhost kernel: [ 8569.539272] PM: Preallocating image memory... done (allocated 349210 pages)
> Apr 13 09:39:34 localhost kernel: [ 8583.627118] PM: Allocated 1396840 kbytes in 14.08 seconds (99.20 MB/s)
>
> Regards,
> Richard
>
Hi,
> > is this the same old issue?
>
> I think so. It appears relatively new since a sysfs lockdep check was
> introduced.
you are right, it was definitely my impression that this particular instance is
a new (last previously tested 2.6.32.8).
After a few more tests it appears to be 100% repeatable in pm-hibernate. Simply
doing "sync" right now does nothing.
Richard