Re: [PATCH 1/2] ftrace: print stack usage right before Oops

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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@xxxxxxxxx.  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, send a message with 'unsubscribe linux-mm' in
the body to majordomo@xxxxxxxxx.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@xxxxxxxxx";> email@xxxxxxxxx </a>




[Index of Archives]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Bugtraq]     [Linux]     [Linux OMAP]     [Linux MIPS]     [ECOS]     [Asterisk Internet PBX]     [Linux API]