* suspend-related lockdep warning @ 2007-11-28 10:43 Andrew Morton 2007-11-28 22:06 ` Rafael J. Wysocki 2007-12-01 8:33 ` Pavel Machek 0 siblings, 2 replies; 12+ messages in thread From: Andrew Morton @ 2007-11-28 10:43 UTC (permalink / raw) To: Rafael J. Wysocki, Ingo Molnar, Peter Zijlstra; +Cc: linux-kernel 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and if I stay awake) will say this during suspend-to-RAM on the Vaio: [ 91.876445] Syncing filesystems ... done. [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b [ 92.385620] ======================= [ 92.385719] irq event stamp: 309 [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 [ 92.392457] (elapsed 0.00 seconds) done. [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. [ 92.392882] PM: Entering mem sleep [ 92.392974] Suspending console(s) this has been happening for quite some time and might even be happening in mainline. Also, a few seconds after resume has completed we get a whimper from the hangcheck driver: [ 1.762425] usb 2-1: configuration #1 chosen from 1 choice [ 1.826548] input: Microsoft Microsoft Wireless Optical Mouse_ 1.00 as /class/input/input9 [ 1.866211] input: USB HID v1.11 Mouse [Microsoft Microsoft Wireless Optical Mouse_ 1.00] on usb-0000:00:1d.1-1 [ 5.757927] Hangcheck: hangcheck value past margin! ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-11-28 10:43 suspend-related lockdep warning Andrew Morton @ 2007-11-28 22:06 ` Rafael J. Wysocki 2007-12-01 8:33 ` Pavel Machek 1 sibling, 0 replies; 12+ messages in thread From: Rafael J. Wysocki @ 2007-11-28 22:06 UTC (permalink / raw) To: Andrew Morton; +Cc: Ingo Molnar, Peter Zijlstra, linux-kernel On Wednesday, 28 of November 2007, Andrew Morton wrote: > > 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and > if I stay awake) will say this during suspend-to-RAM on the Vaio: > > [ 91.876445] Syncing filesystems ... done. > [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 > [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 > [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 > [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d > [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a > [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 > [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 I guess this is the task_lock() in refrigerator(). If that is the case, I don't understand this trace at all. > [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 > [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb > [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 > [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b > [ 92.385620] ======================= > [ 92.385719] irq event stamp: 309 > [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 > [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 > [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e > [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 > [ 92.392457] (elapsed 0.00 seconds) done. > [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > [ 92.392882] PM: Entering mem sleep > [ 92.392974] Suspending console(s) > > this has been happening for quite some time and might even be happening in > mainline. > > Also, a few seconds after resume has completed we get a whimper from the > hangcheck driver: > > [ 1.762425] usb 2-1: configuration #1 chosen from 1 choice > [ 1.826548] input: Microsoft Microsoft Wireless Optical Mouse_ 1.00 as /class/input/input9 > [ 1.866211] input: USB HID v1.11 Mouse [Microsoft Microsoft Wireless Optical Mouse_ 1.00] on usb-0000:00:1d.1-1 > [ 5.757927] Hangcheck: hangcheck value past margin! ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-11-28 10:43 suspend-related lockdep warning Andrew Morton 2007-11-28 22:06 ` Rafael J. Wysocki @ 2007-12-01 8:33 ` Pavel Machek 2007-12-02 20:33 ` Rafael J. Wysocki 1 sibling, 1 reply; 12+ messages in thread From: Pavel Machek @ 2007-12-01 8:33 UTC (permalink / raw) To: Andrew Morton Cc: Rafael J. Wysocki, Ingo Molnar, Peter Zijlstra, linux-kernel Hi! > 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and > if I stay awake) will say this during suspend-to-RAM on the Vaio: > > [ 91.876445] Syncing filesystems ... done. > [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 > [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 > [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 > [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d > [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a > [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 > [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 > [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 > [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb > [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 > [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b > [ 92.385620] ======================= > [ 92.385719] irq event stamp: 309 > [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 > [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 > [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e > [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 > [ 92.392457] (elapsed 0.00 seconds) done. > [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > [ 92.392882] PM: Entering mem sleep > [ 92.392974] Suspending console(s) > > this has been happening for quite some time and might even be happening in > mainline. Is it complaining that we entered refrigerator with irqs disabled? Pavel -- (english) http://www.livejournal.com/~pavelmachek (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-01 8:33 ` Pavel Machek @ 2007-12-02 20:33 ` Rafael J. Wysocki 2007-12-03 6:26 ` Andrew Morton 0 siblings, 1 reply; 12+ messages in thread From: Rafael J. Wysocki @ 2007-12-02 20:33 UTC (permalink / raw) To: Pavel Machek, Andrew Morton; +Cc: Ingo Molnar, Peter Zijlstra, linux-kernel On Saturday, 1 of December 2007, Pavel Machek wrote: > Hi! > > > 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and > > if I stay awake) will say this during suspend-to-RAM on the Vaio: > > > > [ 91.876445] Syncing filesystems ... done. > > [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 > > [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 > > [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 > > [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d > > [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a > > [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 > > [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 > > [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 > > [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb > > [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 > > [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b > > [ 92.385620] ======================= > > [ 92.385719] irq event stamp: 309 > > [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 > > [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 > > [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e > > [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 > > [ 92.392457] (elapsed 0.00 seconds) done. > > [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > [ 92.392882] PM: Entering mem sleep > > [ 92.392974] Suspending console(s) > > > > this has been happening for quite some time and might even be happening in > > mainline. > > Is it complaining that we entered refrigerator with irqs disabled? Or that someone else called task_lock() with irqs disabled at one point ... Hm, perhaps it's related to kernel preemption. Andrew, I guess the kernel is preemptible? Greetings, Rafael ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-02 20:33 ` Rafael J. Wysocki @ 2007-12-03 6:26 ` Andrew Morton 2007-12-03 22:34 ` Rafael J. Wysocki 0 siblings, 1 reply; 12+ messages in thread From: Andrew Morton @ 2007-12-03 6:26 UTC (permalink / raw) To: Rafael J. Wysocki; +Cc: Pavel Machek, Ingo Molnar, Peter Zijlstra, linux-kernel On Sun, 2 Dec 2007 21:33:23 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote: > On Saturday, 1 of December 2007, Pavel Machek wrote: > > Hi! > > > > > 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and > > > if I stay awake) will say this during suspend-to-RAM on the Vaio: > > > > > > [ 91.876445] Syncing filesystems ... done. > > > [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > > [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 > > > [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 > > > [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 > > > [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d > > > [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a > > > [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 > > > [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 > > > [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 > > > [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb > > > [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 > > > [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b > > > [ 92.385620] ======================= > > > [ 92.385719] irq event stamp: 309 > > > [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 > > > [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 > > > [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e > > > [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 > > > [ 92.392457] (elapsed 0.00 seconds) done. > > > [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > > [ 92.392882] PM: Entering mem sleep > > > [ 92.392974] Suspending console(s) > > > > > > this has been happening for quite some time and might even be happening in > > > mainline. > > > > Is it complaining that we entered refrigerator with irqs disabled? > > Or that someone else called task_lock() with irqs disabled at one point ... > > Hm, perhaps it's related to kernel preemption. Andrew, I guess the kernel is > preemptible? > yup. http://userweb.kernel.org/~akpm/config-sony.txt ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-03 6:26 ` Andrew Morton @ 2007-12-03 22:34 ` Rafael J. Wysocki 2007-12-04 1:45 ` Andrew Morton 0 siblings, 1 reply; 12+ messages in thread From: Rafael J. Wysocki @ 2007-12-03 22:34 UTC (permalink / raw) To: Andrew Morton; +Cc: Pavel Machek, Ingo Molnar, Peter Zijlstra, linux-kernel On Monday, 3 of December 2007, Andrew Morton wrote: > On Sun, 2 Dec 2007 21:33:23 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote: > > > On Saturday, 1 of December 2007, Pavel Machek wrote: > > > Hi! > > > > > > > 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and > > > > if I stay awake) will say this during suspend-to-RAM on the Vaio: > > > > > > > > [ 91.876445] Syncing filesystems ... done. > > > > [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > > > [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 > > > > [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 > > > > [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 > > > > [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d > > > > [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a > > > > [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 > > > > [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 > > > > [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 > > > > [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb > > > > [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 > > > > [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b > > > > [ 92.385620] ======================= > > > > [ 92.385719] irq event stamp: 309 > > > > [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 > > > > [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 > > > > [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e > > > > [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 > > > > [ 92.392457] (elapsed 0.00 seconds) done. > > > > [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > > > [ 92.392882] PM: Entering mem sleep > > > > [ 92.392974] Suspending console(s) > > > > > > > > this has been happening for quite some time and might even be happening in > > > > mainline. > > > > > > Is it complaining that we entered refrigerator with irqs disabled? > > > > Or that someone else called task_lock() with irqs disabled at one point ... > > > > Hm, perhaps it's related to kernel preemption. Andrew, I guess the kernel is > > preemptible? > > > > yup. http://userweb.kernel.org/~akpm/config-sony.txt Is this reproducible with kernel preemption off? ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-03 22:34 ` Rafael J. Wysocki @ 2007-12-04 1:45 ` Andrew Morton 2007-12-06 0:21 ` Rafael J. Wysocki 0 siblings, 1 reply; 12+ messages in thread From: Andrew Morton @ 2007-12-04 1:45 UTC (permalink / raw) To: Rafael J. Wysocki; +Cc: Pavel Machek, Ingo Molnar, Peter Zijlstra, linux-kernel On Mon, 3 Dec 2007 23:34:26 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote: > On Monday, 3 of December 2007, Andrew Morton wrote: > > On Sun, 2 Dec 2007 21:33:23 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote: > > > > > On Saturday, 1 of December 2007, Pavel Machek wrote: > > > > Hi! > > > > > > > > > 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and > > > > > if I stay awake) will say this during suspend-to-RAM on the Vaio: > > > > > > > > > > [ 91.876445] Syncing filesystems ... done. > > > > > [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > > > > [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 > > > > > [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 > > > > > [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 > > > > > [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d > > > > > [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a > > > > > [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 > > > > > [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 > > > > > [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 > > > > > [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb > > > > > [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 > > > > > [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b > > > > > [ 92.385620] ======================= > > > > > [ 92.385719] irq event stamp: 309 > > > > > [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 > > > > > [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 > > > > > [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e > > > > > [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 > > > > > [ 92.392457] (elapsed 0.00 seconds) done. > > > > > [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > > > > [ 92.392882] PM: Entering mem sleep > > > > > [ 92.392974] Suspending console(s) > > > > > > > > > > this has been happening for quite some time and might even be happening in > > > > > mainline. > > > > > > > > Is it complaining that we entered refrigerator with irqs disabled? > > > > > > Or that someone else called task_lock() with irqs disabled at one point ... > > > > > > Hm, perhaps it's related to kernel preemption. Andrew, I guess the kernel is > > > preemptible? > > > > > > > yup. http://userweb.kernel.org/~akpm/config-sony.txt > > Is this reproducible with kernel preemption off? yes. Current -mm lineup: [ 34.455096] ipw2200: Failed to send WEP_KEY: Command timed out. [ 34.911876] Syncing filesystems ... done. [ 34.934526] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() [ 34.934917] Pid: 1922, comm: dbus-daemon Not tainted 2.6.24-rc3-mm3 #2 [ 34.935036] [<c0104853>] show_trace_log_lvl+0x12/0x25 [ 34.935142] [<c010506c>] show_trace+0xd/0x10 [ 34.935231] [<c0105850>] dump_stack+0x55/0x5d [ 34.935322] [<c0136125>] check_flags+0x7f/0x11a [ 34.935417] [<c0139210>] lock_acquire+0x3a/0x86 [ 34.935511] [<c0318faf>] _spin_lock+0x1c/0x49 [ 34.935603] [<c0140fc7>] refrigerator+0x13/0xc8 [ 34.935697] [<c01270ac>] get_signal_to_deliver+0x34/0x2e8 [ 34.935807] [<c0102edc>] do_notify_resume+0x8c/0x6fe [ 34.935907] [<c0103a2c>] work_notifysig+0x13/0x1b [ 34.936004] ======================= [ 34.936072] irq event stamp: 253 [ 34.936133] hardirqs last enabled at (253): [<c0103a8d>] syscall_exit_work+0x11/0x26 [ 34.936294] hardirqs last disabled at (252): [<c0103956>] syscall_exit+0x14/0x25 [ 34.936446] softirqs last enabled at (0): [<c011baf9>] copy_process+0x300/0x1246 [ 34.936599] softirqs last disabled at (0): [<00000000>] 0x0 [ 34.954308] (elapsed 0.01 seconds) done. [ 34.954389] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-04 1:45 ` Andrew Morton @ 2007-12-06 0:21 ` Rafael J. Wysocki 2007-12-06 10:31 ` Peter Zijlstra 0 siblings, 1 reply; 12+ messages in thread From: Rafael J. Wysocki @ 2007-12-06 0:21 UTC (permalink / raw) To: Andrew Morton, Ingo Molnar; +Cc: Pavel Machek, Peter Zijlstra, linux-kernel On Tuesday, 4 of December 2007, Andrew Morton wrote: > On Mon, 3 Dec 2007 23:34:26 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote: > > > On Monday, 3 of December 2007, Andrew Morton wrote: > > > On Sun, 2 Dec 2007 21:33:23 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote: > > > > > > > On Saturday, 1 of December 2007, Pavel Machek wrote: > > > > > Hi! > > > > > > > > > > > 2.6.24-rc3-mm2 (which will be released if it boots on two more machines and > > > > > > if I stay awake) will say this during suspend-to-RAM on the Vaio: > > > > > > > > > > > > [ 91.876445] Syncing filesystems ... done. > > > > > > [ 92.382595] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > > > > > [ 92.384000] Pid: 1925, comm: dbus-daemon Not tainted 2.6.24-rc3-mm2 #32 > > > > > > [ 92.384177] [<c0104a74>] show_trace_log_lvl+0x12/0x25 > > > > > > [ 92.384335] [<c01052ff>] show_trace+0xd/0x10 > > > > > > [ 92.384469] [<c01059be>] dump_stack+0x55/0x5d > > > > > > [ 92.384605] [<c0136a29>] check_flags+0x7f/0x11a > > > > > > [ 92.384746] [<c0139cfb>] lock_acquire+0x3a/0x86 > > > > > > [ 92.384886] [<c031f4de>] _spin_lock+0x26/0x53 > > > > > > [ 92.385023] [<c0141d3b>] refrigerator+0x13/0xc8 > > > > > > [ 92.385163] [<c01274c8>] get_signal_to_deliver+0x32/0x3fb > > > > > > [ 92.385326] [<c01030f4>] do_notify_resume+0x8c/0x699 > > > > > > [ 92.385476] [<c0103c18>] work_notifysig+0x13/0x1b > > > > > > [ 92.385620] ======================= > > > > > > [ 92.385719] irq event stamp: 309 > > > > > > [ 92.385809] hardirqs last enabled at (309): [<c0103c79>] syscall_exit_work+0x11/0x26 > > > > > > [ 92.386045] hardirqs last disabled at (308): [<c0103b42>] syscall_exit+0x14/0x25 > > > > > > [ 92.386265] softirqs last enabled at (0): [<c011bea5>] copy_process+0x374/0x130e > > > > > > [ 92.386491] softirqs last disabled at (0): [<00000000>] 0x0 > > > > > > [ 92.392457] (elapsed 0.00 seconds) done. > > > > > > [ 92.392581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > > > > > [ 92.392882] PM: Entering mem sleep > > > > > > [ 92.392974] Suspending console(s) > > > > > > > > > > > > this has been happening for quite some time and might even be happening in > > > > > > mainline. > > > > > > > > > > Is it complaining that we entered refrigerator with irqs disabled? > > > > > > > > Or that someone else called task_lock() with irqs disabled at one point ... > > > > > > > > Hm, perhaps it's related to kernel preemption. Andrew, I guess the kernel is > > > > preemptible? > > > > > > > > > > yup. http://userweb.kernel.org/~akpm/config-sony.txt > > > > Is this reproducible with kernel preemption off? > > yes. Current -mm lineup: > > [ 34.455096] ipw2200: Failed to send WEP_KEY: Command timed out. > [ 34.911876] Syncing filesystems ... done. > [ 34.934526] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > [ 34.934917] Pid: 1922, comm: dbus-daemon Not tainted 2.6.24-rc3-mm3 #2 > [ 34.935036] [<c0104853>] show_trace_log_lvl+0x12/0x25 > [ 34.935142] [<c010506c>] show_trace+0xd/0x10 > [ 34.935231] [<c0105850>] dump_stack+0x55/0x5d > [ 34.935322] [<c0136125>] check_flags+0x7f/0x11a > [ 34.935417] [<c0139210>] lock_acquire+0x3a/0x86 > [ 34.935511] [<c0318faf>] _spin_lock+0x1c/0x49 > [ 34.935603] [<c0140fc7>] refrigerator+0x13/0xc8 > [ 34.935697] [<c01270ac>] get_signal_to_deliver+0x34/0x2e8 > [ 34.935807] [<c0102edc>] do_notify_resume+0x8c/0x6fe > [ 34.935907] [<c0103a2c>] work_notifysig+0x13/0x1b > [ 34.936004] ======================= > [ 34.936072] irq event stamp: 253 > [ 34.936133] hardirqs last enabled at (253): [<c0103a8d>] syscall_exit_work+0x11/0x26 > [ 34.936294] hardirqs last disabled at (252): [<c0103956>] syscall_exit+0x14/0x25 > [ 34.936446] softirqs last enabled at (0): [<c011baf9>] copy_process+0x300/0x1246 > [ 34.936599] softirqs last disabled at (0): [<00000000>] 0x0 > [ 34.954308] (elapsed 0.01 seconds) done. > [ 34.954389] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. Hmm, do I understand correctly that lockdep expects us to disable interrupts before acquiring the task lock in refrigerator()? That would be strange. Ingo, can you have a look at this, please? ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-06 0:21 ` Rafael J. Wysocki @ 2007-12-06 10:31 ` Peter Zijlstra 2007-12-06 12:01 ` Andrew Morton 0 siblings, 1 reply; 12+ messages in thread From: Peter Zijlstra @ 2007-12-06 10:31 UTC (permalink / raw) To: Rafael J. Wysocki; +Cc: Andrew Morton, Ingo Molnar, Pavel Machek, linux-kernel [-- Attachment #1: Type: text/plain, Size: 2126 bytes --] On Thu, 2007-12-06 at 01:21 +0100, Rafael J. Wysocki wrote: > On Tuesday, 4 of December 2007, Andrew Morton wrote: > > [ 34.455096] ipw2200: Failed to send WEP_KEY: Command timed out. > > [ 34.911876] Syncing filesystems ... done. > > [ 34.934526] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > [ 34.934917] Pid: 1922, comm: dbus-daemon Not tainted 2.6.24-rc3-mm3 #2 > > [ 34.935036] [<c0104853>] show_trace_log_lvl+0x12/0x25 > > [ 34.935142] [<c010506c>] show_trace+0xd/0x10 > > [ 34.935231] [<c0105850>] dump_stack+0x55/0x5d > > [ 34.935322] [<c0136125>] check_flags+0x7f/0x11a > > [ 34.935417] [<c0139210>] lock_acquire+0x3a/0x86 > > [ 34.935511] [<c0318faf>] _spin_lock+0x1c/0x49 > > [ 34.935603] [<c0140fc7>] refrigerator+0x13/0xc8 > > [ 34.935697] [<c01270ac>] get_signal_to_deliver+0x34/0x2e8 > > [ 34.935807] [<c0102edc>] do_notify_resume+0x8c/0x6fe > > [ 34.935907] [<c0103a2c>] work_notifysig+0x13/0x1b > > [ 34.936004] ======================= > > [ 34.936072] irq event stamp: 253 > > [ 34.936133] hardirqs last enabled at (253): [<c0103a8d>] syscall_exit_work+0x11/0x26 > > [ 34.936294] hardirqs last disabled at (252): [<c0103956>] syscall_exit+0x14/0x25 > > [ 34.936446] softirqs last enabled at (0): [<c011baf9>] copy_process+0x300/0x1246 > > [ 34.936599] softirqs last disabled at (0): [<00000000>] 0x0 > > [ 34.954308] (elapsed 0.01 seconds) done. > > [ 34.954389] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > Hmm, do I understand correctly that lockdep expects us to disable interrupts > before acquiring the task lock in refrigerator()? That would be strange. > > Ingo, can you have a look at this, please? No its complaining that the IRQ state changed without anybody telling it about it. Usually an unannotated cli/sti. The particular line it warns, (lockdep.c:2662), suggests... /me grabs a copy of 24-rc3-mm2 ... that hardirqs are disabled, but irq tracking thinks they are still enabled. So that would be an unannotated cli. [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 189 bytes --] ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-06 10:31 ` Peter Zijlstra @ 2007-12-06 12:01 ` Andrew Morton 2007-12-06 12:04 ` Ingo Molnar 2007-12-06 12:04 ` Peter Zijlstra 0 siblings, 2 replies; 12+ messages in thread From: Andrew Morton @ 2007-12-06 12:01 UTC (permalink / raw) To: Peter Zijlstra; +Cc: Rafael J. Wysocki, Ingo Molnar, Pavel Machek, linux-kernel On Thu, 06 Dec 2007 11:31:28 +0100 Peter Zijlstra <a.p.zijlstra@chello.nl> wrote: > > On Thu, 2007-12-06 at 01:21 +0100, Rafael J. Wysocki wrote: > > On Tuesday, 4 of December 2007, Andrew Morton wrote: > > > > [ 34.455096] ipw2200: Failed to send WEP_KEY: Command timed out. > > > [ 34.911876] Syncing filesystems ... done. > > > [ 34.934526] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > > [ 34.934917] Pid: 1922, comm: dbus-daemon Not tainted 2.6.24-rc3-mm3 #2 > > > [ 34.935036] [<c0104853>] show_trace_log_lvl+0x12/0x25 > > > [ 34.935142] [<c010506c>] show_trace+0xd/0x10 > > > [ 34.935231] [<c0105850>] dump_stack+0x55/0x5d > > > [ 34.935322] [<c0136125>] check_flags+0x7f/0x11a > > > [ 34.935417] [<c0139210>] lock_acquire+0x3a/0x86 > > > [ 34.935511] [<c0318faf>] _spin_lock+0x1c/0x49 > > > [ 34.935603] [<c0140fc7>] refrigerator+0x13/0xc8 > > > [ 34.935697] [<c01270ac>] get_signal_to_deliver+0x34/0x2e8 > > > [ 34.935807] [<c0102edc>] do_notify_resume+0x8c/0x6fe > > > [ 34.935907] [<c0103a2c>] work_notifysig+0x13/0x1b > > > [ 34.936004] ======================= > > > [ 34.936072] irq event stamp: 253 > > > [ 34.936133] hardirqs last enabled at (253): [<c0103a8d>] syscall_exit_work+0x11/0x26 > > > [ 34.936294] hardirqs last disabled at (252): [<c0103956>] syscall_exit+0x14/0x25 > > > [ 34.936446] softirqs last enabled at (0): [<c011baf9>] copy_process+0x300/0x1246 > > > [ 34.936599] softirqs last disabled at (0): [<00000000>] 0x0 > > > [ 34.954308] (elapsed 0.01 seconds) done. > > > [ 34.954389] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > > > Hmm, do I understand correctly that lockdep expects us to disable interrupts > > before acquiring the task lock in refrigerator()? That would be strange. > > > > Ingo, can you have a look at this, please? > > No its complaining that the IRQ state changed without anybody telling it > about it. Usually an unannotated cli/sti. > > The particular line it warns, (lockdep.c:2662), suggests... > > /me grabs a copy of 24-rc3-mm2 > > ... that hardirqs are disabled, but irq tracking thinks they are still > enabled. So that would be an unannotated cli. > It would be nice to make that warning tell us that - we've hit it a few times and I never knew this was the reason. ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-06 12:01 ` Andrew Morton @ 2007-12-06 12:04 ` Ingo Molnar 2007-12-06 12:04 ` Peter Zijlstra 1 sibling, 0 replies; 12+ messages in thread From: Ingo Molnar @ 2007-12-06 12:04 UTC (permalink / raw) To: Andrew Morton Cc: Peter Zijlstra, Rafael J. Wysocki, Pavel Machek, linux-kernel * Andrew Morton <akpm@linux-foundation.org> wrote: > It would be nice to make that warning tell us that - we've hit it a > few times and I never knew this was the reason. i'm a mind-reader and a time-traveler as well, so i've got the patch below lined up in my sched.git queue already :-) Ingo --------------> Subject: lockdep: make cli/sti annotation warnings clearer From: Ingo Molnar <mingo@elte.hu> make cli/sti annotation warnings easier to interpret. Signed-off-by: Ingo Molnar <mingo@elte.hu> Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl> --- kernel/lockdep.c | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) Index: linux/kernel/lockdep.c =================================================================== --- linux.orig/kernel/lockdep.c +++ linux/kernel/lockdep.c @@ -2654,10 +2654,15 @@ static void check_flags(unsigned long fl if (!debug_locks) return; - if (irqs_disabled_flags(flags)) - DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled); - else - DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled); + if (irqs_disabled_flags(flags)) { + if (DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled)) { + printk("possible reason: unannotated irqs-off.\n"); + } + } else { + if (DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled)) { + printk("possible reason: unannotated irqs-on.\n"); + } + } /* * We dont accurately track softirq state in e.g. ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: suspend-related lockdep warning 2007-12-06 12:01 ` Andrew Morton 2007-12-06 12:04 ` Ingo Molnar @ 2007-12-06 12:04 ` Peter Zijlstra 1 sibling, 0 replies; 12+ messages in thread From: Peter Zijlstra @ 2007-12-06 12:04 UTC (permalink / raw) To: Andrew Morton; +Cc: Rafael J. Wysocki, Ingo Molnar, Pavel Machek, linux-kernel [-- Attachment #1: Type: text/plain, Size: 2653 bytes --] On Thu, 2007-12-06 at 04:01 -0800, Andrew Morton wrote: > On Thu, 06 Dec 2007 11:31:28 +0100 Peter Zijlstra <a.p.zijlstra@chello.nl> wrote: > > > > > On Thu, 2007-12-06 at 01:21 +0100, Rafael J. Wysocki wrote: > > > On Tuesday, 4 of December 2007, Andrew Morton wrote: > > > > > > [ 34.455096] ipw2200: Failed to send WEP_KEY: Command timed out. > > > > [ 34.911876] Syncing filesystems ... done. > > > > [ 34.934526] Freezing user space processes ... WARNING: at kernel/lockdep.c:2662 check_flags() > > > > [ 34.934917] Pid: 1922, comm: dbus-daemon Not tainted 2.6.24-rc3-mm3 #2 > > > > [ 34.935036] [<c0104853>] show_trace_log_lvl+0x12/0x25 > > > > [ 34.935142] [<c010506c>] show_trace+0xd/0x10 > > > > [ 34.935231] [<c0105850>] dump_stack+0x55/0x5d > > > > [ 34.935322] [<c0136125>] check_flags+0x7f/0x11a > > > > [ 34.935417] [<c0139210>] lock_acquire+0x3a/0x86 > > > > [ 34.935511] [<c0318faf>] _spin_lock+0x1c/0x49 > > > > [ 34.935603] [<c0140fc7>] refrigerator+0x13/0xc8 > > > > [ 34.935697] [<c01270ac>] get_signal_to_deliver+0x34/0x2e8 > > > > [ 34.935807] [<c0102edc>] do_notify_resume+0x8c/0x6fe > > > > [ 34.935907] [<c0103a2c>] work_notifysig+0x13/0x1b > > > > [ 34.936004] ======================= > > > > [ 34.936072] irq event stamp: 253 > > > > [ 34.936133] hardirqs last enabled at (253): [<c0103a8d>] syscall_exit_work+0x11/0x26 > > > > [ 34.936294] hardirqs last disabled at (252): [<c0103956>] syscall_exit+0x14/0x25 > > > > [ 34.936446] softirqs last enabled at (0): [<c011baf9>] copy_process+0x300/0x1246 > > > > [ 34.936599] softirqs last disabled at (0): [<00000000>] 0x0 > > > > [ 34.954308] (elapsed 0.01 seconds) done. > > > > [ 34.954389] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. > > > > > > Hmm, do I understand correctly that lockdep expects us to disable interrupts > > > before acquiring the task lock in refrigerator()? That would be strange. > > > > > > Ingo, can you have a look at this, please? > > > > No its complaining that the IRQ state changed without anybody telling it > > about it. Usually an unannotated cli/sti. > > > > The particular line it warns, (lockdep.c:2662), suggests... > > > > /me grabs a copy of 24-rc3-mm2 > > > > ... that hardirqs are disabled, but irq tracking thinks they are still > > enabled. So that would be an unannotated cli. > > > > It would be nice to make that warning tell us that - we've hit it a > few times and I never knew this was the reason. Ingo just did that, patch should be coming to a lockdep repo near you soon :-) [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 189 bytes --] ^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2007-12-06 12:04 UTC | newest] Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2007-11-28 10:43 suspend-related lockdep warning Andrew Morton 2007-11-28 22:06 ` Rafael J. Wysocki 2007-12-01 8:33 ` Pavel Machek 2007-12-02 20:33 ` Rafael J. Wysocki 2007-12-03 6:26 ` Andrew Morton 2007-12-03 22:34 ` Rafael J. Wysocki 2007-12-04 1:45 ` Andrew Morton 2007-12-06 0:21 ` Rafael J. Wysocki 2007-12-06 10:31 ` Peter Zijlstra 2007-12-06 12:01 ` Andrew Morton 2007-12-06 12:04 ` Ingo Molnar 2007-12-06 12:04 ` Peter Zijlstra
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).