[-next regression] lockdep? tracing? BUG: unable to handle kernelpaging request at
From: Eric Paris
Date: Tue Nov 03 2009 - 10:48:53 EST
Linux-next from Oct 30 did not have this problem. Linux next from
yesterday (and today) I always hit this on boot.
[ 7.989630] BUG: unable to handle kernel paging request at 00000000000160de
[ 7.990538] IP: [<ffffffff8123cdbf>] strcmp+0xf/0x30
[ 7.990538] PGD 77f7e067 PUD 77ff1067 PMD 0
[ 7.990538] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 7.990538] last sysfs file: /sys/devices/platform/i8042/serio0/input/input2/event2/uevent
[ 7.990538] CPU 0
[ 7.990538] Modules linked in: ata_piix(+)
[ 7.990538] Pid: 1024, comm: modprobe Not tainted 2.6.32-rc5-fanotify-next-20091102 #150
[ 7.990538] RIP: 0010:[<ffffffff8123cdbf>] [<ffffffff8123cdbf>] strcmp+0xf/0x30
[ 7.990538] RSP: 0018:ffff8800774d5c78 EFLAGS: 00010086
[ 7.990538] RAX: 0000000000000026 RBX: ffffffff820fbe60 RCX: 00000000000001cc
[ 7.990538] RDX: 0000000000000026 RSI: 00000000000160de RDI: ffffffff81790728
[ 7.990538] RBP: ffff8800774d5c78 R08: 0000000000000000 R09: ffffffff820fbe70
[ 7.990538] R10: 0000000000000001 R11: 0000000000000000 R12: ffffffff820c4320
[ 7.990538] R13: ffffffff820c4520 R14: ffffffff824b11c0 R15: ffffffff81a63570
[ 7.990538] FS: 00007f043db3a700(0000) GS:ffff880006200000(0000) knlGS:0000000000000000
[ 7.990538] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 7.990538] CR2: 00000000000160de CR3: 0000000077519000 CR4: 00000000000006f0
[ 7.990538] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 7.990538] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 7.990538] Process modprobe (pid: 1024, threadinfo ffff8800774d4000, task ffff88007769a440)
[ 7.990538] Stack:
[ 7.990538] ffff8800774d5cd8 ffffffff8108f9c7 ffff8800774d5ce8 ffffffff820fbe70
[ 7.990538] <0> ffff880000000000 0000000000000000 0000000000000002 0000000000000000
[ 7.990538] <0> 0000000000000002 ffff88007769a440 0000000000000002 ffffffff81a63570
[ 7.990538] Call Trace:
[ 7.990538] [<ffffffff8108f9c7>] register_lock_class+0x237/0x5b0
[ 7.990538] [<ffffffff810941c6>] __lock_acquire+0x76/0x6a0
[ 7.990538] [<ffffffff810948a1>] lock_acquire+0xb1/0x150
[ 7.990538] [<ffffffff810d9d25>] ? trace_module_notify+0x25/0x360
[ 7.990538] [<ffffffff814a29d8>] __mutex_lock_common+0x58/0x510
[ 7.990538] [<ffffffff810d9d25>] ? trace_module_notify+0x25/0x360
[ 7.990538] [<ffffffff81081035>] ? sched_clock_local+0x15/0x80
[ 7.990538] [<ffffffff8108115b>] ? sched_clock_cpu+0xbb/0x100
[ 7.990538] [<ffffffff810d9d25>] ? trace_module_notify+0x25/0x360
[ 7.990538] [<ffffffff814a2f6c>] mutex_lock_nested+0x3c/0x50
[ 7.990538] [<ffffffff810d9d25>] trace_module_notify+0x25/0x360
[ 7.990538] [<ffffffff810804d8>] ? __blocking_notifier_call_chain+0x48/0x90
[ 7.990538] [<ffffffff814a8725>] notifier_call_chain+0x45/0x80
[ 7.990538] [<ffffffff810804ee>] __blocking_notifier_call_chain+0x5e/0x90
[ 7.990538] [<ffffffff81080531>] blocking_notifier_call_chain+0x11/0x20
[ 7.990538] [<ffffffff810a2e01>] sys_init_module+0xb1/0x270
[ 7.990538] [<ffffffff8100af02>] system_call_fastpath+0x16/0x1b
[ 7.990538] Code: 83 c6 01 84 c0 88 01 74 0d 48 83 c1 01 48 83 ea 01 75 e9 c6 01 00 c9 48 89 f8 c3 90 55 48 89 e5 eb 04 48 83 c7 01 0f b6 17 89 d0 <2a> 06 48 83 c6 01 84 c0 75 04 84 d2 75 e9 c9 0f be c0 c3 0f 1f
[ 7.990538] RIP [<ffffffff8123cdbf>] strcmp+0xf/0x30
[ 7.990538] RSP <ffff8800774d5c78>
[ 7.990538] CR2: 00000000000160de
[ 7.990538] ---[ end trace c7a840a812150e3c ]---
[ 7.990538] note: modprobe[1024] exited with preempt_count 1
[ 8.270817] modprobe used greatest stack depth: 4376 bytes left
udevd-work[919]: '/sbin/modprobe -b pci:v00008086d00007010sv00001AF4sd00001100bc01sc01i80' unexpected exit with status 0x0009
udevd-work[919]: '/sbin/modprobe -b pci:v00008086d00007010sv00001AF4sd00001100bc01sc01i80' unexpected exit with status 0x0009
So it looks to me like we are locking the event_mutex (?for the first
time?) in trace_module_load. Eventually we get to __lock_acquire which
calls register_lock_class() which gets into count_matching_names() which
starts calling strcmp on lock_class->names.
static int count_matching_names(struct lock_class *new_class)
{
[snip]
if (class->name && !strcmp(class->name, new_class->name))
count = max(count, class->name_version);
So, strcmp from lib/string.c
int strcmp(const char *cs, const char *ct)
{
signed char __res;
while (1) {
if ((__res = *cs - *ct++) != 0 || !*cs++)
break;
}
return __res;
}
And it's assembly:
ffffffff8123cdb0 <strcmp>:
ffffffff8123cdb0: 55 push %rbp
ffffffff8123cdb1: 48 89 e5 mov %rsp,%rbp
ffffffff8123cdb4: eb 04 jmp ffffffff8123cdba <strcmp+0xa>
ffffffff8123cdb6: 48 83 c7 01 add $0x1,%rdi
ffffffff8123cdba: 0f b6 17 movzbl (%rdi),%edx
ffffffff8123cdbd: 89 d0 mov %edx,%eax
ffffffff8123cdbf: 2a 06 sub (%rsi),%al
ffffffff8123cdc1: 48 83 c6 01 add $0x1,%rsi
ffffffff8123cdc5: 84 c0 test %al,%al
ffffffff8123cdc7: 75 04 jne ffffffff8123cdcd <strcmp+0x1d>
ffffffff8123cdc9: 84 d2 test %dl,%dl
ffffffff8123cdcb: 75 e9 jne ffffffff8123cdb6 <strcmp+0x6>
ffffffff8123cdcd: c9 leaveq
ffffffff8123cdce: 0f be c0 movsbl %al,%eax
ffffffff8123cdd1: c3 retq
ffffffff8123cdd2: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
ffffffff8123cdd9: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
Looks to me like %rdi is the first argument to strcmp (cs) and %rsi is
the second argument (ct). %rsi has the crap value. This means that
new_class->name was != NULL, but wasn't valid. So it's something to do
with the event_lock....
I'm sure someone who knows this code better than I can explain how that
gets messed up.....
-Eric
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/