Re: BUG due to mm-instrumentation
Mathieu Desnoyers <[email protected]> Tue, 26 Feb 2008 09:48:55 -0500
| Newsgroups | gmane.linux.kernel.tracing |
|---|---|
| Message-ID | <20080226144855.GA12753@Krystal> |
* Jan Kiszka ([email protected]) wrote: > Mathieu Desnoyers wrote: > > * Jan Kiszka ([email protected]) wrote: > >> 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(...); > >> > > > > I would rather go for > > > > trace_mark(mm_page_alloc, "order %u pfn %lu", order, page?page_to_pfn(page):0); > > > > So it would be embedded within the disabled branch. > > So you want to record page==NULL? > Hrm, I think page == NULL is an error path, so you are right : it should be 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? > >> > > > > Hrm, this is not good. Can you try the following with your config ? > > > > #else /* !CONFIG_MARKERS */ > > #define __trace_mark(name, call_private, format, args...) \ > > if (0) \ > > __mark_check_format(format, ## args) > > > > It should still do the format string test, but completely compile out > > the code. > > > > (please try with a "wrong" format string to see if the compiler still > > complains) > > Yes, works perfectly! For test reference: > > #define trace_mark(name, format, args...) \ > if (0) __mark_check_format(format, ## args) > Actually, the "neat version" would be : #define trace_mark(name, format, args...) \ do { \ if (0) \ __mark_check_format(format, ## args); \ } while (0) Mathieu > #define __printf(a,b) __attribute__((format(printf,a,b))) > > static inline void __printf(1, 2) > __mark_check_format(const char *fmt, ...) > { > } > > extern int foo(int x); > > int bar(int y) > { > trace_mark(my_trace, "foo %p", foo(y)); > > return 0; > } > > > Thanks, > Jan > > -- > Siemens AG, Corporate Technology, CT SE 2 > Corporate Competence Center Embedded Linux > -- Mathieu Desnoyers Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68