Re: BUG due to mm-instrumentation
Mathieu Desnoyers <[email protected]> Wed, 27 Feb 2008 11:18:54 -0500
| Newsgroups | gmane.linux.kernel.tracing |
|---|---|
| Message-ID | <20080227161853.GA10391@Krystal> |
* Mathieu Desnoyers ([email protected]) wrote: > * 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) > Here is the proper fix : Linux Kernel Markers - if check format Wrap __mark_check_format() into an if(0) to make sure that parameters such as trace_mark(mm_page_alloc, "order %u pfn %lu", order, page?page_to_pfn(page):0); (where page_to_pfn() has side-effects) won't generate code because of the __mark_check_format(). Thanks to Jan Kiszka for reporting this. Signed-off-by: Mathieu Desnoyers <[email protected]> CC: Jan Kiszka <[email protected]> --- include/linux/marker.h | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) Index: linux-2.6-lttng/include/linux/marker.h =================================================================== --- linux-2.6-lttng.orig/include/linux/marker.h 2008-02-27 11:08:50.000000000 -0500 +++ linux-2.6-lttng/include/linux/marker.h 2008-02-27 11:11:27.000000000 -0500 @@ -104,10 +104,16 @@ static inline void marker_update_probe_r #define MARK_NOARGS " " /* To be used for string format validity checking with gcc */ -static inline void __printf(1, 2) __mark_check_format(const char *fmt, ...) +static inline void __printf(1, 2) ___mark_check_format(const char *fmt, ...) { } +#define __mark_check_format(format, args...) \ + do { \ + if (0) \ + ___mark_check_format(format, ## args); \ + } while (0) + extern marker_probe_func __mark_empty_function; extern void marker_probe_cb(const struct marker *mdata, > 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 > _______________________________________________ > Ltt-dev mailing list > [email protected] > http://listserv.shafik.org/mailman/listinfo/ltt-dev > -- Mathieu Desnoyers Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68