Re: [PATCH 1/2] ftrace: print stack usage right before Oops
From: Minchan Kim
Date: Wed May 28 2014 - 23:49:01 EST
On Wed, May 28, 2014 at 11:01:25PM -0400, Steven Rostedt wrote:
> On Wed, 28 May 2014 15:53:58 +0900
> Minchan Kim <minchan@xxxxxxxxxx> 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:[<ffffffff8112340f>] [<ffffffff8112340f>] 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] [<ffffffff81042410>] ? __change_page_attr_set_clr+0xe0/0xb50
> > [ 111.404781] [<ffffffff816efdff>] ftrace_call+0x5/0x2f
> > [ 111.404781] [<ffffffff81004ba7>] ? dump_trace+0x177/0x2b0
> > [ 111.404781] [<ffffffff81041a65>] ? _lookup_address_cpa.isra.3+0x5/0x40
> > [ 111.404781] [<ffffffff81041a65>] ? _lookup_address_cpa.isra.3+0x5/0x40
> > [ 111.404781] [<ffffffff81042410>] ? __change_page_attr_set_clr+0xe0/0xb50
> > [ 111.404781] [<ffffffff811231a9>] ? stack_trace_call+0x119/0x390
> > [ 111.404781] [<ffffffff81043eac>] ? kernel_map_pages+0x6c/0x120
> > [ 111.404781] [<ffffffff810a22dd>] ? trace_hardirqs_off+0xd/0x10
> > [ 111.404781] [<ffffffff81150131>] ? get_page_from_freelist+0x3d1/0x920
> > [ 111.404781] [<ffffffff81043eac>] kernel_map_pages+0x6c/0x120
> > [ 111.404781] [<ffffffff811501e9>] get_page_from_freelist+0x489/0x920
> > [ 111.404781] [<ffffffff81150c61>] __alloc_pages_nodemask+0x5e1/0xb20
> > [ 111.404781] [<ffffffff8119188f>] alloc_pages_current+0x10f/0x1f0
> > [ 111.404781] [<ffffffff8119ac35>] ? new_slab+0x2c5/0x370
> > [ 111.404781] [<ffffffff8119ac35>] new_slab+0x2c5/0x370
> > [ 111.404781] [<ffffffff816dbfc9>] __slab_alloc+0x3a9/0x501
> > [ 111.404781] [<ffffffff8119beeb>] ? __kmalloc+0x1cb/0x200
> > [ 111.404781] [<ffffffff8141eba6>] ? vring_add_indirect+0x36/0x200
> > [ 111.404781] [<ffffffff8141eba6>] ? vring_add_indirect+0x36/0x200
> > [ 111.404781] [<ffffffff8141eba6>] ? vring_add_indirect+0x36/0x200
> > [ 111.404781] [<ffffffff8119beeb>] __kmalloc+0x1cb/0x200
> > [ 111.404781] [<ffffffff8141ed70>] ? vring_add_indirect+0x200/0x200
> > [ 111.404781] [<ffffffff8141eba6>] vring_add_indirect+0x36/0x200
> > [ 111.404781] [<ffffffff8141f362>] virtqueue_add_sgs+0x2e2/0x320
> > [ 111.404781] [<ffffffff8148f2ba>] __virtblk_add_req+0xda/0x1b0
> > [ 111.404781] [<ffffffff813780c5>] ? __delay+0x5/0x20
> > [ 111.404781] [<ffffffff8148f463>] virtio_queue_rq+0xd3/0x1d0
> > [ 111.404781] [<ffffffff8134b96f>] __blk_mq_run_hw_queue+0x1ef/0x440
> > [ 111.404781] [<ffffffff8134c035>] blk_mq_run_hw_queue+0x35/0x40
> > [ 111.404781] [<ffffffff8134c71b>] blk_mq_insert_requests+0xdb/0x160
> > [ 111.404781] [<ffffffff8134cdbb>] blk_mq_flush_plug_list+0x12b/0x140
> > [ 111.404781] [<ffffffff810c5ab5>] ? ktime_get_ts+0x125/0x150
> > [ 111.404781] [<ffffffff81343197>] blk_flush_plug_list+0xc7/0x220
> > [ 111.404781] [<ffffffff816e70bf>] ? _raw_spin_unlock_irqrestore+0x3f/0x70
> > [ 111.404781] [<ffffffff816e26b8>] io_schedule_timeout+0x88/0x100
> > [ 111.404781] [<ffffffff816e2635>] ? io_schedule_timeout+0x5/0x100
> > [ 111.404781] [<ffffffff81149465>] mempool_alloc+0x145/0x170
> > [ 111.404781] [<ffffffff8109baf0>] ? __init_waitqueue_head+0x60/0x60
> > [ 111.404781] [<ffffffff811e33cb>] bio_alloc_bioset+0x10b/0x1d0
> > [ 111.404781] [<ffffffff81184280>] ? end_swap_bio_read+0xc0/0xc0
> > [ 111.404781] [<ffffffff81184280>] ? end_swap_bio_read+0xc0/0xc0
> > [ 111.404781] [<ffffffff81184160>] get_swap_bio+0x30/0x90
> > [ 111.404781] [<ffffffff81184280>] ? end_swap_bio_read+0xc0/0xc0
> > [ 111.404781] [<ffffffff811846b0>] __swap_writepage+0x150/0x230
> > [ 111.404781] [<ffffffff81184280>] ? end_swap_bio_read+0xc0/0xc0
> > [ 111.404781] [<ffffffff81184565>] ? __swap_writepage+0x5/0x230
> > [ 111.404781] [<ffffffff811847d2>] swap_writepage+0x42/0x90
> > [ 111.404781] [<ffffffff8115aee6>] shrink_page_list+0x676/0xa80
> > [ 111.404781] [<ffffffff816efdff>] ? ftrace_call+0x5/0x2f
> > [ 111.404781] [<ffffffff8115b8c2>] shrink_inactive_list+0x262/0x4e0
> > [ 111.404781] [<ffffffff8115c211>] shrink_lruvec+0x3e1/0x6a0
> > [ 111.404781] [<ffffffff8115c50f>] shrink_zone+0x3f/0x110
> > [ 111.404781] [<ffffffff816efdff>] ? ftrace_call+0x5/0x2f
> > [ 111.404781] [<ffffffff8115ca36>] do_try_to_free_pages+0x156/0x4c0
> > [ 111.404781] [<ffffffff8115cf97>] try_to_free_pages+0xf7/0x1e0
> > [ 111.404781] [<ffffffff81150e03>] __alloc_pages_nodemask+0x783/0xb20
> > [ 111.404781] [<ffffffff8119188f>] alloc_pages_current+0x10f/0x1f0
> > [ 111.404781] [<ffffffff8119ac35>] ? new_slab+0x2c5/0x370
> > [ 111.404781] [<ffffffff8119ac35>] new_slab+0x2c5/0x370
> > [ 111.404781] [<ffffffff816dbfc9>] __slab_alloc+0x3a9/0x501
> > [ 111.404781] [<ffffffff8119d95c>] ? kmem_cache_alloc+0x1ac/0x1c0
> > [ 111.404781] [<ffffffff81149025>] ? mempool_alloc_slab+0x15/0x20
> > [ 111.404781] [<ffffffff81149025>] ? mempool_alloc_slab+0x15/0x20
> > [ 111.404781] [<ffffffff8119d95c>] kmem_cache_alloc+0x1ac/0x1c0
> > [ 111.404781] [<ffffffff81149025>] ? mempool_alloc_slab+0x15/0x20
> > [ 111.404781] [<ffffffff81149025>] mempool_alloc_slab+0x15/0x20
> > [ 111.404781] [<ffffffff8114937e>] mempool_alloc+0x5e/0x170
> > [ 111.404781] [<ffffffff811e33cb>] bio_alloc_bioset+0x10b/0x1d0
> > [ 111.404781] [<ffffffff811ea618>] mpage_alloc+0x38/0xa0
> > [ 111.404781] [<ffffffff811eb2eb>] do_mpage_readpage+0x49b/0x5d0
> > [ 111.404781] [<ffffffff812512f0>] ? ext4_get_block_write+0x20/0x20
> > [ 111.404781] [<ffffffff811eb55f>] mpage_readpages+0xcf/0x120
> > [ 111.404781] [<ffffffff812512f0>] ? ext4_get_block_write+0x20/0x20
> > [ 111.404781] [<ffffffff812512f0>] ? ext4_get_block_write+0x20/0x20
> > [ 111.404781] [<ffffffff816efdff>] ? ftrace_call+0x5/0x2f
> > [ 111.404781] [<ffffffff816efdff>] ? ftrace_call+0x5/0x2f
> > [ 111.404781] [<ffffffff81153e21>] ? __do_page_cache_readahead+0xc1/0x2d0
> > [ 111.404781] [<ffffffff812512f0>] ? ext4_get_block_write+0x20/0x20
> > [ 111.404781] [<ffffffff8124d045>] ext4_readpages+0x45/0x60
> > [ 111.404781] [<ffffffff81153f82>] __do_page_cache_readahead+0x222/0x2d0
> > [ 111.404781] [<ffffffff81153e21>] ? __do_page_cache_readahead+0xc1/0x2d0
> > [ 111.404781] [<ffffffff811541c1>] ra_submit+0x21/0x30
> > [ 111.404781] [<ffffffff811482f7>] filemap_fault+0x2d7/0x4f0
> > [ 111.404781] [<ffffffff8116f3ad>] __do_fault+0x6d/0x4c0
> > [ 111.404781] [<ffffffff81172596>] handle_mm_fault+0x1a6/0xaf0
> > [ 111.404781] [<ffffffff816eb1aa>] __do_page_fault+0x18a/0x590
> > [ 111.404781] [<ffffffff816efdff>] ? ftrace_call+0x5/0x2f
> > [ 111.404781] [<ffffffff81081e9c>] ? finish_task_switch+0x7c/0x120
> > [ 111.404781] [<ffffffff81081e5f>] ? finish_task_switch+0x3f/0x120
> > [ 111.404781] [<ffffffff816eb5bc>] do_page_fault+0xc/0x10
> > [ 111.404781] [<ffffffff816e7a52>] page_fault+0x22/0x30
> >
> > Signed-off-by: Minchan Kim <minchan@xxxxxxxxxx>
> > ---
> > 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@xxxxxxxxxx For more info on Linux MM,
> see: http://www.linux-mm.org/ .
> Don't email: <a href=mailto:"dont@xxxxxxxxx";> email@xxxxxxxxx </a>
--
Kind regards,
Minchan Kim
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/