BUG due to mm-instrumentation

Hi,

I just ran into an interesting BUG on an LTT-patched (Xenomai) kernel,
but with markers & LTT disabled:

Unable to handle kernel NULL pointer dereference at 0000000000000000 RIP:
 [<ffffffff802c4c75>] page_to_pfn+0x9/0x3d
PGD 2082f067 PUD 58caf067 PMD 0
Oops: 0000 [1] SMP
CPU 2
Modules linked in: scsi_mod libata ahci ata_piix fan jbd mbcache ext3 raid0 edd sd_mod raid1 xor async_tx async_memcpy async_xor raid456 sg cdrom button i2c_core edac_core rtc_lib e1000 pci_hotplr
Pid: 1592, comm: ld Not tainted 2.6.24.2-xeno_64 #12
RIP: 0010:[<ffffffff802c4c75>]  [<ffffffff802c4c75>] page_to_pfn+0x9/0x3d
RSP: 0018:ffff810058c21868  EFLAGS: 00010246
RAX: 0000000000000000 RBX: 0000000000041250 RCX: ffff810000011968
RDX: 0000000000000000 RSI: ffff810000011950 RDI: 0000000000000000
RBP: ffff810058c21868 R08: 0000000000000000 R09: 00000000000007d9
R10: 0000000000000000 R11: 0000000000000001 R12: 00000000000c1250
R13: ffff810000011950 R14: 0000000000000000 R15: 0000000000000000
FS:  00002b9d20c6fb00(0000) GS:ffff81007df79340(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000000 CR3: 000000007bd25000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process ld (pid: 1592, threadinfo ffff810058c20000, task ffff81007c161040)
Stack:  ffff810058c218f8 ffffffff802c7909 0000000000000001 0000100000000000
 0000000000001000 ffff810000011958 000412003dc403b4 00000010000e1250
 0000000000000000 ffff81007c161040 0000000003163370 ffff81006288e748
Call Trace:
 [<ffffffff802c7909>] __alloc_pages+0x355/0x368
 [<ffffffff802e5e54>] kmem_getpages+0xa9/0x161
 [<ffffffff802e739d>] cache_grow+0xb3/0x27c
 [<ffffffff802e7a6e>] cache_alloc_refill+0x1b0/0x201
 [<ffffffff802e7d08>] kmem_cache_alloc+0xda/0x136
 [<ffffffff880733e5>] :jbd:journal_add_journal_head+0x35/0x167
 [<ffffffff8806f938>] :jbd:journal_dirty_data+0x3e/0x1da
 [<ffffffff8808943d>] :ext3:ext3_journal_dirty_data+0x1d/0x46
 [<ffffffff88088718>] :ext3:walk_page_buffers+0x70/0x97
 [<ffffffff88089420>] :ext3:ext3_journal_dirty_data+0x0/0x46
 [<ffffffff8808b1ff>] :ext3:ext3_ordered_write_end+0x77/0xed
 [<ffffffff802c2916>] generic_file_buffered_write+0x1dc/0x6aa
 [<ffffffff8023d34e>] current_fs_time+0x27/0x2e
 [<ffffffff8809874c>] :ext3:ext3_xattr_security_get+0x26/0x28
 [<ffffffff802c3147>] __generic_file_aio_write_nolock+0x363/0x397
 [<ffffffff802c31e7>] generic_file_aio_write+0x6c/0xc8
 [<ffffffff8808745b>] :ext3:ext3_file_write+0x23/0xa3
 [<ffffffff802ebed1>] do_sync_write+0xf0/0x137
 [<ffffffff80366872>] __up_read+0x94/0x9c
 [<ffffffff8024d3b9>] autoremove_wake_function+0x0/0x3d
 [<ffffffff802d597e>] vma_merge+0x143/0x1f3
 [<ffffffff80272fae>] ipipe_check_context+0xc/0xf6
 [<ffffffff80272fae>] ipipe_check_context+0xc/0xf6
 [<ffffffff8047c5c3>] cond_resched+0x9/0x3e
 [<ffffffff802ec701>] vfs_write+0xcc/0x155
 [<ffffffff802eccae>] sys_write+0x4c/0x75
 [<ffffffff8020c1f2>] system_call+0x92/0x97


Code: 48 8b 07 48 c1 e8 3a 48 8b 14 c5 d0 28 5e 80 48 b8 b7 6d db
RIP  [<ffffffff802c4c75>] page_to_pfn+0x9/0x3d
 RSP <ffff810058c21868>
CR2: 0000000000000000
---[ end trace 6f19d1f5ca1f738f ]---


This problem obviously starts with

struct page * fastcall
__alloc_pages(gfp_t gfp_mask, unsigned int order,
                struct zonelist *zonelist)
{

[...]

nopage:
        if (!(gfp_mask & __GFP_NOWARN) && printk_ratelimit()) {
                printk(KERN_WARNING "%s: page allocation failure."
                        " order:%d, mode:0x%x\n",
                        p->comm, order, gfp_mask);
                dump_stack();
                show_mem();
        }
got_pg:
        trace_mark(mm_page_alloc, "order %u pfn %lu", order, page_to_pfn(page));
        return page;
}


So we can come along trace_mark with page==NULL. But this is something
page_to_pfn dislikes (with CONFIG_DISCONTIGMEM at least), and I also
don't think mm_page_alloc is supposed to trace unsuccessful allocations.
Shouldn't we put

if (page)
	trace_mark(...);

here?


The second point is that I didn't want tracing for this build at all.
But looking at the disassembly,

ffffffff802c78f1:       e8 ba 15 f7 ff          callq  ffffffff80238eb0 <printk>
ffffffff802c78f6:       e8 ac 67 f4 ff          callq  ffffffff8020e0a7 <dump_stack>
ffffffff802c78fb:       e8 ef d1 f5 ff          callq  ffffffff80224aef <show_mem>
ffffffff802c7900:       48 8b 7d b0             mov    -0x50(%rbp),%rdi
ffffffff802c7904:       e8 63 d3 ff ff          callq  ffffffff802c4c6c <page_to_pfn>
ffffffff802c7909:       48 8b 45 b0             mov    -0x50(%rbp),%rax
ffffffff802c790d:       48 83 c4 58             add    $0x58,%rsp
ffffffff802c7911:       5b                      pop    %rbx
ffffffff802c7912:       41 5c                   pop    %r12
ffffffff802c7914:       41 5d                   pop    %r13
ffffffff802c7916:       41 5e                   pop    %r14
ffffffff802c7918:       41 5f                   pop    %r15
ffffffff802c791a:       c9                      leaveq
ffffffff802c791b:       c3                      retq

we see a useless page_to_pfn call. Is this is due to
__mark_check_format, trying to match format against arguments even
without CONFIG_MARKERS? Compiler issue?

Jan

-- 
Siemens AG, Corporate Technology, CT SE 2
Corporate Competence Center Embedded Linux