Fwd: 2.6.17-rc5-mm1

Fwd: 2.6.17-rc5-mm1

[Michal Piotrowski]

Sorry, I forgot CC.

---------- Forwarded message ----------
From: Michal Piotrowski <michal.k.k.piotrowski@gmail.com>
Date: 30-May-2006 20:55
Subject: Re: 2.6.17-rc5-mm1
To: Andrew Morton <akpm@osdl.org>
Cc: linux-kernel@vger.kernel.org


Hi,

On 30/05/06, Andrew Morton <akpm@osdl.org> wrote:
>
> ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17-rc5/2.6.17-rc5-mm1/
>

SCSI or libata problem.
============================
[ BUG: illegal lock usage! ]
----------------------------
illegal {in-hardirq-W} -> {hardirq-on-W} usage.
init/1 [HC0[0]:SC0[0]:HE1:SE1] takes:
 (&base->lock#2){++..}, at: [<c0129a24>] lock_timer_base+0x29/0x55
{in-hardirq-W} state was registered at:
  [<c0139a56>] lockdep_acquire+0x69/0x82
  [<c02f237c>] _spin_lock_irqsave+0x2a/0x3a
  [<c0129a24>] lock_timer_base+0x29/0x55
  [<c0129e48>] del_timer+0x19/0x4c
  [<c02651e2>] scsi_delete_timer+0xe/0x1f
  [<c0262964>] scsi_done+0xb/0x19
  [<c0273ed3>] ata_scsi_qc_complete+0x73/0x7f
  [<c027024a>] __ata_qc_complete+0x26c/0x274
  [<c02704f0>] ata_qc_complete+0xd5/0xdc
  [<c0270c42>] ata_hsm_qc_complete+0x201/0x210
  [<c02713e7>] ata_hsm_move+0x796/0x7ac
  [<c027314e>] ata_interrupt+0x173/0x1b4
  [<c014c4f4>] handle_IRQ_event+0x20/0x50
  [<c014d76e>] handle_level_irq+0xa1/0xeb
  [<c010579c>] do_IRQ+0xa1/0xc9
irq event stamp: 576924
hardirqs last  enabled at (576923): [<c02f26c7>]
_spin_unlock_irqrestore+0x36/0x69
hardirqs last disabled at (576924): [<c02f2361>] _spin_lock_irqsave+0xf/0x3a
softirqs last  enabled at (576878): [<c0125873>] __do_softirq+0xea/0xf0
softirqs last disabled at (576869): [<c0105689>] do_softirq+0x59/0xcb

other info that might help us debug this:
1 locks held by init/1:
 #0:  (&base->lock#2){++..}, at: [<c0129a24>] lock_timer_base+0x29/0x55

stack backtrace:
 [<c0103e52>] show_trace_log_lvl+0x4b/0xf4
 [<c01044b3>] show_trace+0xd/0x10
 [<c010457b>] dump_stack+0x19/0x1b
 [<c0137d63>] print_usage_bug+0x1a1/0x1ab
 [<c0138458>] mark_lock+0x2d7/0x514
 [<c01386dc>] mark_held_locks+0x47/0x65
 [<c0139745>] trace_hardirqs_on+0x12b/0x16f
 [<c02f2b61>] restore_nocheck+0x8/0xb

Here is config
http://www.stardust.webpages.pl/files/mm/2.6.17-rc5-mm1/mm-config2

Here is dmesg
http://www.stardust.webpages.pl/files/mm/2.6.17-rc5-mm1/mm-dmesg2

Regards,
Michal

--
Michal K. K. Piotrowski
LTG - Linux Testers Group
(http://www.stardust.webpages.pl/ltg/wiki/)

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Michal Piotrowski <michal.k.k.piotrowski@gmail.com> wrote:

> SCSI or libata problem.

i think SCSI and libata is innocent here.

> ============================
> [ BUG: illegal lock usage! ]
> ----------------------------
> illegal {in-hardirq-W} -> {hardirq-on-W} usage.

> 1 locks held by init/1:
> #0:  (&base->lock#2){++..}, at: [<c0129a24>] lock_timer_base+0x29/0x55
> 
> stack backtrace:
> [<c0103e52>] show_trace_log_lvl+0x4b/0xf4
> [<c01044b3>] show_trace+0xd/0x10
> [<c010457b>] dump_stack+0x19/0x1b
> [<c0137d63>] print_usage_bug+0x1a1/0x1ab
> [<c0138458>] mark_lock+0x2d7/0x514
> [<c01386dc>] mark_held_locks+0x47/0x65
> [<c0139745>] trace_hardirqs_on+0x12b/0x16f
> [<c02f2b61>] restore_nocheck+0x8/0xb

weird. We are holding base->lock#2 [CPU#1's timer base lock], _and_ we 
execute restore_nocheck - which is a return-to-userspace thing.

unfortunately the stacktrace provides no clues of how we got here. 
For such nasty cases i have a kernel tracing patch prepared, you can get 
it from:

  http://redhat.com/~mingo/lockdep-patches/latency-tracing-lockdep.patch

just apply it ontop of your current tree and accept all the new .config 
options as the kernel suggests them to you. Then rebuild and reboot into 
the kernel, and reproduce the lockdep bug. Once such a bug is reported, 
/proc/latency_trace should have a full kernel trace leading up to the 
bug. Please upload that trace to your site and send us the URL.

(the tracer runs nonstop and it saves the current trace if it encounters 
a lockdep bug. That way i can see the history of the bug.)

if possible it would be nice to boot with maxcpus=1 as well, to make 
sure we have all relevant kernel activity traced. (assuming that booting 
with maxcpus=1 does not make the bug go away)

	Ingo

Re: Fwd: 2.6.17-rc5-mm1

[Ingo Molnar]

* Michal Piotrowski <michal.k.k.piotrowski@gmail.com> wrote:

> ============================
> [ BUG: illegal lock usage! ]
> ----------------------------
> illegal {in-hardirq-W} -> {hardirq-on-W} usage.

sorry - the messages are indeed cryptic, partly because there are lots 
of illegal state transitions and the printout is atomated, and partly to 
keep the already sizable lockdep printouts as compact as possible.

What happened here is that a lock (-type) that had the {in-hardirq-W} 
state bit set, and lockdep observed an event that also sets the 
{hardirq-on-W} state bit: illegal.

here is a rough translation of the usage history state bits:

 {in-hardirq-W}: lock was exclusively acquired in hardirq context
 {in-hardirq-R}: lock was read-acquired in hardirq context
 {in-softirq-W}: lock was exclusively acquired in softirq context
 {in-softirq-R}: lock was read-acquired in softirq context
 {hardirq-on-W}: lock was held exclusively with hardirqs enabled
 {hardirq-on-R}: lock was read-held with hardirqs enabled
 {softirq-on-W}: lock was held exclusively with softirqs enabled
 {softirq-on-R}: lock was read-held with softirqs enabled

to interpret the lock state at a glance, there's an even shorter 
representation of the state bits:

 (&base->lock#2){++..}
                 ^^^^

'+' : irq-safe [lock was taken in irq context]
'-' : irq-unsafe [lock was taken with irqs enabled]
'.' : unknown [lock has not yet become irq-safe or irq-unsafe]

'?' : read-locked with both hardirq context and with irqs enabled

the first character is for exclusive-locking in hardirqs, the second for 
exclusive-locking in softirqs, the third is for read-locking in 
hardirqs, the fourth is for read-locking in softirqs.

this means that the "{++..}" sequence shows that this lock is 
hardirq-safe and softirq-safe, and was never read-locked. [the later one 
is not surprising from a spinlock - but lockdep doesnt know that it's a 
spinlock, it deals with all lock types in a unified way]

(more details about the usage history state bits are in 
Documentation/lockdep-design.txt and in include/linux/lockdep.h)

	Ingo

Re: 2.6.17-rc5-mm1

[Michal Piotrowski]

On 30/05/06, Ingo Molnar <mingo@elte.hu> wrote:
> * Michal Piotrowski <michal.k.k.piotrowski@gmail.com> wrote:
>
> > SCSI or libata problem.
>
> i think SCSI and libata is innocent here.
>
> > ============================
> > [ BUG: illegal lock usage! ]
> > ----------------------------
> > illegal {in-hardirq-W} -> {hardirq-on-W} usage.
>
> > 1 locks held by init/1:
> > #0:  (&base->lock#2){++..}, at: [<c0129a24>] lock_timer_base+0x29/0x55
> >
> > stack backtrace:
> > [<c0103e52>] show_trace_log_lvl+0x4b/0xf4
> > [<c01044b3>] show_trace+0xd/0x10
> > [<c010457b>] dump_stack+0x19/0x1b
> > [<c0137d63>] print_usage_bug+0x1a1/0x1ab
> > [<c0138458>] mark_lock+0x2d7/0x514
> > [<c01386dc>] mark_held_locks+0x47/0x65
> > [<c0139745>] trace_hardirqs_on+0x12b/0x16f
> > [<c02f2b61>] restore_nocheck+0x8/0xb
>
> weird. We are holding base->lock#2 [CPU#1's timer base lock], _and_ we
> execute restore_nocheck - which is a return-to-userspace thing.
>
> unfortunately the stacktrace provides no clues of how we got here.
> For such nasty cases i have a kernel tracing patch prepared, you can get
> it from:
>
>   http://redhat.com/~mingo/lockdep-patches/latency-tracing-lockdep.patch
>
> just apply it ontop of your current tree and accept all the new .config
> options as the kernel suggests them to you.

I can't boot with that patch. I even don't see "Uncompressing
Linux..." - machine reboots.
I have 2.6.17-rc5-mm1 +
genirq-cleanup-remove-irq_descp-fix.patch
lock-validator-irqtrace-support-non-x86-architectures.patch
lock-validator-special-locking-sb-s_umount-2-fix.patch
from hot fixes
+
Arjan's net/ipv4/igmp.c patch.

BTW. I got error when compiling kernel/latency.c, so I change
if (DEBUG_WARN_ON((val < PREEMPT_MASK) && !(preempt_count() & PREEMPT_MASK))))

to

if (DEBUG_WARN_ON((val < PREEMPT_MASK) && !(preempt_count() & PREEMPT_MASK)))

Here is config
http://www.stardust.webpages.pl/files/mm/2.6.17-rc5-mm1/mm-config3

Here is "Kernel Bug : The Movie" (4,3MB)
www.stardust.webpages.pl/files/crap/kbtm.avi

[snip]
>
>         Ingo
>

Regards,
Michal

-- 
Michal K. K. Piotrowski
LTG - Linux Testers Group
(http://www.stardust.webpages.pl/ltg/wiki/)

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Michal Piotrowski <michal.k.k.piotrowski@gmail.com> wrote:

> >  http://redhat.com/~mingo/lockdep-patches/latency-tracing-lockdep.patch
> >
> >just apply it ontop of your current tree and accept all the new .config
> >options as the kernel suggests them to you.
> 
> I can't boot with that patch. I even don't see "Uncompressing
> Linux..." - machine reboots.
> I have 2.6.17-rc5-mm1 +
> genirq-cleanup-remove-irq_descp-fix.patch
> lock-validator-irqtrace-support-non-x86-architectures.patch
> lock-validator-special-locking-sb-s_umount-2-fix.patch
> from hot fixes
> +
> Arjan's net/ipv4/igmp.c patch.

could you try to 1) disable PREEMPT, 2) apply the -V2 rollup of all 
fixes so far to 2.6.17-rc5-mm1:

 http://redhat.com/~mingo/lockdep-patches/lockdep-combo-2.6.17-rc5-mm1.patch

? I'll try your config meanwhile.

	Ingo

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> could you try to 1) disable PREEMPT, 2) apply the -V2 rollup of all 
> fixes so far to 2.6.17-rc5-mm1:
> 
>  http://redhat.com/~mingo/lockdep-patches/lockdep-combo-2.6.17-rc5-mm1.patch
> 
> ? I'll try your config meanwhile.

PREEMPT wasnt the problem but CONFIG_DEBUG_STACKOVERFLOW (at least). 
There's some other debug option that seems incompatible too - i'm still 
trying to figure out which one.

	Ingo

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> PREEMPT wasnt the problem but CONFIG_DEBUG_STACKOVERFLOW (at least). 
> There's some other debug option that seems incompatible too - i'm 
> still trying to figure out which one.

narrowed it down to:

--- .config.good01	2006-05-31 00:24:44.000000000 +0200
+++ .config.bad01	2006-05-31 00:22:28.000000000 +0200
@@ -1,7 +1,7 @@
 #
 # Automatically generated make config: don't edit
 # Linux kernel version: 2.6.17-rc5-mm1-lockdep
-# Wed May 31 00:23:12 2006
+# Wed May 31 00:19:45 2006
 #
 CONFIG_X86_32=y
 CONFIG_GENERIC_TIME=y
@@ -1798,7 +1798,7 @@ CONFIG_PROVE_RWSEM_LOCKING=y
 CONFIG_LOCKDEP=y
 CONFIG_DEBUG_LOCKDEP=y
 CONFIG_TRACE_IRQFLAGS=y
-# CONFIG_DEBUG_SPINLOCK_SLEEP is not set
+CONFIG_DEBUG_SPINLOCK_SLEEP=y
 CONFIG_DEBUG_LOCKING_API_SELFTESTS=y
 CONFIG_WAKEUP_TIMING=y
 # CONFIG_WAKEUP_LATENCY_HIST is not set
@@ -1807,18 +1807,19 @@ CONFIG_LATENCY_TIMING=y
 CONFIG_LATENCY_TRACE=y
 CONFIG_MCOUNT=y
 # CONFIG_DEBUG_KOBJECT is not set
-# CONFIG_DEBUG_HIGHMEM is not set
+CONFIG_DEBUG_HIGHMEM=y
 CONFIG_DEBUG_BUGVERBOSE=y
-# CONFIG_DEBUG_INFO is not set
-# CONFIG_PAGE_OWNER is not set
+CONFIG_DEBUG_INFO=y
+CONFIG_PAGE_OWNER=y
 CONFIG_DEBUG_FS=y
-# CONFIG_DEBUG_VM is not set
+CONFIG_DEBUG_VM=y
 CONFIG_FRAME_POINTER=y
-# CONFIG_UNWIND_INFO is not set
+CONFIG_UNWIND_INFO=y
+CONFIG_STACK_UNWIND=y
 CONFIG_FORCED_INLINING=y
-# CONFIG_DEBUG_SYNCHRO_TEST is not set
-# CONFIG_RCU_TORTURE_TEST is not set
-# CONFIG_PROFILE_LIKELY is not set
+CONFIG_DEBUG_SYNCHRO_TEST=y
+CONFIG_RCU_TORTURE_TEST=y
+CONFIG_PROFILE_LIKELY=y
 # CONFIG_WANT_EXTRA_DEBUG_INFORMATION is not set
 # CONFIG_KGDB is not set
 CONFIG_EARLY_PRINTK=y

i'm continuing the config-bisect.

	Ingo

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> * Ingo Molnar <mingo@elte.hu> wrote:
> 
> > PREEMPT wasnt the problem but CONFIG_DEBUG_STACKOVERFLOW (at least). 
> > There's some other debug option that seems incompatible too - i'm 
> > still trying to figure out which one.
> 
> narrowed it down to:

CONFIG_PROFILE_LIKELY it is, please disable it in your config, along 
with CONFIG_DEBUG_STACKOVERFLOW:

--- .config.good02	2006-05-31 00:28:35.000000000 +0200
+++ .config.bad01	2006-05-31 00:22:28.000000000 +0200
@@ -1,7 +1,7 @@
 #
 # Automatically generated make config: don't edit
 # Linux kernel version: 2.6.17-rc5-mm1-lockdep
-# Wed May 31 00:26:04 2006
+# Wed May 31 00:19:45 2006
 #
 CONFIG_X86_32=y
 CONFIG_GENERIC_TIME=y
@@ -1819,7 +1819,7 @@ CONFIG_STACK_UNWIND=y
 CONFIG_FORCED_INLINING=y
 CONFIG_DEBUG_SYNCHRO_TEST=y
 CONFIG_RCU_TORTURE_TEST=y
-# CONFIG_PROFILE_LIKELY is not set
+CONFIG_PROFILE_LIKELY=y
 # CONFIG_WANT_EXTRA_DEBUG_INFORMATION is not set
 # CONFIG_KGDB is not set
 CONFIG_EARLY_PRINTK=y

	Ingo

Re: 2.6.17-rc5-mm1

[Michal Piotrowski]

On 31/05/06, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Ingo Molnar <mingo@elte.hu> wrote:
>
> > * Ingo Molnar <mingo@elte.hu> wrote:
> >
> > > PREEMPT wasnt the problem but CONFIG_DEBUG_STACKOVERFLOW (at least).
> > > There's some other debug option that seems incompatible too - i'm
> > > still trying to figure out which one.
> >
> > narrowed it down to:
>
> CONFIG_PROFILE_LIKELY it is, please disable it in your config, along
> with CONFIG_DEBUG_STACKOVERFLOW:

Ok, thanks.

>
>         Ingo
>

Regards,
Michal

-- 
Michal K. K. Piotrowski
LTG - Linux Testers Group
(http://www.stardust.webpages.pl/ltg/wiki/)

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> CONFIG_PROFILE_LIKELY it is, please disable it in your config, along 
> with CONFIG_DEBUG_STACKOVERFLOW:

i've also uploaded an updated tracing patch to:

  http://redhat.com/~mingo/lockdep-patches/latency-tracing-lockdep.patch

which forces CONFIG_PROFILE_LIKELY off if LATENCY_TRACE is enabled.

	Ingo

Re: 2.6.17-rc5-mm1

[Michal Piotrowski]

On 31/05/06, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Michal Piotrowski <michal.k.k.piotrowski@gmail.com> wrote:
>
> > >  http://redhat.com/~mingo/lockdep-patches/latency-tracing-lockdep.patch
> > >
> > >just apply it ontop of your current tree and accept all the new .config
> > >options as the kernel suggests them to you.
> >
> > I can't boot with that patch. I even don't see "Uncompressing
> > Linux..." - machine reboots.
> > I have 2.6.17-rc5-mm1 +
> > genirq-cleanup-remove-irq_descp-fix.patch
> > lock-validator-irqtrace-support-non-x86-architectures.patch
> > lock-validator-special-locking-sb-s_umount-2-fix.patch
> > from hot fixes
> > +
> > Arjan's net/ipv4/igmp.c patch.
>
> could you try to 1) disable PREEMPT, 2) apply the -V2 rollup of all
> fixes so far to 2.6.17-rc5-mm1:
>
>  http://redhat.com/~mingo/lockdep-patches/lockdep-combo-2.6.17-rc5-mm1.patch

I'll try to reproduce that bug now... but here is new one :)

BUG: key f7155db0 not in .data!
(        modprobe-485  |#0): new 15286092 us user-latency.
stopped custom tracer.
BUG: warning at /usr/src/linux-mm/kernel/lockdep.c:1985/lockdep_init_map()
 [<c0104208>] show_trace+0x1b/0x20
 [<c01042e6>] dump_stack+0x1f/0x24
 [<c0136e26>] lockdep_init_map+0x65/0xb0
 [<c0134a62>] __mutex_init+0x46/0x50
 [<f98b72a3>] find_driver+0xb7/0x115 [snd_seq_device]
 [<f98b776f>] snd_seq_device_register_driver+0x42/0xeb [snd_seq_device]
 [<f887012d>] alsa_seq_oss_init+0x12d/0x158 [snd_seq_oss]
 [<c013fdad>] sys_init_module+0x96/0x1d4
 [<c02eb442>] sysenter_past_esp+0x63/0xa1
---------------------------
| preempt count: 00000000 ]
| 0-level deep critical section nesting:
----------------------------------------

Here is dmesg
http://www.stardust.webpages.pl/files/mm/2.6.17-rc5-mm1/mm-dmesg3

Here is new config (without some debugging options)
http://www.stardust.webpages.pl/files/mm/2.6.17-rc5-mm1/mm-config4

>
> ? I'll try your config meanwhile.
>
>         Ingo
>

Regards,
Michal

-- 
Michal K. K. Piotrowski
LTG - Linux Testers Group
(http://www.stardust.webpages.pl/ltg/wiki/)

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Michal Piotrowski <michal.k.k.piotrowski@gmail.com> wrote:

> I'll try to reproduce that bug now... but here is new one :)
> 
> BUG: key f7155db0 not in .data!
> (        modprobe-485  |#0): new 15286092 us user-latency.
> stopped custom tracer.
> BUG: warning at /usr/src/linux-mm/kernel/lockdep.c:1985/lockdep_init_map()

Arjan's sound patch is wrong: the key must not be in a dynamic variable!

Could you try the patch below? This uses the ID string as the key. (the 
ID string seems to be based on static kernel strings most of the time, 
so this might as well work)

	Ingo

Index: linux/sound/core/seq/seq_device.c
===================================================================
--- linux.orig/sound/core/seq/seq_device.c
+++ linux/sound/core/seq/seq_device.c
@@ -382,7 +382,7 @@ static struct ops_list * create_driver(c
 
 	/* set up driver entry */
 	strlcpy(ops->id, id, sizeof(ops->id));
-	mutex_init_key(&ops->reg_mutex, id, &ops->reg_mutex_key);
+	mutex_init_key(&ops->reg_mutex, id, (struct lockdep_type_key)id);
 	ops->driver = DRIVER_EMPTY;
 	INIT_LIST_HEAD(&ops->dev_list);
 	/* lock this instance */

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> Could you try the patch below? This uses the ID string as the key. 
> (the ID string seems to be based on static kernel strings most of the 
> time, so this might as well work)

that patch should be:

Index: linux/sound/core/seq/seq_device.c
===================================================================
--- linux.orig/sound/core/seq/seq_device.c
+++ linux/sound/core/seq/seq_device.c
@@ -74,8 +74,6 @@ struct ops_list {
 	struct mutex reg_mutex;
 
 	struct list_head list;	/* next driver */
-
-	struct lockdep_type_key reg_mutex_key;
 };
 
 
@@ -382,7 +380,7 @@ static struct ops_list * create_driver(c
 
 	/* set up driver entry */
 	strlcpy(ops->id, id, sizeof(ops->id));
-	mutex_init_key(&ops->reg_mutex, id, &ops->reg_mutex_key);
+	mutex_init_key(&ops->reg_mutex, id, (struct lockdep_type_key *)id);
 	ops->driver = DRIVER_EMPTY;
 	INIT_LIST_HEAD(&ops->dev_list);
 	/* lock this instance */

Re: 2.6.17-rc5-mm1

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> CONFIG_PROFILE_LIKELY it is, please disable it in your config, along 
> with CONFIG_DEBUG_STACKOVERFLOW:

the tracer fix for PROFILE_LIKELY is below. I have also uploaded an 
updated tracing patch to

  http://redhat.com/~mingo/lockdep-patches/latency-tracing-lockdep.patch

which allows the enabling of PROFILE_LIKELY && LATENCY_TRACING again. 
There's an updated combo patch too:

  http://redhat.com/~mingo/lockdep-patches/lockdep-combo-2.6.17-rc5-mm1.patch

for easy pickup of all current fixes against mm1 baseline.

	Ingo

Index: linux/lib/likely_prof.c
===================================================================
--- linux.orig/lib/likely_prof.c
+++ linux/lib/likely_prof.c
@@ -20,7 +20,7 @@
 
 static struct likeliness *likeliness_head;
 
-int do_check_likely(struct likeliness *likeliness, int ret)
+int notrace do_check_likely(struct likeliness *likeliness, int ret)
 {
 	static unsigned long likely_lock;