* 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).