public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed
* [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output
@ 2014-04-19  7:45 Jiaxing Wang
  2014-04-19 15:18 ` Steven Rostedt
  2014-04-24 17:41 ` Steven Rostedt
  0 siblings, 2 replies; 5+ messages in thread
From: Jiaxing Wang @ 2014-04-19  7:45 UTC (permalink / raw)
  To: Steven Rostedt, Frederic Weisbecker, Ingo Molnar
  Cc: linux-kernel, Jiaxing Wang

When function_graph tracer is enabled, we get stack trace like this:

         Depth    Size   Location    (88 entries)
         -----    ----   --------
   0)     3232       0   update_curr+0xe/0x1e0
   1)     3232       0   dump_trace+0xb5/0x1b0
   2)     3232       0   ftrace_ops_list_func+0xe6/0x100
   3)     3232      68   ftrace_call+0x5/0xb
   4)     3164      92   enqueue_entity+0x38/0xe20
   5)     3072       0   return_to_handler+0x0/0xf
   6)     3072      80   save_stack_trace+0x30/0x50
   7)     2992       0   return_to_handler+0x0/0xf
   8)     2992      28   stack_trace_call+0x119/0x340
   9)     2964       0   return_to_handler+0x0/0xf
  10)     2964      12   enqueue_task_fair+0x47/0x7e0
  11)     2952       0   return_to_handler+0x0/0xf
  12)     2952      16   enqueue_task+0x45/0x70
  ... ...

The 'save_stack_trace+0x30/0x50' and 'stack_trace_call+0x119/0x340'
entries are misplaced below the ftrace_ops_list_func and ftrace_call entries,
which looks very confusing.

And dump_stack() is also affected when function_graph tracer is enabled:

  [  425.353391] Call Trace:
  [  425.353449]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.353496]  [<c1012546>] print_context_stack+0xc6/0xd0
  [  425.353547]  [<c108ab84>] enqueue_entity+0x894/0xe60
  [  425.353597]  [<c107b4c5>] ? enqueue_task+0x45/0x70
  [  425.353649]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
  [  425.353694]  [<c107b4c5>] ? enqueue_task+0x45/0x70
  [  425.353743]  [<c1041037>] ? prepare_ftrace_return+0x77/0xa0
  [  425.353791]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
  [  425.353856]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.353901]  [<c10116b5>] dump_trace+0xb5/0x1b0
  [  425.353958]  [<c107b4dd>] ? enqueue_task+0x5d/0x70
  [  425.354002]  [<c107b436>] ? update_rq_clock.part.80+0x6/0x50
  [  425.354074]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.354120]  [<c1012666>] show_trace_log_lvl+0x46/0x50
  [  425.354178]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.354222]  [<c1011802>] show_stack_log_lvl+0x52/0xe0
  [  425.354272]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.354317]  [<c10126c6>] show_stack+0x26/0x50
  [  425.354369]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.354415]  [<c1643be1>] dump_stack+0x41/0x52
  [  425.354483]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.354527]  [<c108b197>] enqueue_task_fair+0x47/0x7e0
  [  425.354576]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
  [  425.354621]  [<c107b4c5>] enqueue_task+0x45/0x70
  ... ...

This happens because the functions in the route of stack_trace and
dump_stack() get function_graph traced, their return addresses on stack are
replaced by 'return_to_handler' and their real return addresses are
saved in current->ret_stack[].(Specifically, these functons include
save_stack_trace,dump_trace,print_context_stack,print_ftrace_graph_addr
in the case of stack_trace and show_stack,show_stack_log_lvl,show_trace_log_lvl
,dump_trace,print_context_stack,print_ftrace_graph_addr in the case of
dump_stack()).

When dumping the stack, their 'return_to_handler' on stack are skipped
but not their corresponding current->ret_stack entries which then are matched
with other function's 'return_to_handler' on the stack and resulting the
wrong output above.

To fix this, we can disable the profiling of dumpstack utilities.

Signed-off-by: Jiaxing Wang <wangjiaxing@insigma.com.cn>
---
 arch/x86/kernel/Makefile | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile
index f4d9600..9dd8ce4 100644
--- a/arch/x86/kernel/Makefile
+++ b/arch/x86/kernel/Makefile
@@ -14,6 +14,9 @@ CFLAGS_REMOVE_pvclock.o = -pg
 CFLAGS_REMOVE_kvmclock.o = -pg
 CFLAGS_REMOVE_ftrace.o = -pg
 CFLAGS_REMOVE_early_printk.o = -pg
+CFLAGS_REMOVE_dumpstack.o = -pg
+CFLAGS_REMOVE_dumpstack_32.o = -pg
+CFLAGS_REMOVE_stacktrace.o = -pg
 endif
 
 CFLAGS_irq.o := -I$(src)/../include/asm/trace
-- 
1.8.3.2


^ permalink raw reply related	[flat|nested] 5+ messages in thread

* Re: [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output
  2014-04-19  7:45 [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output Jiaxing Wang
@ 2014-04-19 15:18 ` Steven Rostedt
  2014-04-19 23:47   ` Jiaxing Wang
  2014-04-24 17:41 ` Steven Rostedt
  1 sibling, 1 reply; 5+ messages in thread
From: Steven Rostedt @ 2014-04-19 15:18 UTC (permalink / raw)
  To: Jiaxing Wang; +Cc: Frederic Weisbecker, Ingo Molnar, linux-kernel

On Sat, 19 Apr 2014 15:45:46 +0800
Jiaxing Wang <wangjiaxing@insigma.com.cn> wrote:

> When function_graph tracer is enabled, we get stack trace like this:
> 
>          Depth    Size   Location    (88 entries)
>          -----    ----   --------
>    0)     3232       0   update_curr+0xe/0x1e0
>    1)     3232       0   dump_trace+0xb5/0x1b0
>    2)     3232       0   ftrace_ops_list_func+0xe6/0x100
>    3)     3232      68   ftrace_call+0x5/0xb
>    4)     3164      92   enqueue_entity+0x38/0xe20
>    5)     3072       0   return_to_handler+0x0/0xf
>    6)     3072      80   save_stack_trace+0x30/0x50
>    7)     2992       0   return_to_handler+0x0/0xf
>    8)     2992      28   stack_trace_call+0x119/0x340
>    9)     2964       0   return_to_handler+0x0/0xf
>   10)     2964      12   enqueue_task_fair+0x47/0x7e0
>   11)     2952       0   return_to_handler+0x0/0xf
>   12)     2952      16   enqueue_task+0x45/0x70
>   ... ...
> 
> The 'save_stack_trace+0x30/0x50' and 'stack_trace_call+0x119/0x340'
> entries are misplaced below the ftrace_ops_list_func and ftrace_call entries,
> which looks very confusing.
> 
> And dump_stack() is also affected when function_graph tracer is enabled:
> 
>   [  425.353391] Call Trace:
>   [  425.353449]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.353496]  [<c1012546>] print_context_stack+0xc6/0xd0
>   [  425.353547]  [<c108ab84>] enqueue_entity+0x894/0xe60
>   [  425.353597]  [<c107b4c5>] ? enqueue_task+0x45/0x70
>   [  425.353649]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
>   [  425.353694]  [<c107b4c5>] ? enqueue_task+0x45/0x70
>   [  425.353743]  [<c1041037>] ? prepare_ftrace_return+0x77/0xa0
>   [  425.353791]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
>   [  425.353856]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.353901]  [<c10116b5>] dump_trace+0xb5/0x1b0
>   [  425.353958]  [<c107b4dd>] ? enqueue_task+0x5d/0x70
>   [  425.354002]  [<c107b436>] ? update_rq_clock.part.80+0x6/0x50
>   [  425.354074]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354120]  [<c1012666>] show_trace_log_lvl+0x46/0x50
>   [  425.354178]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354222]  [<c1011802>] show_stack_log_lvl+0x52/0xe0
>   [  425.354272]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354317]  [<c10126c6>] show_stack+0x26/0x50
>   [  425.354369]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354415]  [<c1643be1>] dump_stack+0x41/0x52
>   [  425.354483]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354527]  [<c108b197>] enqueue_task_fair+0x47/0x7e0
>   [  425.354576]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354621]  [<c107b4c5>] enqueue_task+0x45/0x70
>   ... ...
> 
> This happens because the functions in the route of stack_trace and
> dump_stack() get function_graph traced, their return addresses on stack are
> replaced by 'return_to_handler' and their real return addresses are
> saved in current->ret_stack[].(Specifically, these functons include
> save_stack_trace,dump_trace,print_context_stack,print_ftrace_graph_addr
> in the case of stack_trace and show_stack,show_stack_log_lvl,show_trace_log_lvl
> ,dump_trace,print_context_stack,print_ftrace_graph_addr in the case of
> dump_stack()).
> 
> When dumping the stack, their 'return_to_handler' on stack are skipped
> but not their corresponding current->ret_stack entries which then are matched
> with other function's 'return_to_handler' on the stack and resulting the
> wrong output above.

This sounds like a separate bug that should be fixed.

> 
> To fix this, we can disable the profiling of dumpstack utilities.
> 
> Signed-off-by: Jiaxing Wang <wangjiaxing@insigma.com.cn>
> ---
>  arch/x86/kernel/Makefile | 3 +++
>  1 file changed, 3 insertions(+)
> 
> diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile
> index f4d9600..9dd8ce4 100644
> --- a/arch/x86/kernel/Makefile
> +++ b/arch/x86/kernel/Makefile
> @@ -14,6 +14,9 @@ CFLAGS_REMOVE_pvclock.o = -pg
>  CFLAGS_REMOVE_kvmclock.o = -pg
>  CFLAGS_REMOVE_ftrace.o = -pg
>  CFLAGS_REMOVE_early_printk.o = -pg
> +CFLAGS_REMOVE_dumpstack.o = -pg
> +CFLAGS_REMOVE_dumpstack_32.o = -pg
> +CFLAGS_REMOVE_stacktrace.o = -pg

I have no problem with this change, but it is 3.16 material. But if the
function graph tracer is causing the stack trace to be incorrect, then
that is a separate issues that we should try to rectify.

-- Steve

>  endif
>  
>  CFLAGS_irq.o := -I$(src)/../include/asm/trace


^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output
  2014-04-19 15:18 ` Steven Rostedt
@ 2014-04-19 23:47   ` Jiaxing Wang
  2014-04-24 17:39     ` Steven Rostedt
  0 siblings, 1 reply; 5+ messages in thread
From: Jiaxing Wang @ 2014-04-19 23:47 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Frederic Weisbecker, Ingo Molnar, linux-kernel

On 04/19/2014 11:18 PM, Steven Rostedt wrote:
> On Sat, 19 Apr 2014 15:45:46 +0800
> Jiaxing Wang <wangjiaxing@insigma.com.cn> wrote:
> 
>> When function_graph tracer is enabled, we get stack trace like this:
>>
>>          Depth    Size   Location    (88 entries)
>>          -----    ----   --------
>>    0)     3232       0   update_curr+0xe/0x1e0
>>    1)     3232       0   dump_trace+0xb5/0x1b0
>>    2)     3232       0   ftrace_ops_list_func+0xe6/0x100
>>    3)     3232      68   ftrace_call+0x5/0xb
>>    4)     3164      92   enqueue_entity+0x38/0xe20
>>    5)     3072       0   return_to_handler+0x0/0xf
>>    6)     3072      80   save_stack_trace+0x30/0x50
>>    7)     2992       0   return_to_handler+0x0/0xf
>>    8)     2992      28   stack_trace_call+0x119/0x340
>>    9)     2964       0   return_to_handler+0x0/0xf
>>   10)     2964      12   enqueue_task_fair+0x47/0x7e0
>>   11)     2952       0   return_to_handler+0x0/0xf
>>   12)     2952      16   enqueue_task+0x45/0x70
>>   ... ...
>>
>> The 'save_stack_trace+0x30/0x50' and 'stack_trace_call+0x119/0x340'
>> entries are misplaced below the ftrace_ops_list_func and ftrace_call entries,
>> which looks very confusing.
>>
>> And dump_stack() is also affected when function_graph tracer is enabled:
>>
>>   [  425.353391] Call Trace:
>>   [  425.353449]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.353496]  [<c1012546>] print_context_stack+0xc6/0xd0
>>   [  425.353547]  [<c108ab84>] enqueue_entity+0x894/0xe60
>>   [  425.353597]  [<c107b4c5>] ? enqueue_task+0x45/0x70
>>   [  425.353649]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
>>   [  425.353694]  [<c107b4c5>] ? enqueue_task+0x45/0x70
>>   [  425.353743]  [<c1041037>] ? prepare_ftrace_return+0x77/0xa0
>>   [  425.353791]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
>>   [  425.353856]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.353901]  [<c10116b5>] dump_trace+0xb5/0x1b0
>>   [  425.353958]  [<c107b4dd>] ? enqueue_task+0x5d/0x70
>>   [  425.354002]  [<c107b436>] ? update_rq_clock.part.80+0x6/0x50
>>   [  425.354074]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.354120]  [<c1012666>] show_trace_log_lvl+0x46/0x50
>>   [  425.354178]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.354222]  [<c1011802>] show_stack_log_lvl+0x52/0xe0
>>   [  425.354272]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.354317]  [<c10126c6>] show_stack+0x26/0x50
>>   [  425.354369]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.354415]  [<c1643be1>] dump_stack+0x41/0x52
>>   [  425.354483]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.354527]  [<c108b197>] enqueue_task_fair+0x47/0x7e0
>>   [  425.354576]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>>   [  425.354621]  [<c107b4c5>] enqueue_task+0x45/0x70
>>   ... ...
>>
>> This happens because the functions in the route of stack_trace and
>> dump_stack() get function_graph traced, their return addresses on stack are
>> replaced by 'return_to_handler' and their real return addresses are
>> saved in current->ret_stack[].(Specifically, these functons include
>> save_stack_trace,dump_trace,print_context_stack,print_ftrace_graph_addr
>> in the case of stack_trace and show_stack,show_stack_log_lvl,show_trace_log_lvl
>> ,dump_trace,print_context_stack,print_ftrace_graph_addr in the case of
>> dump_stack()).
>>
>> When dumping the stack, their 'return_to_handler' on stack are skipped
>> but not their corresponding current->ret_stack entries which then are matched
>> with other function's 'return_to_handler' on the stack and resulting the
>> wrong output above.
> 
> This sounds like a separate bug that should be fixed.
> 
Return addresses are skipped as stack_trace dump stack from the return
address of dump_trace() and dump_stack() dump stack from the return address
of show_stack().

Here is the stack_trace case:
  stack                               current->ret_stack[]
  -----                               --------------------
  return_to_handler                   print_context_stack+0xc6/0xd0
  return_to_handler                   dump_trace+0xb5/0x1b0
  return_to_handler                   save_stack_trace+0x30/0x50
  return_to_handler                   stack_trace_call+0x119/0x340
  ftrace_ops_listfunc+0xe6/0x100
  ftrace_call+0x5/0xb

So when dump, the first two 'return_to_handler' entries are skipped but
not the current->ret_stack[] entries.

And the following is the dump_stack() case:

  stack                               current->ret_stack[]
  -----                               --------------------
  return_to_handler                   print_context_stack+0xc6/0xd0
  return_to_handler                   dump_trace+0xb5/0x1b0
  return_to_handler                   show_trace_log_lvl+0x46/0x50
  return_to_handler                   show_stack_log_lvl+0x52/0xe0
  return_to_handler                   show_stack+0x26/0x50
  return_to_handler                   dump_stack+0x41/0x52

In this case the first five 'return_to_handler' entries on stack are
skipped but not the current->ret_stack[] entries.

So the problem is caused by dumpstack utilities get traced by function_graph
tracer, and disable the profiling of them fixes this.

Thanks.
>>
>> To fix this, we can disable the profiling of dumpstack utilities.
>>
>> Signed-off-by: Jiaxing Wang <wangjiaxing@insigma.com.cn>
>> ---
>>  arch/x86/kernel/Makefile | 3 +++
>>  1 file changed, 3 insertions(+)
>>
>> diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile
>> index f4d9600..9dd8ce4 100644
>> --- a/arch/x86/kernel/Makefile
>> +++ b/arch/x86/kernel/Makefile
>> @@ -14,6 +14,9 @@ CFLAGS_REMOVE_pvclock.o = -pg
>>  CFLAGS_REMOVE_kvmclock.o = -pg
>>  CFLAGS_REMOVE_ftrace.o = -pg
>>  CFLAGS_REMOVE_early_printk.o = -pg
>> +CFLAGS_REMOVE_dumpstack.o = -pg
>> +CFLAGS_REMOVE_dumpstack_32.o = -pg
>> +CFLAGS_REMOVE_stacktrace.o = -pg
> 
> I have no problem with this change, but it is 3.16 material. But if the
> function graph tracer is causing the stack trace to be incorrect, then
> that is a separate issues that we should try to rectify.
> 
> -- Steve
> 
>>  endif
>>  
>>  CFLAGS_irq.o := -I$(src)/../include/asm/trace
> 
> .
> 


^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output
  2014-04-19 23:47   ` Jiaxing Wang
@ 2014-04-24 17:39     ` Steven Rostedt
  0 siblings, 0 replies; 5+ messages in thread
From: Steven Rostedt @ 2014-04-24 17:39 UTC (permalink / raw)
  To: Jiaxing Wang; +Cc: Frederic Weisbecker, Ingo Molnar, linux-kernel

On Sun, 20 Apr 2014 07:47:03 +0800
Jiaxing Wang <wangjiaxing@insigma.com.cn> wrote:

> So the problem is caused by dumpstack utilities get traced by function_graph
> tracer, and disable the profiling of them fixes this.

OK, that makes sense. Thanks.

-- Steve

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output
  2014-04-19  7:45 [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output Jiaxing Wang
  2014-04-19 15:18 ` Steven Rostedt
@ 2014-04-24 17:41 ` Steven Rostedt
  1 sibling, 0 replies; 5+ messages in thread
From: Steven Rostedt @ 2014-04-24 17:41 UTC (permalink / raw)
  To: Jiaxing Wang, H. Peter Anvin
  Cc: Frederic Weisbecker, Ingo Molnar, linux-kernel

Peter, this is actually an ftrace/x86 fix (not a tracing one), do you
want to take it. You can add my Acked-by as well.

-- Steve


On Sat, 19 Apr 2014 15:45:46 +0800
Jiaxing Wang <wangjiaxing@insigma.com.cn> wrote:

> When function_graph tracer is enabled, we get stack trace like this:
> 
>          Depth    Size   Location    (88 entries)
>          -----    ----   --------
>    0)     3232       0   update_curr+0xe/0x1e0
>    1)     3232       0   dump_trace+0xb5/0x1b0
>    2)     3232       0   ftrace_ops_list_func+0xe6/0x100
>    3)     3232      68   ftrace_call+0x5/0xb
>    4)     3164      92   enqueue_entity+0x38/0xe20
>    5)     3072       0   return_to_handler+0x0/0xf
>    6)     3072      80   save_stack_trace+0x30/0x50
>    7)     2992       0   return_to_handler+0x0/0xf
>    8)     2992      28   stack_trace_call+0x119/0x340
>    9)     2964       0   return_to_handler+0x0/0xf
>   10)     2964      12   enqueue_task_fair+0x47/0x7e0
>   11)     2952       0   return_to_handler+0x0/0xf
>   12)     2952      16   enqueue_task+0x45/0x70
>   ... ...
> 
> The 'save_stack_trace+0x30/0x50' and 'stack_trace_call+0x119/0x340'
> entries are misplaced below the ftrace_ops_list_func and ftrace_call entries,
> which looks very confusing.
> 
> And dump_stack() is also affected when function_graph tracer is enabled:
> 
>   [  425.353391] Call Trace:
>   [  425.353449]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.353496]  [<c1012546>] print_context_stack+0xc6/0xd0
>   [  425.353547]  [<c108ab84>] enqueue_entity+0x894/0xe60
>   [  425.353597]  [<c107b4c5>] ? enqueue_task+0x45/0x70
>   [  425.353649]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
>   [  425.353694]  [<c107b4c5>] ? enqueue_task+0x45/0x70
>   [  425.353743]  [<c1041037>] ? prepare_ftrace_return+0x77/0xa0
>   [  425.353791]  [<c108b159>] ? enqueue_task_fair+0x9/0x7e0
>   [  425.353856]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.353901]  [<c10116b5>] dump_trace+0xb5/0x1b0
>   [  425.353958]  [<c107b4dd>] ? enqueue_task+0x5d/0x70
>   [  425.354002]  [<c107b436>] ? update_rq_clock.part.80+0x6/0x50
>   [  425.354074]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354120]  [<c1012666>] show_trace_log_lvl+0x46/0x50
>   [  425.354178]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354222]  [<c1011802>] show_stack_log_lvl+0x52/0xe0
>   [  425.354272]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354317]  [<c10126c6>] show_stack+0x26/0x50
>   [  425.354369]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354415]  [<c1643be1>] dump_stack+0x41/0x52
>   [  425.354483]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354527]  [<c108b197>] enqueue_task_fair+0x47/0x7e0
>   [  425.354576]  [<c16531c1>] ftrace_graph_caller+0x19/0x19
>   [  425.354621]  [<c107b4c5>] enqueue_task+0x45/0x70
>   ... ...
> 
> This happens because the functions in the route of stack_trace and
> dump_stack() get function_graph traced, their return addresses on stack are
> replaced by 'return_to_handler' and their real return addresses are
> saved in current->ret_stack[].(Specifically, these functons include
> save_stack_trace,dump_trace,print_context_stack,print_ftrace_graph_addr
> in the case of stack_trace and show_stack,show_stack_log_lvl,show_trace_log_lvl
> ,dump_trace,print_context_stack,print_ftrace_graph_addr in the case of
> dump_stack()).
> 
> When dumping the stack, their 'return_to_handler' on stack are skipped
> but not their corresponding current->ret_stack entries which then are matched
> with other function's 'return_to_handler' on the stack and resulting the
> wrong output above.
> 
> To fix this, we can disable the profiling of dumpstack utilities.
> 
> Signed-off-by: Jiaxing Wang <wangjiaxing@insigma.com.cn>
> ---
>  arch/x86/kernel/Makefile | 3 +++
>  1 file changed, 3 insertions(+)
> 
> diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile
> index f4d9600..9dd8ce4 100644
> --- a/arch/x86/kernel/Makefile
> +++ b/arch/x86/kernel/Makefile
> @@ -14,6 +14,9 @@ CFLAGS_REMOVE_pvclock.o = -pg
>  CFLAGS_REMOVE_kvmclock.o = -pg
>  CFLAGS_REMOVE_ftrace.o = -pg
>  CFLAGS_REMOVE_early_printk.o = -pg
> +CFLAGS_REMOVE_dumpstack.o = -pg
> +CFLAGS_REMOVE_dumpstack_32.o = -pg
> +CFLAGS_REMOVE_stacktrace.o = -pg
>  endif
>  
>  CFLAGS_irq.o := -I$(src)/../include/asm/trace


^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, other threads:[~2014-04-24 17:41 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2014-04-19  7:45 [PATCH] tracing:Do not profile dumpstack utilities to fix stack trace output Jiaxing Wang
2014-04-19 15:18 ` Steven Rostedt
2014-04-19 23:47   ` Jiaxing Wang
2014-04-24 17:39     ` Steven Rostedt
2014-04-24 17:41 ` Steven Rostedt

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox