* 2.6.32 regression, hard lock @ 2009-12-06 14:14 Richard Zidlicky 2009-12-07 22:30 ` Andrew Morton 0 siblings, 1 reply; 17+ messages in thread From: Richard Zidlicky @ 2009-12-06 14:14 UTC (permalink / raw) To: linux-kernel [-- Attachment #1: Type: text/plain, Size: 391 bytes --] 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 [-- Attachment #2: .config.bz2 --] [-- Type: application/x-bzip2, Size: 25807 bytes --] [-- Attachment #3: messages.bz2 --] [-- Type: application/x-bzip2, Size: 11625 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-06 14:14 2.6.32 regression, hard lock Richard Zidlicky @ 2009-12-07 22:30 ` Andrew Morton 2009-12-08 0:23 ` Richard Zidlicky 2009-12-08 0:42 ` Andy Isaacson 0 siblings, 2 replies; 17+ messages in thread From: Andrew Morton @ 2009-12-07 22:30 UTC (permalink / raw) To: Richard Zidlicky; +Cc: linux-kernel, netdev On Sun, 6 Dec 2009 15:14:19 +0100 Richard Zidlicky <rz@linux-m68k.org> 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. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-07 22:30 ` Andrew Morton @ 2009-12-08 0:23 ` Richard Zidlicky 2009-12-08 0:48 ` Andrew Morton 2009-12-08 0:42 ` Andy Isaacson 1 sibling, 1 reply; 17+ messages in thread From: Richard Zidlicky @ 2009-12-08 0:23 UTC (permalink / raw) To: Andrew Morton; +Cc: linux-kernel, netdev > > 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-08 0:23 ` Richard Zidlicky @ 2009-12-08 0:48 ` Andrew Morton 2009-12-08 9:59 ` Richard Zidlicky ` (2 more replies) 0 siblings, 3 replies; 17+ messages in thread From: Andrew Morton @ 2009-12-08 0:48 UTC (permalink / raw) To: Richard Zidlicky; +Cc: linux-kernel, netdev, Takashi Iwai On Tue, 8 Dec 2009 01:23:53 +0100 Richard Zidlicky <rz@linux-m68k.org> 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 ;) ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-08 0:48 ` Andrew Morton @ 2009-12-08 9:59 ` Richard Zidlicky 2009-12-08 11:15 ` Takashi Iwai 2009-12-08 21:27 ` 2.6.32 regression, hard lock Richard Zidlicky 2 siblings, 0 replies; 17+ messages in thread From: Richard Zidlicky @ 2009-12-08 9:59 UTC (permalink / raw) To: Andrew Morton; +Cc: linux-kernel, netdev, Takashi Iwai > > 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-08 0:48 ` Andrew Morton 2009-12-08 9:59 ` Richard Zidlicky @ 2009-12-08 11:15 ` Takashi Iwai 2009-12-08 20:25 ` Richard Zidlicky 2010-04-13 20:30 ` usb-sound circular locking again? Richard Zidlicky 2009-12-08 21:27 ` 2.6.32 regression, hard lock Richard Zidlicky 2 siblings, 2 replies; 17+ messages in thread From: Takashi Iwai @ 2009-12-08 11:15 UTC (permalink / raw) To: Andrew Morton; +Cc: Richard Zidlicky, linux-kernel, netdev At Mon, 7 Dec 2009 16:48:26 -0800, Andrew Morton wrote: > > On Tue, 8 Dec 2009 01:23:53 +0100 > Richard Zidlicky <rz@linux-m68k.org> 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-08 11:15 ` Takashi Iwai @ 2009-12-08 20:25 ` Richard Zidlicky 2010-04-13 20:30 ` usb-sound circular locking again? Richard Zidlicky 1 sibling, 0 replies; 17+ messages in thread From: Richard Zidlicky @ 2009-12-08 20:25 UTC (permalink / raw) To: Takashi Iwai; +Cc: Andrew Morton, linux-kernel, netdev 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* usb-sound circular locking again? 2009-12-08 11:15 ` Takashi Iwai 2009-12-08 20:25 ` Richard Zidlicky @ 2010-04-13 20:30 ` Richard Zidlicky 2010-04-14 6:15 ` Takashi Iwai 1 sibling, 1 reply; 17+ messages in thread From: Richard Zidlicky @ 2010-04-13 20:30 UTC (permalink / raw) To: Takashi Iwai; +Cc: Andrew Morton, linux-kernel, netdev 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: usb-sound circular locking again? 2010-04-13 20:30 ` usb-sound circular locking again? Richard Zidlicky @ 2010-04-14 6:15 ` Takashi Iwai 2010-04-14 8:26 ` Richard Zidlicky 0 siblings, 1 reply; 17+ messages in thread From: Takashi Iwai @ 2010-04-14 6:15 UTC (permalink / raw) To: Richard Zidlicky; +Cc: Andrew Morton, linux-kernel, netdev 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 > ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: usb-sound circular locking again? 2010-04-14 6:15 ` Takashi Iwai @ 2010-04-14 8:26 ` Richard Zidlicky 0 siblings, 0 replies; 17+ messages in thread From: Richard Zidlicky @ 2010-04-14 8:26 UTC (permalink / raw) To: Takashi Iwai; +Cc: Andrew Morton, linux-kernel, netdev 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-08 0:48 ` Andrew Morton 2009-12-08 9:59 ` Richard Zidlicky 2009-12-08 11:15 ` Takashi Iwai @ 2009-12-08 21:27 ` Richard Zidlicky 2 siblings, 0 replies; 17+ messages in thread From: Richard Zidlicky @ 2009-12-08 21:27 UTC (permalink / raw) To: Andrew Morton; +Cc: linux-kernel, netdev [-- Attachment #1: Type: text/plain, Size: 185 bytes --] 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 [-- Attachment #2: spinlock-2.6.31.bz2 --] [-- Type: application/x-bzip2, Size: 25199 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-07 22:30 ` Andrew Morton 2009-12-08 0:23 ` Richard Zidlicky @ 2009-12-08 0:42 ` Andy Isaacson 2009-12-08 3:16 ` Robert Hancock 1 sibling, 1 reply; 17+ messages in thread From: Andy Isaacson @ 2009-12-08 0:42 UTC (permalink / raw) To: Andrew Morton; +Cc: Richard Zidlicky, linux-kernel, netdev 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: 2.6.32 regression, hard lock 2009-12-08 0:42 ` Andy Isaacson @ 2009-12-08 3:16 ` Robert Hancock 2009-12-08 8:29 ` [PATCH 1/2] factor duplicated code out of __show_regs into show_regs_common Andy Isaacson 2009-12-08 8:30 ` [PATCH 2/2] print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs Andy Isaacson 0 siblings, 2 replies; 17+ messages in thread From: Robert Hancock @ 2009-12-08 3:16 UTC (permalink / raw) To: Andy Isaacson; +Cc: Andrew Morton, Richard Zidlicky, linux-kernel, netdev 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. ^ permalink raw reply [flat|nested] 17+ messages in thread
* [PATCH 1/2] factor duplicated code out of __show_regs into show_regs_common 2009-12-08 3:16 ` Robert Hancock @ 2009-12-08 8:29 ` Andy Isaacson 2009-12-09 9:56 ` [tip:x86/urgent] x86: Factor duplicated code out of __show_regs() into show_regs_common() tip-bot for Andy Isaacson 2009-12-08 8:30 ` [PATCH 2/2] print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs Andy Isaacson 1 sibling, 1 reply; 17+ messages in thread From: Andy Isaacson @ 2009-12-08 8:29 UTC (permalink / raw) To: linux-kernel; +Cc: Robert Hancock, Andrew Morton, Richard Zidlicky, netdev 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 <adi@hexapodia.org> --- 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 ^ permalink raw reply related [flat|nested] 17+ messages in thread
* [tip:x86/urgent] x86: Factor duplicated code out of __show_regs() into show_regs_common() 2009-12-08 8:29 ` [PATCH 1/2] factor duplicated code out of __show_regs into show_regs_common Andy Isaacson @ 2009-12-09 9:56 ` tip-bot for Andy Isaacson 0 siblings, 0 replies; 17+ messages in thread From: tip-bot for Andy Isaacson @ 2009-12-09 9:56 UTC (permalink / raw) To: linux-tip-commits Cc: linux-kernel, hpa, mingo, hancockrwd, arjan, rz, akpm, tglx, mingo, adi Commit-ID: 814e2c84a722c45650a9b8f52285d7ba6874f63b Gitweb: http://git.kernel.org/tip/814e2c84a722c45650a9b8f52285d7ba6874f63b Author: Andy Isaacson <adi@hexapodia.org> AuthorDate: Tue, 8 Dec 2009 00:29:42 -0800 Committer: Ingo Molnar <mingo@elte.hu> 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 <adi@hexapodia.org> Cc: Arjan van de Ven <arjan@linux.intel.com> Cc: Robert Hancock <hancockrwd@gmail.com> Cc: Richard Zidlicky <rz@linux-m68k.org> Cc: Andrew Morton <akpm@linux-foundation.org> LKML-Reference: <20091208082942.GA27174@hexapodia.org> [ v2: resolved conflict ] Signed-off-by: Ingo Molnar <mingo@elte.hu> --- 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, ^ permalink raw reply related [flat|nested] 17+ messages in thread
* [PATCH 2/2] print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs 2009-12-08 3:16 ` Robert Hancock 2009-12-08 8:29 ` [PATCH 1/2] factor duplicated code out of __show_regs into show_regs_common Andy Isaacson @ 2009-12-08 8:30 ` Andy Isaacson 2009-12-09 9:56 ` [tip:x86/urgent] x86: Print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs() tip-bot for Andy Isaacson 1 sibling, 1 reply; 17+ messages in thread From: Andy Isaacson @ 2009-12-08 8:30 UTC (permalink / raw) To: linux-kernel; +Cc: Robert Hancock, Andrew Morton, Richard Zidlicky, netdev 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 <adi@hexapodia.org> Cc: Robert Hancock <hancockrwd@gmail.com> LKML-Reference: <4B1DC4F0.9050708@gmail.com> --- 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 ^ permalink raw reply related [flat|nested] 17+ messages in thread
* [tip:x86/urgent] x86: Print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs() 2009-12-08 8:30 ` [PATCH 2/2] print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs Andy Isaacson @ 2009-12-09 9:56 ` tip-bot for Andy Isaacson 0 siblings, 0 replies; 17+ messages in thread From: tip-bot for Andy Isaacson @ 2009-12-09 9:56 UTC (permalink / raw) To: linux-tip-commits Cc: linux-kernel, hpa, mingo, hancockrwd, arjan, rz, akpm, tglx, mingo, adi Commit-ID: a1884b8e558ef6395f6033f9e1b69b332dd040e0 Gitweb: http://git.kernel.org/tip/a1884b8e558ef6395f6033f9e1b69b332dd040e0 Author: Andy Isaacson <adi@hexapodia.org> AuthorDate: Tue, 8 Dec 2009 00:30:21 -0800 Committer: Ingo Molnar <mingo@elte.hu> 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 <adi@hexapodia.org> Cc: Arjan van de Ven <arjan@linux.intel.com> Cc: Robert Hancock <hancockrwd@gmail.com> Cc: Richard Zidlicky <rz@linux-m68k.org> Cc: Andrew Morton <akpm@linux-foundation.org> LKML-Reference: <20091208083021.GB27174@hexapodia.org> Signed-off-by: Ingo Molnar <mingo@elte.hu> --- 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) ^ permalink raw reply related [flat|nested] 17+ messages in thread
end of thread, other threads:[~2010-04-14 8:24 UTC | newest] Thread overview: 17+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2009-12-06 14:14 2.6.32 regression, hard lock Richard Zidlicky 2009-12-07 22:30 ` Andrew Morton 2009-12-08 0:23 ` Richard Zidlicky 2009-12-08 0:48 ` Andrew Morton 2009-12-08 9:59 ` Richard Zidlicky 2009-12-08 11:15 ` Takashi Iwai 2009-12-08 20:25 ` Richard Zidlicky 2010-04-13 20:30 ` usb-sound circular locking again? Richard Zidlicky 2010-04-14 6:15 ` Takashi Iwai 2010-04-14 8:26 ` Richard Zidlicky 2009-12-08 21:27 ` 2.6.32 regression, hard lock Richard Zidlicky 2009-12-08 0:42 ` Andy Isaacson 2009-12-08 3:16 ` Robert Hancock 2009-12-08 8:29 ` [PATCH 1/2] factor duplicated code out of __show_regs into show_regs_common Andy Isaacson 2009-12-09 9:56 ` [tip:x86/urgent] x86: Factor duplicated code out of __show_regs() into show_regs_common() tip-bot for Andy Isaacson 2009-12-08 8:30 ` [PATCH 2/2] print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs Andy Isaacson 2009-12-09 9:56 ` [tip:x86/urgent] x86: Print DMI_BOARD_NAME as well as DMI_PRODUCT_NAME from __show_regs() tip-bot for Andy Isaacson
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox