From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mail-pb0-f48.google.com (mail-pb0-f48.google.com [209.85.160.48]) by kanga.kvack.org (Postfix) with ESMTP id 6E6F76B0037 for ; Wed, 28 May 2014 23:48:56 -0400 (EDT) Received: by mail-pb0-f48.google.com with SMTP id rr13so12228067pbb.7 for ; Wed, 28 May 2014 20:48:56 -0700 (PDT) Received: from lgeamrelo04.lge.com (lgeamrelo04.lge.com. [156.147.1.127]) by mx.google.com with ESMTP id xp1si26635293pab.44.2014.05.28.20.48.54 for ; Wed, 28 May 2014 20:48:55 -0700 (PDT) Date: Thu, 29 May 2014 12:49:26 +0900 From: Minchan Kim Subject: Re: [PATCH 1/2] ftrace: print stack usage right before Oops Message-ID: <20140529034925.GC10092@bbox> References: <1401260039-18189-1-git-send-email-minchan@kernel.org> <20140528230125.78e4a5c7@gandalf.local.home> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20140528230125.78e4a5c7@gandalf.local.home> Sender: owner-linux-mm@kvack.org List-ID: To: Steven Rostedt Cc: linux-kernel@vger.kernel.org, Andrew Morton , linux-mm@kvack.org, "H. Peter Anvin" , Ingo Molnar , Peter Zijlstra , Mel Gorman , Rik van Riel , Johannes Weiner , Hugh Dickins , rusty@rustcorp.com.au, mst@redhat.com, Dave Hansen On Wed, May 28, 2014 at 11:01:25PM -0400, Steven Rostedt wrote: > On Wed, 28 May 2014 15:53:58 +0900 > Minchan Kim wrote: > > > While I played with my own feature(ex, something on the way to reclaim), > > kernel went to oops easily. I guessed reason would be stack overflow > > and wanted to prove it. > > > > I found stack tracer which would be very useful for me but kernel went > > oops before my user program gather the information via > > "watch cat /sys/kernel/debug/tracing/stack_trace" so I couldn't get an > > stack usage of each functions. > > > > What I want was that emit the kernel stack usage when kernel goes oops. > > > > This patch records callstack of max stack usage into ftrace buffer > > right before Oops and print that information with ftrace_dump_on_oops. > > At last, I can find a culprit. :) > > > > The result is as follows. > > > > 111.402376] ------------[ cut here ]------------ > > [ 111.403077] kernel BUG at kernel/trace/trace_stack.c:177! > > [ 111.403831] invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC > > [ 111.404635] Dumping ftrace buffer: > > [ 111.404781] --------------------------------- > > [ 111.404781] <...>-15987 5d..2 111689526us : stack_trace_call: Depth Size Location (49 entries) > > [ 111.404781] ----- ---- -------- > > [ 111.404781] <...>-15987 5d..2 111689535us : stack_trace_call: 0) 7216 24 __change_page_attr_set_clr+0xe0/0xb50 > > [ 111.404781] <...>-15987 5d..2 111689535us : stack_trace_call: 1) 7192 392 kernel_map_pages+0x6c/0x120 > > [ 111.404781] <...>-15987 5d..2 111689535us : stack_trace_call: 2) 6800 256 get_page_from_freelist+0x489/0x920 > > [ 111.404781] <...>-15987 5d..2 111689536us : stack_trace_call: 3) 6544 352 __alloc_pages_nodemask+0x5e1/0xb20 > > [ 111.404781] <...>-15987 5d..2 111689536us : stack_trace_call: 4) 6192 8 alloc_pages_current+0x10f/0x1f0 > > [ 111.404781] <...>-15987 5d..2 111689537us : stack_trace_call: 5) 6184 168 new_slab+0x2c5/0x370 > > [ 111.404781] <...>-15987 5d..2 111689537us : stack_trace_call: 6) 6016 8 __slab_alloc+0x3a9/0x501 > > [ 111.404781] <...>-15987 5d..2 111689537us : stack_trace_call: 7) 6008 80 __kmalloc+0x1cb/0x200 > > [ 111.404781] <...>-15987 5d..2 111689538us : stack_trace_call: 8) 5928 376 vring_add_indirect+0x36/0x200 > > This is a different report than patch 2/2 has, but the numbers are the > same. Are you sure that you used the posted config to get these > crashes? I'm still having a hard time figuring out where these numbers > are coming from. :-/ It was a different report but same path to go bomb. Just wanted to show one of sample example. > > -- Steve > > > > [ 111.404781] <...>-15987 5d..2 111689538us : stack_trace_call: 9) 5552 144 virtqueue_add_sgs+0x2e2/0x320 > > [ 111.404781] <...>-15987 5d..2 111689538us : stack_trace_call: 10) 5408 288 __virtblk_add_req+0xda/0x1b0 > > [ 111.404781] <...>-15987 5d..2 111689538us : stack_trace_call: 11) 5120 96 virtio_queue_rq+0xd3/0x1d0 > > [ 111.404781] <...>-15987 5d..2 111689539us : stack_trace_call: 12) 5024 128 __blk_mq_run_hw_queue+0x1ef/0x440 > > [ 111.404781] <...>-15987 5d..2 111689539us : stack_trace_call: 13) 4896 16 blk_mq_run_hw_queue+0x35/0x40 > > [ 111.404781] <...>-15987 5d..2 111689539us : stack_trace_call: 14) 4880 96 blk_mq_insert_requests+0xdb/0x160 > > [ 111.404781] <...>-15987 5d..2 111689540us : stack_trace_call: 15) 4784 112 blk_mq_flush_plug_list+0x12b/0x140 > > [ 111.404781] <...>-15987 5d..2 111689540us : stack_trace_call: 16) 4672 112 blk_flush_plug_list+0xc7/0x220 > > [ 111.404781] <...>-15987 5d..2 111689540us : stack_trace_call: 17) 4560 64 io_schedule_timeout+0x88/0x100 > > [ 111.404781] <...>-15987 5d..2 111689541us : stack_trace_call: 18) 4496 128 mempool_alloc+0x145/0x170 > > [ 111.404781] <...>-15987 5d..2 111689541us : stack_trace_call: 19) 4368 96 bio_alloc_bioset+0x10b/0x1d0 > > [ 111.404781] <...>-15987 5d..2 111689541us : stack_trace_call: 20) 4272 48 get_swap_bio+0x30/0x90 > > [ 111.404781] <...>-15987 5d..2 111689542us : stack_trace_call: 21) 4224 160 __swap_writepage+0x150/0x230 > > [ 111.404781] <...>-15987 5d..2 111689542us : stack_trace_call: 22) 4064 32 swap_writepage+0x42/0x90 > > [ 111.404781] <...>-15987 5d..2 111689542us : stack_trace_call: 23) 4032 320 shrink_page_list+0x676/0xa80 > > [ 111.404781] <...>-15987 5d..2 111689543us : stack_trace_call: 24) 3712 208 shrink_inactive_list+0x262/0x4e0 > > [ 111.404781] <...>-15987 5d..2 111689543us : stack_trace_call: 25) 3504 304 shrink_lruvec+0x3e1/0x6a0 > > [ 111.404781] <...>-15987 5d..2 111689543us : stack_trace_call: 26) 3200 80 shrink_zone+0x3f/0x110 > > [ 111.404781] <...>-15987 5d..2 111689544us : stack_trace_call: 27) 3120 128 do_try_to_free_pages+0x156/0x4c0 > > [ 111.404781] <...>-15987 5d..2 111689544us : stack_trace_call: 28) 2992 208 try_to_free_pages+0xf7/0x1e0 > > [ 111.404781] <...>-15987 5d..2 111689544us : stack_trace_call: 29) 2784 352 __alloc_pages_nodemask+0x783/0xb20 > > [ 111.404781] <...>-15987 5d..2 111689545us : stack_trace_call: 30) 2432 8 alloc_pages_current+0x10f/0x1f0 > > [ 111.404781] <...>-15987 5d..2 111689545us : stack_trace_call: 31) 2424 168 new_slab+0x2c5/0x370 > > [ 111.404781] <...>-15987 5d..2 111689545us : stack_trace_call: 32) 2256 8 __slab_alloc+0x3a9/0x501 > > [ 111.404781] <...>-15987 5d..2 111689546us : stack_trace_call: 33) 2248 80 kmem_cache_alloc+0x1ac/0x1c0 > > [ 111.404781] <...>-15987 5d..2 111689546us : stack_trace_call: 34) 2168 296 mempool_alloc_slab+0x15/0x20 > > [ 111.404781] <...>-15987 5d..2 111689546us : stack_trace_call: 35) 1872 128 mempool_alloc+0x5e/0x170 > > [ 111.404781] <...>-15987 5d..2 111689547us : stack_trace_call: 36) 1744 96 bio_alloc_bioset+0x10b/0x1d0 > > [ 111.404781] <...>-15987 5d..2 111689547us : stack_trace_call: 37) 1648 48 mpage_alloc+0x38/0xa0 > > [ 111.404781] <...>-15987 5d..2 111689547us : stack_trace_call: 38) 1600 208 do_mpage_readpage+0x49b/0x5d0 > > [ 111.404781] <...>-15987 5d..2 111689548us : stack_trace_call: 39) 1392 224 mpage_readpages+0xcf/0x120 > > [ 111.404781] <...>-15987 5d..2 111689548us : stack_trace_call: 40) 1168 48 ext4_readpages+0x45/0x60 > > [ 111.404781] <...>-15987 5d..2 111689548us : stack_trace_call: 41) 1120 224 __do_page_cache_readahead+0x222/0x2d0 > > [ 111.404781] <...>-15987 5d..2 111689549us : stack_trace_call: 42) 896 16 ra_submit+0x21/0x30 > > [ 111.404781] <...>-15987 5d..2 111689549us : stack_trace_call: 43) 880 112 filemap_fault+0x2d7/0x4f0 > > [ 111.404781] <...>-15987 5d..2 111689549us : stack_trace_call: 44) 768 144 __do_fault+0x6d/0x4c0 > > [ 111.404781] <...>-15987 5d..2 111689550us : stack_trace_call: 45) 624 160 handle_mm_fault+0x1a6/0xaf0 > > [ 111.404781] <...>-15987 5d..2 111689550us : stack_trace_call: 46) 464 272 __do_page_fault+0x18a/0x590 > > [ 111.404781] <...>-15987 5d..2 111689550us : stack_trace_call: 47) 192 16 do_page_fault+0xc/0x10 > > [ 111.404781] <...>-15987 5d..2 111689551us : stack_trace_call: 48) 176 176 page_fault+0x22/0x30 > > [ 111.404781] --------------------------------- > > [ 111.404781] Modules linked in: > > [ 111.404781] CPU: 5 PID: 15987 Comm: cc1 Not tainted 3.14.0+ #162 > > [ 111.404781] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 > > [ 111.404781] task: ffff880008a4a0e0 ti: ffff88000002c000 task.ti: ffff88000002c000 > > [ 111.404781] RIP: 0010:[] [] stack_trace_call+0x37f/0x390 > > [ 111.404781] RSP: 0000:ffff88000002c2b0 EFLAGS: 00010092 > > [ 111.404781] RAX: ffff88000002c000 RBX: 0000000000000005 RCX: 0000000000000002 > > [ 111.404781] RDX: 0000000000000006 RSI: 0000000000000002 RDI: ffff88002780be00 > > [ 111.404781] RBP: ffff88000002c310 R08: 00000000000009e8 R09: ffffffffffffffff > > [ 111.404781] R10: ffff88000002dfd8 R11: 0000000000000001 R12: 000000000000f2e8 > > [ 111.404781] R13: 0000000000000005 R14: ffffffff82768dfc R15: 00000000000000f8 > > [ 111.404781] FS: 00002ae66a6e4640(0000) GS:ffff880027ca0000(0000) knlGS:0000000000000000 > > [ 111.404781] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > > [ 111.404781] CR2: 00002ba016c8e004 CR3: 00000000045b7000 CR4: 00000000000006e0 > > [ 111.404781] Stack: > > [ 111.404781] 0000000000000005 ffffffff81042410 0000000000000087 0000000000001c30 > > [ 111.404781] ffff88000002c000 00002ae66a6f3000 ffffffffffffe000 0000000000000002 > > [ 111.404781] ffff88000002c510 ffff880000d04000 ffff88000002c4b8 0000000000000002 > > [ 111.404781] Call Trace: > > [ 111.404781] [] ? __change_page_attr_set_clr+0xe0/0xb50 > > [ 111.404781] [] ftrace_call+0x5/0x2f > > [ 111.404781] [] ? dump_trace+0x177/0x2b0 > > [ 111.404781] [] ? _lookup_address_cpa.isra.3+0x5/0x40 > > [ 111.404781] [] ? _lookup_address_cpa.isra.3+0x5/0x40 > > [ 111.404781] [] ? __change_page_attr_set_clr+0xe0/0xb50 > > [ 111.404781] [] ? stack_trace_call+0x119/0x390 > > [ 111.404781] [] ? kernel_map_pages+0x6c/0x120 > > [ 111.404781] [] ? trace_hardirqs_off+0xd/0x10 > > [ 111.404781] [] ? get_page_from_freelist+0x3d1/0x920 > > [ 111.404781] [] kernel_map_pages+0x6c/0x120 > > [ 111.404781] [] get_page_from_freelist+0x489/0x920 > > [ 111.404781] [] __alloc_pages_nodemask+0x5e1/0xb20 > > [ 111.404781] [] alloc_pages_current+0x10f/0x1f0 > > [ 111.404781] [] ? new_slab+0x2c5/0x370 > > [ 111.404781] [] new_slab+0x2c5/0x370 > > [ 111.404781] [] __slab_alloc+0x3a9/0x501 > > [ 111.404781] [] ? __kmalloc+0x1cb/0x200 > > [ 111.404781] [] ? vring_add_indirect+0x36/0x200 > > [ 111.404781] [] ? vring_add_indirect+0x36/0x200 > > [ 111.404781] [] ? vring_add_indirect+0x36/0x200 > > [ 111.404781] [] __kmalloc+0x1cb/0x200 > > [ 111.404781] [] ? vring_add_indirect+0x200/0x200 > > [ 111.404781] [] vring_add_indirect+0x36/0x200 > > [ 111.404781] [] virtqueue_add_sgs+0x2e2/0x320 > > [ 111.404781] [] __virtblk_add_req+0xda/0x1b0 > > [ 111.404781] [] ? __delay+0x5/0x20 > > [ 111.404781] [] virtio_queue_rq+0xd3/0x1d0 > > [ 111.404781] [] __blk_mq_run_hw_queue+0x1ef/0x440 > > [ 111.404781] [] blk_mq_run_hw_queue+0x35/0x40 > > [ 111.404781] [] blk_mq_insert_requests+0xdb/0x160 > > [ 111.404781] [] blk_mq_flush_plug_list+0x12b/0x140 > > [ 111.404781] [] ? ktime_get_ts+0x125/0x150 > > [ 111.404781] [] blk_flush_plug_list+0xc7/0x220 > > [ 111.404781] [] ? _raw_spin_unlock_irqrestore+0x3f/0x70 > > [ 111.404781] [] io_schedule_timeout+0x88/0x100 > > [ 111.404781] [] ? io_schedule_timeout+0x5/0x100 > > [ 111.404781] [] mempool_alloc+0x145/0x170 > > [ 111.404781] [] ? __init_waitqueue_head+0x60/0x60 > > [ 111.404781] [] bio_alloc_bioset+0x10b/0x1d0 > > [ 111.404781] [] ? end_swap_bio_read+0xc0/0xc0 > > [ 111.404781] [] ? end_swap_bio_read+0xc0/0xc0 > > [ 111.404781] [] get_swap_bio+0x30/0x90 > > [ 111.404781] [] ? end_swap_bio_read+0xc0/0xc0 > > [ 111.404781] [] __swap_writepage+0x150/0x230 > > [ 111.404781] [] ? end_swap_bio_read+0xc0/0xc0 > > [ 111.404781] [] ? __swap_writepage+0x5/0x230 > > [ 111.404781] [] swap_writepage+0x42/0x90 > > [ 111.404781] [] shrink_page_list+0x676/0xa80 > > [ 111.404781] [] ? ftrace_call+0x5/0x2f > > [ 111.404781] [] shrink_inactive_list+0x262/0x4e0 > > [ 111.404781] [] shrink_lruvec+0x3e1/0x6a0 > > [ 111.404781] [] shrink_zone+0x3f/0x110 > > [ 111.404781] [] ? ftrace_call+0x5/0x2f > > [ 111.404781] [] do_try_to_free_pages+0x156/0x4c0 > > [ 111.404781] [] try_to_free_pages+0xf7/0x1e0 > > [ 111.404781] [] __alloc_pages_nodemask+0x783/0xb20 > > [ 111.404781] [] alloc_pages_current+0x10f/0x1f0 > > [ 111.404781] [] ? new_slab+0x2c5/0x370 > > [ 111.404781] [] new_slab+0x2c5/0x370 > > [ 111.404781] [] __slab_alloc+0x3a9/0x501 > > [ 111.404781] [] ? kmem_cache_alloc+0x1ac/0x1c0 > > [ 111.404781] [] ? mempool_alloc_slab+0x15/0x20 > > [ 111.404781] [] ? mempool_alloc_slab+0x15/0x20 > > [ 111.404781] [] kmem_cache_alloc+0x1ac/0x1c0 > > [ 111.404781] [] ? mempool_alloc_slab+0x15/0x20 > > [ 111.404781] [] mempool_alloc_slab+0x15/0x20 > > [ 111.404781] [] mempool_alloc+0x5e/0x170 > > [ 111.404781] [] bio_alloc_bioset+0x10b/0x1d0 > > [ 111.404781] [] mpage_alloc+0x38/0xa0 > > [ 111.404781] [] do_mpage_readpage+0x49b/0x5d0 > > [ 111.404781] [] ? ext4_get_block_write+0x20/0x20 > > [ 111.404781] [] mpage_readpages+0xcf/0x120 > > [ 111.404781] [] ? ext4_get_block_write+0x20/0x20 > > [ 111.404781] [] ? ext4_get_block_write+0x20/0x20 > > [ 111.404781] [] ? ftrace_call+0x5/0x2f > > [ 111.404781] [] ? ftrace_call+0x5/0x2f > > [ 111.404781] [] ? __do_page_cache_readahead+0xc1/0x2d0 > > [ 111.404781] [] ? ext4_get_block_write+0x20/0x20 > > [ 111.404781] [] ext4_readpages+0x45/0x60 > > [ 111.404781] [] __do_page_cache_readahead+0x222/0x2d0 > > [ 111.404781] [] ? __do_page_cache_readahead+0xc1/0x2d0 > > [ 111.404781] [] ra_submit+0x21/0x30 > > [ 111.404781] [] filemap_fault+0x2d7/0x4f0 > > [ 111.404781] [] __do_fault+0x6d/0x4c0 > > [ 111.404781] [] handle_mm_fault+0x1a6/0xaf0 > > [ 111.404781] [] __do_page_fault+0x18a/0x590 > > [ 111.404781] [] ? ftrace_call+0x5/0x2f > > [ 111.404781] [] ? finish_task_switch+0x7c/0x120 > > [ 111.404781] [] ? finish_task_switch+0x3f/0x120 > > [ 111.404781] [] do_page_fault+0xc/0x10 > > [ 111.404781] [] page_fault+0x22/0x30 > > > > Signed-off-by: Minchan Kim > > --- > > kernel/trace/trace_stack.c | 32 ++++++++++++++++++++++++++++++-- > > 1 file changed, 30 insertions(+), 2 deletions(-) > > > > diff --git a/kernel/trace/trace_stack.c b/kernel/trace/trace_stack.c > > index 5aa9a5b9b6e2..5eb88e60bc5e 100644 > > --- a/kernel/trace/trace_stack.c > > +++ b/kernel/trace/trace_stack.c > > @@ -51,6 +51,30 @@ static DEFINE_MUTEX(stack_sysctl_mutex); > > int stack_tracer_enabled; > > static int last_stack_tracer_enabled; > > > > +static inline void print_max_stack(void) > > +{ > > + long i; > > + int size; > > + > > + trace_printk(" Depth Size Location" > > + " (%d entries)\n" > > + " ----- ---- --------\n", > > + max_stack_trace.nr_entries - 1); > > + > > + for (i = 0; i < max_stack_trace.nr_entries; i++) { > > + if (stack_dump_trace[i] == ULONG_MAX) > > + break; > > + if (i+1 == max_stack_trace.nr_entries || > > + stack_dump_trace[i+1] == ULONG_MAX) > > + size = stack_dump_index[i]; > > + else > > + size = stack_dump_index[i] - stack_dump_index[i+1]; > > + > > + trace_printk("%3ld) %8d %5d %pS\n", i, stack_dump_index[i], > > + size, (void *)stack_dump_trace[i]); > > + } > > +} > > + > > static inline void > > check_stack(unsigned long ip, unsigned long *stack) > > { > > @@ -149,8 +173,12 @@ check_stack(unsigned long ip, unsigned long *stack) > > i++; > > } > > > > - BUG_ON(current != &init_task && > > - *(end_of_stack(current)) != STACK_END_MAGIC); > > + if ((current != &init_task && > > + *(end_of_stack(current)) != STACK_END_MAGIC)) { > > + print_max_stack(); > > + BUG(); > > + } > > + > > out: > > arch_spin_unlock(&max_stack_lock); > > local_irq_restore(flags); > > -- > To unsubscribe, send a message with 'unsubscribe linux-mm' in > the body to majordomo@kvack.org. For more info on Linux MM, > see: http://www.linux-mm.org/ . > Don't email: email@kvack.org -- Kind regards, Minchan Kim -- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to majordomo@kvack.org. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: email@kvack.org