Re: Linux 2.6.22-rc4

On Tue, 5 Jun 2007, Michal Piotrowski wrote:

It is too stable for me.

I wish all our testers were you ;)

this looks harmless

[  116.733327] PM: suspend-to-disk mode set to 'shutdown'
[  116.738849] swsusp: Basic memory bitmaps created
[  116.745353] Stopping tasks ... WARNING: at /home/devel/linux-git/kernel/lockdep.c:2414 check_flags()
[  116.754921]  [<c0404fbf>] show_trace_log_lvl+0x1a/0x2f
[  116.754937]  [<c0405bd6>] show_trace+0x12/0x14
[  116.754947]  [<c0405c5d>] dump_stack+0x16/0x18
[  116.754957]  [<c043c3e5>] check_flags+0x95/0x143
[  116.754967]  [<c043f158>] lock_acquire+0x29/0x82
[  116.754977]  [<c06313a7>] _spin_lock+0x35/0x42
[  116.754990]  [<c044894a>] refrigerator+0x14/0xc6
[  116.755002]  [<c042d4b3>] get_signal_to_deliver+0x33/0x397
[  116.755016]  [<c0403597>] do_notify_resume+0x94/0x6ed
[  116.755029]  [<c0404099>] work_notifysig+0x13/0x1a
[  116.755044]  =======================
[  116.755052] irq event stamp: 69
[  116.755060] hardirqs last  enabled at (69): [<c04040f9>] syscall_exit_work+0x11/0x26
[  116.755084] hardirqs last disabled at (68): [<c0403fdd>] syscall_exit+0x9/0x1a
[  116.755109] softirqs last  enabled at (0): [<c042150c>] copy_process+0x4dd/0x1286
[  116.755139] softirqs last disabled at (0): [<00000000>] 0x0
[  116.945776] done.

http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.22-rc4/git-dmesg
http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.22-rc4/git-config

Well, it's harmless in the sense that "yeah, the system still works", but 
it does seem to be a real bug. We have hardware interrupts disabled when 
we _think_ we should have them on, so our irq tracking is off.

Ingo, do you see what's up? It looks like we got a signal to a process 
that just got created, is the setup stuff for "tsk->hardirqs_enabled" 
perhaps off a bit?

			Linus

* Linus Torvalds [off-list ref] wrote:

quoted

this looks harmless

[ 116.733327] PM: suspend-to-disk mode set to 'shutdown' [ 
116.738849] swsusp: Basic memory bitmaps created [ 116.745353] 
Stopping tasks ... WARNING: at 
/home/devel/linux-git/kernel/lockdep.c:2414 check_flags()

quoted

[  116.755052] irq event stamp: 69
[  116.755060] hardirqs last  enabled at (69): [<c04040f9>] syscall_exit_work+0x11/0x26
[  116.755084] hardirqs last disabled at (68): [<c0403fdd>] syscall_exit+0x9/0x1a
[  116.755109] softirqs last  enabled at (0): [<c042150c>] copy_process+0x4dd/0x1286
[  116.755139] softirqs last disabled at (0): [<00000000>] 0x0
[  116.945776] done.

Well, it's harmless in the sense that "yeah, the system still works", 
but it does seem to be a real bug. We have hardware interrupts 
disabled when we _think_ we should have them on, so our irq tracking 
is off.

Ingo, do you see what's up? It looks like we got a signal to a process 
that just got created, is the setup stuff for "tsk->hardirqs_enabled" 
perhaps off a bit?

hm. I cannot see the source of the bug at the moment, but here's my 
analysis so far:

the last event that irqtrace got was #69, and that was a 'hardirqs on' 
in syscall_exit_work. After that we did a 'hardirqs off' without 
properly tracking that via irqtrace. Next time we got an irqtrace event 
(event 70) the assert caught up with us and turned off lockdep and 
backed out of that function. This was in:

 > [  116.754957]  [<c043c3e5>] check_flags+0x95/0x143
 > [  116.754967]  [<c043f158>] lock_acquire+0x29/0x82
 > [  116.754977]  [<c06313a7>] _spin_lock+0x35/0x42
 > [  116.754990]  [<c044894a>] refrigerator+0x14/0xc6
 > [  116.755002]  [<c042d4b3>] get_signal_to_deliver+0x33/0x397
 > [  116.755016]  [<c0403597>] do_notify_resume+0x94/0x6ed
 > [  116.755029]  [<c0404099>] work_notifysig+0x13/0x1a

isnt the refrigerator() suspend related? Perhaps suspend disables irqs 
somewhere that we forgot to track?

a new thread gets its hardirqs_enabled this way:

 #ifdef __ARCH_WANT_INTERRUPTS_ON_CTXSW
         p->hardirqs_enabled = 1;
 #else
         p->hardirqs_enabled = 0;
 #endif

on i386 __ARCH_WANT_INTERRUPTS_ON_CTXSW is off so it starts with 0. We 
set this up in copy_process() so there's no chance this task can run 
without this initialized.

	Ingo

On Tue, 5 Jun 2007, Ingo Molnar wrote:

isnt the refrigerator() suspend related? Perhaps suspend disables irqs 
somewhere that we forgot to track?

There _is_ something strange there. For that whole sequence to trigger, 
the current task has to have the TIF_FREEZE bit set, but I don't see why 
it would be during shutdown.

		Linus

Hi!

quoted

isnt the refrigerator() suspend related? Perhaps suspend disables irqs 
somewhere that we forgot to track?

There _is_ something strange there. For that whole sequence to trigger, 
the current task has to have the TIF_FREEZE bit set, but I don't see why 
it would be during shutdown.

[  116.733327] PM: suspend-to-disk mode set to 'shutdown'
[  116.738849] swsusp: Basic memory bitmaps created
[  116.745353] Stopping tasks ... WARNING: at
/home/devel/linux-git/kernel/lockdep.c:2414 check_flags()
[  116.754921]  [<c0404fbf>] show_trace_log_lvl+0x1a/0x2f
[  116.754937]  [<c0405bd6>] show_trace+0x12/0x14

No, he's not shutting down, he's trying to snapshot his
machine. 'shutdown' will be done at end of hibernation, _way_ after
this.

								Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Hi!

quoted

quoted

[ 116.733327] PM: suspend-to-disk mode set to 'shutdown' [ 
116.738849] swsusp: Basic memory bitmaps created [ 116.745353] 
Stopping tasks ... WARNING: at 
/home/devel/linux-git/kernel/lockdep.c:2414 check_flags()

quoted

quoted

[  116.755052] irq event stamp: 69
[  116.755060] hardirqs last  enabled at (69): [<c04040f9>] syscall_exit_work+0x11/0x26
[  116.755084] hardirqs last disabled at (68): [<c0403fdd>] syscall_exit+0x9/0x1a
[  116.755109] softirqs last  enabled at (0): [<c042150c>] copy_process+0x4dd/0x1286
[  116.755139] softirqs last disabled at (0): [<00000000>] 0x0
[  116.945776] done.

quoted

Well, it's harmless in the sense that "yeah, the system still works", 
but it does seem to be a real bug. We have hardware interrupts 
disabled when we _think_ we should have them on, so our irq tracking 
is off.

Ingo, do you see what's up? It looks like we got a signal to a process 
that just got created, is the setup stuff for "tsk->hardirqs_enabled" 
perhaps off a bit?

hm. I cannot see the source of the bug at the moment, but here's my 
analysis so far:

the last event that irqtrace got was #69, and that was a 'hardirqs on' 
in syscall_exit_work. After that we did a 'hardirqs off' without 
properly tracking that via irqtrace. Next time we got an irqtrace event 
(event 70) the assert caught up with us and turned off lockdep and 
backed out of that function. This was in:

 > [  116.754957]  [<c043c3e5>] check_flags+0x95/0x143
 > [  116.754967]  [<c043f158>] lock_acquire+0x29/0x82
 > [  116.754977]  [<c06313a7>] _spin_lock+0x35/0x42
 > [  116.754990]  [<c044894a>] refrigerator+0x14/0xc6
 > [  116.755002]  [<c042d4b3>] get_signal_to_deliver+0x33/0x397
 > [  116.755016]  [<c0403597>] do_notify_resume+0x94/0x6ed
 > [  116.755029]  [<c0404099>] work_notifysig+0x13/0x1a

isnt the refrigerator() suspend related? Perhaps suspend disables irqs 
somewhere that we forgot to track?

refrigerator is suspend related, but I do not think it does any
interrupt magic. We do magic later in hibernation process.

This is in kernel/power/process.c, we have spinlock_irqsave there, but
that's pretty much it AFAICT.
								Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

On Jun 5 2007 12:26, Linus Torvalds wrote:

On Tue, 5 Jun 2007, Michal Piotrowski wrote:

quoted

It is too stable for me.

I wish all our testers were you ;)

It [2.6.22-rc4] did not die on me so far, unlike that stock FC7 kernel 
(same config but without fc patches).



	Jan
-- 

On Thursday 07 June 2007, Jan Engelhardt wrote:

On Jun 5 2007 12:26, Linus Torvalds wrote:

quoted

On Tue, 5 Jun 2007, Michal Piotrowski wrote:

quoted

It is too stable for me.

I wish all our testers were you ;)

It [2.6.22-rc4] did not die on me so far, unlike that stock FC7 kernel
(same config but without fc patches).



Jan

Oh its stable allright, but why do I have to turn the monitor off by hand when 
I leave.  None of that is working, not even the screen blanker.

-- 
Cheers, Gene
"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)
I'm not an Iranian!!  I voted for Dianne Feinstein!!