[-next regression] lockdep? tracing? BUG: unable to handle kernel paging request at

[Eric Paris <eparis@redhat.com>]

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