Message-ID: <20110208101730.GB7020@liondog.tnic>
Date:	Tue, 8 Feb 2011 11:17:30 +0100
From:	Borislav Petkov <bp@...en8.de>
To:	Linus Torvalds <torvalds@...ux-foundation.org>
Cc:	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
	x86@...nel.org
Subject: lockdep: possible reason: unannotated irqs-off. (was: Re: Linux
 2.6.38-rc4)

On Mon, Feb 07, 2011 at 04:23:37PM -0800, Linus Torvalds wrote:
> No travel or cyclone-dodging this time, so as promised, the -rc's are
> now back to the usual weekly schedule.
> 
> There's nothing much that stands out here. Some arch updates (arm and
> powerpc), the usual driver updates: dri (radeon/i915), network cards,
> sound, media, scisi, some filesystem updates (cifs, btrfs), and some
> random stuff to round it all out (networking, watchpoints,
> tracepoints, etc).
> 
> Pretty small, all in all. I'd obviously prefer it to be even smaller,
> and I actually dropped a pull request or two, but for being -rc4 this
> is by no means horrible. As long as it keeps shrinking, I'll be happy.

So, I'm getting the warning below early in the boot process. And yes, I
didn't have it on -rc3. 2.6.38-rc4-00001-g1e554e3-dirty means a debug
diff ontop of -rc4 which shouldn't have anything to do with this splat
since all it does is a couple of printk's due to -rc3 not suspending to
disk properly in some cases.

Now, I'm not going to even pretend to understand the code but here's
what I can read out, you tell me whether it makes sense.

spawn_ksoftirqd() is one of the early initcalls that gets called and
it's notifier callback does kthread_bind() and you can follow in the
backtrace below that this thing comes down to del_timer_sync() which
does the lockdep annotation. Now, problem as I see it, is that hardirqs
were disabled when we were called although it doesn't say so in the
irqtrace events dump after the calltrace: "hardirqs last enabled at
(999)" and our irq event stamp is 1000.

There are actually at least three del_timer_sync()'s inflight so the
problem could be there somewhere, I dunno.

So, is it a wrong lockdep annotation or is it a real problem? I've
attached dmesg and config.

Thanks.

[    0.023211] Setting APIC routing to flat
[    0.024378] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.034634] CPU0: AMD Phenom(tm) II X4 940 Processor stepping 02
[    0.034997] calling  trace_init_flags_sys_exit+0x0/0x12 @ 1
[    0.034997] initcall trace_init_flags_sys_exit+0x0/0x12 returned 0 after 0 usecs
[    0.034997] calling  trace_init_flags_sys_enter+0x0/0x12 @ 1
[    0.034997] initcall trace_init_flags_sys_enter+0x0/0x12 returned 0 after 0 usecs
[    0.034997] calling  init_hw_perf_events+0x0/0xbfa @ 1
[    0.034997] Performance Events: AMD PMU driver.
[    0.035003] ... version:                0
[    0.035140] ... bit width:              48
[    0.035278] ... generic registers:      4
[    0.035415] ... value mask:             0000ffffffffffff
[    0.035554] ... max period:             00007fffffffffff
[    0.035692] ... fixed-purpose events:   0
[    0.035829] ... event mask:             000000000000000f
[    0.036035] initcall init_hw_perf_events+0x0/0xbfa returned 0 after 1952 usecs
[    0.036276] calling  migration_init+0x0/0x6d @ 1
[    0.036418] initcall migration_init+0x0/0x6d returned 0 after 0 usecs
[    0.036558] calling  spawn_ksoftirqd+0x0/0x52 @ 1
[    0.036786] System has AMD C1E enabled
[    0.036937] Switch to broadcast mode on CPU0
[    0.037063] ------------[ cut here ]------------
[    0.037210] WARNING: at kernel/lockdep.c:3151 check_flags+0x63/0x179()
[    0.037349] Hardware name: System Product Name
[    0.037487] Modules linked in:
[    0.037658] Pid: 1, comm: swapper Not tainted 2.6.38-rc4-00001-g1e554e3-dirty #11
[    0.037898] Call Trace:
[    0.037997]  [<ffffffff81039906>] ? warn_slowpath_common+0x85/0x9d
[    0.037997]  [<ffffffff81048251>] ? del_timer_sync+0x0/0xa0
[    0.037997]  [<ffffffff81039938>] ? warn_slowpath_null+0x1a/0x1c
[    0.037997]  [<ffffffff81066f1c>] ? check_flags+0x63/0x179
[    0.037997]  [<ffffffff8106c664>] ? lock_acquire+0x4c/0x192
[    0.037997]  [<ffffffff81048273>] ? del_timer_sync+0x22/0xa0
[    0.037997]  [<ffffffff81048292>] ? del_timer_sync+0x41/0xa0
[    0.037997]  [<ffffffff81048251>] ? del_timer_sync+0x0/0xa0
[    0.037997]  [<ffffffff81439969>] ? schedule_timeout+0x35c/0x3bb
[    0.037997]  [<ffffffff81047e9e>] ? process_timeout+0x0/0x10
[    0.037997]  [<ffffffff814399e6>] ? schedule_timeout_uninterruptible+0x1e/0x20
[    0.037997]  [<ffffffff81036c44>] ? wait_task_inactive+0x181/0x1cd
[    0.037997]  [<ffffffff810584bc>] ? kthread_bind+0x1c/0x6d
[    0.037997]  [<ffffffff81436007>] ? cpu_callback+0x87/0x3e8
[    0.037997]  [<ffffffff81931ed1>] ? spawn_ksoftirqd+0x0/0x52
[    0.037997]  [<ffffffff81931ef5>] ? spawn_ksoftirqd+0x24/0x52
[    0.037997]  [<ffffffff810001f2>] ? do_one_initcall+0x57/0x133
[    0.037997]  [<ffffffff8192258a>] ? kernel_init+0x67/0x1c1
[    0.037997]  [<ffffffff81002f94>] ? kernel_thread_helper+0x4/0x10
[    0.037997]  [<ffffffff81032a78>] ? finish_task_switch+0x80/0xec
[    0.037997]  [<ffffffff8143c499>] ? _raw_spin_unlock_irq+0x3b/0x58
[    0.037997]  [<ffffffff8143cb44>] ? restore_args+0x0/0x30
[    0.037997]  [<ffffffff81922523>] ? kernel_init+0x0/0x1c1
[    0.037997]  [<ffffffff81002f90>] ? kernel_thread_helper+0x0/0x10
[    0.037997] ---[ end trace 4eaa2a86a8e2da22 ]---
[    0.037997] possible reason: unannotated irqs-off.
[    0.037997] irq event stamp: 1000
[    0.037997] hardirqs last  enabled at (999): [<ffffffff8143c48e>] _raw_spin_unlock_irq+0x30/0x58
[    0.037997] hardirqs last disabled at (998): [<ffffffff8143ba38>] _raw_spin_lock_irq+0x19/0x79
[    0.037997] softirqs last  enabled at (908): [<ffffffff81040864>] __do_softirq+0x2a0/0x2f0
[    0.037997] softirqs last disabled at (1000): [<ffffffff81048273>] del_timer_sync+0x22/0xa0
[    0.038006] initcall spawn_ksoftirqd+0x0/0x52 returned 0 after 1952 usecs
[    0.039000] calling  init_workqueues+0x0/0x34d @ 1
[    0.040114] initcall init_workqueues+0x0/0x34d returned 0 after 976 usecs
[    0.041001] calling  init_call_single_data+0x0/0xaa @ 1
[    0.041143] initcall init_call_single_data+0x0/0xaa returned 0 after 0 usecs


-- 
Regards/Gruss,
    Boris.

View attachment "dmesg.log" of type "text/plain" (104949 bytes)

View attachment "config" of type "text/plain" (62812 bytes)

Powered by blists - more mailing lists