[PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Tim Bird]

This adds support for 'tracing_thresh' to the existing function_graph
tracer.  When 'tracing_thresh' is in effect, function entry events are
not stored - only function exits are stored.  This prevents filtered
functions from filling up the log. An extra option is added to allow
showing the function name with the exit event.  (Otherwise, all you
get are closing braces.)

Note that the 'funcgraph-exit' display option is valuable by itself,
since it makes the output much more 'grep-able'.

Signed-off-by: Tim Bird <tim.bird@am.sony.com>
--
 trace.c                 |    5 +++--
 trace_functions_graph.c |   20 +++++++++++++++++++-
 2 files changed, 22 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 0df1b0f..aa39f8e 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -502,9 +502,10 @@ static ssize_t trace_seq_to_buffer(struct trace_seq
*s, void *buf, size_t cnt)
 static arch_spinlock_t ftrace_max_lock =
     (arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
 
+unsigned long __read_mostly    tracing_thresh;
+
 #ifdef CONFIG_TRACER_MAX_TRACE
 unsigned long __read_mostly    tracing_max_latency;
-unsigned long __read_mostly    tracing_thresh;
 
 /*
  * Copy the new maximum trace into the separate maximum-trace
@@ -4176,10 +4177,10 @@ static __init int tracer_init_debugfs(void)
 #ifdef CONFIG_TRACER_MAX_TRACE
     trace_create_file("tracing_max_latency", 0644, d_tracer,
             &tracing_max_latency, &tracing_max_lat_fops);
+#endif
 
     trace_create_file("tracing_thresh", 0644, d_tracer,
             &tracing_thresh, &tracing_max_lat_fops);
-#endif
 
     trace_create_file("README", 0444, d_tracer,
             NULL, &tracing_readme_fops);
diff --git a/kernel/trace/trace_functions_graph.c
b/kernel/trace/trace_functions_graph.c
index b1342c5..e019e32 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -39,6 +39,7 @@ struct fgraph_data {
 #define TRACE_GRAPH_PRINT_PROC        0x8
 #define TRACE_GRAPH_PRINT_DURATION    0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME    0X20
+#define TRACE_GRAPH_PRINT_FUNC_EXIT    0X40
 
 static struct tracer_opt trace_opts[] = {
     /* Display overruns? (for self-debug purpose) */
@@ -53,6 +54,8 @@ static struct tracer_opt trace_opts[] = {
     { TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
     /* Display absolute time of an entry */
     { TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
+    /* Display function name on exit, instead of just closing brace */
+    { TRACER_OPT(funcgraph-exit, TRACE_GRAPH_PRINT_FUNC_EXIT) },
     { } /* Empty entry */
 };
 
@@ -202,6 +205,8 @@ static int __trace_graph_entry(struct trace_array *tr,
     return 1;
 }
 
+extern unsigned long __read_mostly tracing_thresh;
+
 int trace_graph_entry(struct ftrace_graph_ent *trace)
 {
     struct trace_array *tr = graph_array;
@@ -221,6 +226,10 @@ int trace_graph_entry(struct ftrace_graph_ent *trace)
     if (!ftrace_graph_addr(trace->func))
         return 0;
 
+    /* if tracing duration, only save function exits (omit function
entries in log) */
+    if (tracing_thresh)
+        return 1;
+
     local_irq_save(flags);
     cpu = raw_smp_processor_id();
     data = tr->data[cpu];
@@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array
*tr,
     if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
         return;
 
+    if (tracing_thresh &&
+        (trace->rettime - trace->calltime < tracing_thresh))
+        return;
+
     event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_RET,
                       sizeof(*entry), flags, pc);
     if (!event)
@@ -891,7 +904,12 @@ print_graph_return(struct ftrace_graph_ret *trace,
struct trace_seq *s,
             return TRACE_TYPE_PARTIAL_LINE;
     }
 
-    ret = trace_seq_printf(s, "}\n");
+    if (tracer_flags.val & TRACE_GRAPH_PRINT_FUNC_EXIT) {
+        ret = trace_seq_printf(s, "%ps();\n", (void *)trace->func);
+    } else {
+        ret = trace_seq_printf(s, "}\n");
+    }
+
     if (!ret)
         return TRACE_TYPE_PARTIAL_LINE;
 

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Tim Bird]

On 02/10/2010 02:45 PM, Tim Bird wrote:
(a bunch of format_flowed garbage)

Sorry - I updated my mail client and forgot to disable the format_flowed
option.

Here's the patch again, hopefully in better format this time.

This adds support for 'tracing_thresh' to the existing function_graph
tracer.  When 'tracing_thresh' is in effect, function entry events are
not stored - only function exits are stored.  This prevents filtered
functions from filling up the log. An extra option is added to allow
showing the function name with the exit event.  (Otherwise, all you
get are closing braces.)

Note that the 'funcgraph-exit' display option is valuable by itself,
since it makes the output much more 'grep-able'.

Signed-off-by: Tim Bird <tim.bird@am.sony.com>
--
 trace.c                 |    5 +++--
 trace_functions_graph.c |   20 +++++++++++++++++++-
 2 files changed, 22 insertions(+), 3 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 0df1b0f..aa39f8e 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -502,9 +502,10 @@ static ssize_t trace_seq_to_buffer(struct trace_seq *s, void *buf, size_t cnt)
 static arch_spinlock_t ftrace_max_lock =
 	(arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
 
+unsigned long __read_mostly	tracing_thresh;
+
 #ifdef CONFIG_TRACER_MAX_TRACE
 unsigned long __read_mostly	tracing_max_latency;
-unsigned long __read_mostly	tracing_thresh;
 
 /*
  * Copy the new maximum trace into the separate maximum-trace
@@ -4176,10 +4177,10 @@ static __init int tracer_init_debugfs(void)
 #ifdef CONFIG_TRACER_MAX_TRACE
 	trace_create_file("tracing_max_latency", 0644, d_tracer,
 			&tracing_max_latency, &tracing_max_lat_fops);
+#endif
 
 	trace_create_file("tracing_thresh", 0644, d_tracer,
 			&tracing_thresh, &tracing_max_lat_fops);
-#endif
 
 	trace_create_file("README", 0444, d_tracer,
 			NULL, &tracing_readme_fops);
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index b1342c5..e019e32 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -39,6 +39,7 @@ struct fgraph_data {
 #define TRACE_GRAPH_PRINT_PROC		0x8
 #define TRACE_GRAPH_PRINT_DURATION	0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME	0X20
+#define TRACE_GRAPH_PRINT_FUNC_EXIT	0X40
 
 static struct tracer_opt trace_opts[] = {
 	/* Display overruns? (for self-debug purpose) */
@@ -53,6 +54,8 @@ static struct tracer_opt trace_opts[] = {
 	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
 	/* Display absolute time of an entry */
 	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
+	/* Display function name on exit, instead of just closing brace */
+	{ TRACER_OPT(funcgraph-exit, TRACE_GRAPH_PRINT_FUNC_EXIT) },
 	{ } /* Empty entry */
 };
 
@@ -202,6 +205,8 @@ static int __trace_graph_entry(struct trace_array *tr,
 	return 1;
 }
 
+extern unsigned long __read_mostly tracing_thresh;
+
 int trace_graph_entry(struct ftrace_graph_ent *trace)
 {
 	struct trace_array *tr = graph_array;
@@ -221,6 +226,10 @@ int trace_graph_entry(struct ftrace_graph_ent *trace)
 	if (!ftrace_graph_addr(trace->func))
 		return 0;
 
+	/* if tracing duration, only save function exits (omit function entries in log) */
+	if (tracing_thresh)
+		return 1;
+
 	local_irq_save(flags);
 	cpu = raw_smp_processor_id();
 	data = tr->data[cpu];
@@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array *tr,
 	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
 		return;
 
+	if (tracing_thresh &&
+		(trace->rettime - trace->calltime < tracing_thresh))
+		return;
+
 	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_RET,
 					  sizeof(*entry), flags, pc);
 	if (!event)
@@ -891,7 +904,12 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 			return TRACE_TYPE_PARTIAL_LINE;
 	}
 
-	ret = trace_seq_printf(s, "}\n");
+	if (tracer_flags.val & TRACE_GRAPH_PRINT_FUNC_EXIT) {
+		ret = trace_seq_printf(s, "%ps();\n", (void *)trace->func);
+	} else {
+		ret = trace_seq_printf(s, "}\n");
+	}
+
 	if (!ret)
 		return TRACE_TYPE_PARTIAL_LINE;
 

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Steven Rostedt]

On Wed, 2010-02-10 at 14:52 -0800, Tim Bird wrote:
> On 02/10/2010 02:45 PM, Tim Bird wrote:
> (a bunch of format_flowed garbage)
> 
> Sorry - I updated my mail client and forgot to disable the format_flowed
> option.
> 
> Here's the patch again, hopefully in better format this time.
> 
> This adds support for 'tracing_thresh' to the existing function_graph
> tracer.  When 'tracing_thresh' is in effect, function entry events are
> not stored - only function exits are stored.  This prevents filtered
> functions from filling up the log. An extra option is added to allow
> showing the function name with the exit event.  (Otherwise, all you
> get are closing braces.)
> 
> Note that the 'funcgraph-exit' display option is valuable by itself,
> since it makes the output much more 'grep-able'.
> 
> Signed-off-by: Tim Bird <tim.bird@am.sony.com>
> --
>  trace.c                 |    5 +++--
>  trace_functions_graph.c |   20 +++++++++++++++++++-
>  2 files changed, 22 insertions(+), 3 deletions(-)
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 0df1b0f..aa39f8e 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -502,9 +502,10 @@ static ssize_t trace_seq_to_buffer(struct trace_seq *s, void *buf, size_t cnt)
>  static arch_spinlock_t ftrace_max_lock =
>  	(arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
>  
> +unsigned long __read_mostly	tracing_thresh;
> +
>  #ifdef CONFIG_TRACER_MAX_TRACE
>  unsigned long __read_mostly	tracing_max_latency;
> -unsigned long __read_mostly	tracing_thresh;
>  
>  /*
>   * Copy the new maximum trace into the separate maximum-trace
> @@ -4176,10 +4177,10 @@ static __init int tracer_init_debugfs(void)
>  #ifdef CONFIG_TRACER_MAX_TRACE
>  	trace_create_file("tracing_max_latency", 0644, d_tracer,
>  			&tracing_max_latency, &tracing_max_lat_fops);
> +#endif
>  
>  	trace_create_file("tracing_thresh", 0644, d_tracer,
>  			&tracing_thresh, &tracing_max_lat_fops);
> -#endif
>  
>  	trace_create_file("README", 0444, d_tracer,
>  			NULL, &tracing_readme_fops);
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index b1342c5..e019e32 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -39,6 +39,7 @@ struct fgraph_data {
>  #define TRACE_GRAPH_PRINT_PROC		0x8
>  #define TRACE_GRAPH_PRINT_DURATION	0x10
>  #define TRACE_GRAPH_PRINT_ABS_TIME	0X20
> +#define TRACE_GRAPH_PRINT_FUNC_EXIT	0X40
>  
>  static struct tracer_opt trace_opts[] = {
>  	/* Display overruns? (for self-debug purpose) */
> @@ -53,6 +54,8 @@ static struct tracer_opt trace_opts[] = {
>  	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
>  	/* Display absolute time of an entry */
>  	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
> +	/* Display function name on exit, instead of just closing brace */
> +	{ TRACER_OPT(funcgraph-exit, TRACE_GRAPH_PRINT_FUNC_EXIT) },
>  	{ } /* Empty entry */

I wonder if this should be enabled on start up of the function graph
tracer if the threshold is set?

Otherwise people will wonder WTF?

That's what I did when I tried it out and saw:

 2) + 64.633 us   |                }
 2) + 67.193 us   |              }
 ------------------------------------------
 2)  sendmai-3295  =>    <idle>-0   
 ------------------------------------------

 2) + 15.370 us   |                }
 2) + 25.633 us   |              }
 2) + 29.831 us   |            }
 2) + 36.641 us   |          }
 2) + 31.860 us   |              }
 2) + 33.669 us   |            }
 2) + 36.804 us   |          }
 2) + 79.140 us   |        }
 2)   <========== |
 2) + 81.486 us   |      }



I went back to read your change log and said, Oh! I missed that.

Turned it on, and now it is:

 1) ! 116.424 us  |    smp_apic_timer_interrupt();
 1)   <========== |
 1) ! 154948.1 us |  mwait_idle();
 1) + 17.456 us   |  tick_nohz_restart_sched_tick();
 ------------------------------------------
 1)    <idle>-0    =>   pcscd-3182  
 ------------------------------------------

 1) ! 998960.9 us |        schedule();
 1) ! 998973.3 us |      do_nanosleep();
 1) ! 998975.2 us |    hrtimer_nanosleep();
 1) ! 998977.6 us |  sys_nanosleep();
 1) + 31.927 us   |            link_path_walk();
 1) + 36.168 us   |          path_walk();


-- Steve

>  };
>  
> @@ -202,6 +205,8 @@ static int __trace_graph_entry(struct trace_array *tr,
>  	return 1;
>  }
>  
> +extern unsigned long __read_mostly tracing_thresh;
> +
>  int trace_graph_entry(struct ftrace_graph_ent *trace)
>  {
>  	struct trace_array *tr = graph_array;
> @@ -221,6 +226,10 @@ int trace_graph_entry(struct ftrace_graph_ent *trace)
>  	if (!ftrace_graph_addr(trace->func))
>  		return 0;
>  
> +	/* if tracing duration, only save function exits (omit function entries in log) */
> +	if (tracing_thresh)
> +		return 1;
> +
>  	local_irq_save(flags);
>  	cpu = raw_smp_processor_id();
>  	data = tr->data[cpu];
> @@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array *tr,
>  	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
>  		return;
>  
> +	if (tracing_thresh &&
> +		(trace->rettime - trace->calltime < tracing_thresh))
> +		return;
> +
>  	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_RET,
>  					  sizeof(*entry), flags, pc);
>  	if (!event)
> @@ -891,7 +904,12 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
>  			return TRACE_TYPE_PARTIAL_LINE;
>  	}
>  
> -	ret = trace_seq_printf(s, "}\n");
> +	if (tracer_flags.val & TRACE_GRAPH_PRINT_FUNC_EXIT) {
> +		ret = trace_seq_printf(s, "%ps();\n", (void *)trace->func);
> +	} else {
> +		ret = trace_seq_printf(s, "}\n");
> +	}
> +
>  	if (!ret)
>  		return TRACE_TYPE_PARTIAL_LINE;
>  
> 
> 
> 
> 

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Tim Bird]

On 02/11/2010 03:10 PM, Steven Rostedt wrote:
> On Wed, 2010-02-10 at 14:52 -0800, Tim Bird wrote:
>>  static struct tracer_opt trace_opts[] = {
>>  	/* Display overruns? (for self-debug purpose) */
>> @@ -53,6 +54,8 @@ static struct tracer_opt trace_opts[] = {
>>  	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
>>  	/* Display absolute time of an entry */
>>  	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
>> +	/* Display function name on exit, instead of just closing brace */
>> +	{ TRACER_OPT(funcgraph-exit, TRACE_GRAPH_PRINT_FUNC_EXIT) },
>>  	{ } /* Empty entry */
> 
> I wonder if this should be enabled on start up of the function graph
> tracer if the threshold is set?
> 
> Otherwise people will wonder WTF?

Indeed.  I'm not sure exactly how to do this.

Would it be better to set the option when current_tracer
is set with 'function_graph', and tracing_thresh is non-zero?
Or should I set the option when tracing_thresh is set to
non-zero, and the current_trace is set to 'function_graph'?

Or both?

It wouldn't automatically reset to nofuncgraph-exit
unless I also put some magic in for that.  I'm
pretty sure that disabling it automatically would
lead to unobvious behaviour for the user.

I'll look into how to access the options
from those two points, and see what looks feasible.
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Steven Rostedt]

On Thu, 2010-02-11 at 16:01 -0800, Tim Bird wrote:
> On 02/11/2010 03:10 PM, Steven Rostedt wrote:
> > On Wed, 2010-02-10 at 14:52 -0800, Tim Bird wrote:
> >>  static struct tracer_opt trace_opts[] = {
> >>  	/* Display overruns? (for self-debug purpose) */
> >> @@ -53,6 +54,8 @@ static struct tracer_opt trace_opts[] = {
> >>  	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
> >>  	/* Display absolute time of an entry */
> >>  	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
> >> +	/* Display function name on exit, instead of just closing brace */
> >> +	{ TRACER_OPT(funcgraph-exit, TRACE_GRAPH_PRINT_FUNC_EXIT) },
> >>  	{ } /* Empty entry */
> > 
> > I wonder if this should be enabled on start up of the function graph
> > tracer if the threshold is set?
> > 
> > Otherwise people will wonder WTF?
> 
> Indeed.  I'm not sure exactly how to do this.
> 
> Would it be better to set the option when current_tracer
> is set with 'function_graph', and tracing_thresh is non-zero?

The above is the only one I would do. If tracing_thresh is non-zero when
the function_graph tracer is set, on the start up code in the function
tracer (graph_trace_init).

Just enable the option if trace_thresh is set. If you enable function
graph tracer and have the trace_thresh set, then this type of tracing
starts immediately. It also keeps the code nicely in the
trace_function_graph.c file, and does not need to touch the setting of
tracing_thresh.

-- Steve

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Tim Bird]

On 02/11/2010 04:26 PM, Steven Rostedt wrote:
> On Thu, 2010-02-11 at 16:01 -0800, Tim Bird wrote:
>> On 02/11/2010 03:10 PM, Steven Rostedt wrote:
>>> On Wed, 2010-02-10 at 14:52 -0800, Tim Bird wrote:
>>>>  static struct tracer_opt trace_opts[] = {
>>>>  	/* Display overruns? (for self-debug purpose) */
>>>> @@ -53,6 +54,8 @@ static struct tracer_opt trace_opts[] = {
>>>>  	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
>>>>  	/* Display absolute time of an entry */
>>>>  	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
>>>> +	/* Display function name on exit, instead of just closing brace */
>>>> +	{ TRACER_OPT(funcgraph-exit, TRACE_GRAPH_PRINT_FUNC_EXIT) },
>>>>  	{ } /* Empty entry */
>>>
>>> I wonder if this should be enabled on start up of the function graph
>>> tracer if the threshold is set?
>>>
>>> Otherwise people will wonder WTF?
>>
>> Indeed.  I'm not sure exactly how to do this.
>>
>> Would it be better to set the option when current_tracer
>> is set with 'function_graph', and tracing_thresh is non-zero?
> 
> The above is the only one I would do. If tracing_thresh is non-zero when
> the function_graph tracer is set, on the start up code in the function
> tracer (graph_trace_init).
> 
> Just enable the option if trace_thresh is set. If you enable function
> graph tracer and have the trace_thresh set, then this type of tracing
> starts immediately. It also keeps the code nicely in the
> trace_function_graph.c file, and does not need to touch the setting of
> tracing_thresh.

OK.  Here's what I came up with.  Pretty straightforward.
Do you want me to integrate this into the previous patch and
re-send, or just submit this by itself.

My apologies for getting this out so late.  I'll be on
vacation with my family next week, so if you don't hear
from me, don't take it as a sign of disinterest. :-)

Index: linux-2.6.31.x86_64/kernel/trace/trace_functions_graph.c
===================================================================
--- linux-2.6.31.x86_64.orig/kernel/trace/trace_functions_graph.c	2010-02-10 14:07:47.000000000 -0800
+++ linux-2.6.31.x86_64/kernel/trace/trace_functions_graph.c	2010-02-12 16:13:53.925957633 -0800
@@ -298,6 +298,11 @@
 		return ret;
 	tracing_start_cmdline_record();

+	if (tracing_thresh)
+		tracer_flags.val |= TRACE_GRAPH_PRINT_FUNC_EXIT;
+	else
+		tracer_flags.val &= ~TRACE_GRAPH_PRINT_FUNC_EXIT;
+
 	return 0;
 }



=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Steven Rostedt]

On Fri, 2010-02-12 at 19:47 -0800, Tim Bird wrote:
> On 02/11/2010 04:26 PM, Steven Rostedt wrote:

> OK.  Here's what I came up with.  Pretty straightforward.
> Do you want me to integrate this into the previous patch and
> re-send, or just submit this by itself.

I'll fold this into your previous patch.

> 
> My apologies for getting this out so late.  I'll be on
> vacation with my family next week, so if you don't hear
> from me, don't take it as a sign of disinterest. :-)
> 

No prob. I've been quite busy so this is not that high on my priority
list. If you don't hear from me, it is probably because I put it off and
forgot about it. Don't be afraid to ping me about it.

Thanks!

-- Steve

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Frederic Weisbecker]

On Thu, Feb 11, 2010 at 07:26:55PM -0500, Steven Rostedt wrote:
> On Thu, 2010-02-11 at 16:01 -0800, Tim Bird wrote:
> > On 02/11/2010 03:10 PM, Steven Rostedt wrote:
> > > On Wed, 2010-02-10 at 14:52 -0800, Tim Bird wrote:
> > >>  static struct tracer_opt trace_opts[] = {
> > >>  	/* Display overruns? (for self-debug purpose) */
> > >> @@ -53,6 +54,8 @@ static struct tracer_opt trace_opts[] = {
> > >>  	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
> > >>  	/* Display absolute time of an entry */
> > >>  	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
> > >> +	/* Display function name on exit, instead of just closing brace */
> > >> +	{ TRACER_OPT(funcgraph-exit, TRACE_GRAPH_PRINT_FUNC_EXIT) },
> > >>  	{ } /* Empty entry */
> > > 
> > > I wonder if this should be enabled on start up of the function graph
> > > tracer if the threshold is set?
> > > 
> > > Otherwise people will wonder WTF?
> > 
> > Indeed.  I'm not sure exactly how to do this.
> > 
> > Would it be better to set the option when current_tracer
> > is set with 'function_graph', and tracing_thresh is non-zero?
> 
> The above is the only one I would do. If tracing_thresh is non-zero when
> the function_graph tracer is set, on the start up code in the function
> tracer (graph_trace_init).
> 
> Just enable the option if trace_thresh is set. If you enable function
> graph tracer and have the trace_thresh set, then this type of tracing
> starts immediately. It also keeps the code nicely in the
> trace_function_graph.c file, and does not need to touch the setting of
> tracing_thresh.


Actually why do we encumber with both tracing_thresh and the funcgraph-exit
option?

We could just have the output and the record check tracing_thresh instead
of the funcgraph-exit option.

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Steven Rostedt]

On Sat, 2010-02-20 at 15:21 +0100, Frederic Weisbecker wrote:

> 
> Actually why do we encumber with both tracing_thresh and the funcgraph-exit
> option?
> 
> We could just have the output and the record check tracing_thresh instead
> of the funcgraph-exit option.

You mean just use tracing_thresh during the tracing? We could perhaps
also change the code (and I think this would be beneficial even without
this change) to print the function on exit if it did not have a entry.

That is, in the reading of the trace, keep a depth pointer. For every
"entry" we hit, we add one, and for every "exit" we subtract one (per
cpu). If we go negative, we keep the counter at zero, but write
something like:


  } (sys_write)

Because I always hate it when a trace starts with a bunch of "}" and I
have no idea what functions they are. This would fix that.

Yeah, Tim's trace would have only "} (sys_write)" type syntax but that's
probably fine.

-- Steve

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Frederic Weisbecker]

On Mon, Feb 22, 2010 at 09:48:03AM -0500, Steven Rostedt wrote:
> On Sat, 2010-02-20 at 15:21 +0100, Frederic Weisbecker wrote:
> 
> > 
> > Actually why do we encumber with both tracing_thresh and the funcgraph-exit
> > option?
> > 
> > We could just have the output and the record check tracing_thresh instead
> > of the funcgraph-exit option.
> 
> You mean just use tracing_thresh during the tracing? We could perhaps
> also change the code (and I think this would be beneficial even without
> this change) to print the function on exit if it did not have a entry.
> 
> That is, in the reading of the trace, keep a depth pointer. For every
> "entry" we hit, we add one, and for every "exit" we subtract one (per
> cpu). If we go negative, we keep the counter at zero, but write
> something like:
> 
> 
>   } (sys_write)



Why not, looks like a good idea.


> 
> Because I always hate it when a trace starts with a bunch of "}" and I
> have no idea what functions they are. This would fix that.


Agreed.



> Yeah, Tim's trace would have only "} (sys_write)" type syntax but that's
> probably fine.



May be. Or we can couple your above solution and check if tracing_thresh > 0,
in which case we just zap the "}".

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Frederic Weisbecker]

On Wed, Feb 10, 2010 at 02:52:47PM -0800, Tim Bird wrote:
>  int trace_graph_entry(struct ftrace_graph_ent *trace)
>  {
>  	struct trace_array *tr = graph_array;
> @@ -221,6 +226,10 @@ int trace_graph_entry(struct ftrace_graph_ent *trace)
>  	if (!ftrace_graph_addr(trace->func))
>  		return 0;
>  
> +	/* if tracing duration, only save function exits (omit function entries in log) */
> +	if (tracing_thresh)
> +		return 1;
> +


Instead of having yet another check here, may be should we
have a dedicated stub trace_graph_entry?



> @@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array *tr,
>  	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
>  		return;
>  
> +	if (tracing_thresh &&
> +		(trace->rettime - trace->calltime < tracing_thresh))
> +		return;
> +



And perhaps we can do the same for the return handler?
We could have a trace_graph_return_threshold that
performs the above check and then relies on trace_graph_return.

Thanks.

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Steven Rostedt]

On Sat, 2010-02-20 at 15:43 +0100, Frederic Weisbecker wrote:
> 
> Instead of having yet another check here, may be should we
> have a dedicated stub trace_graph_entry?
> 
> 
> 
> > @@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array *tr,
> >  	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
> >  		return;
> >  
> > +	if (tracing_thresh &&
> > +		(trace->rettime - trace->calltime < tracing_thresh))
> > +		return;
> > +
> 
> 
> 
> And perhaps we can do the same for the return handler?
> We could have a trace_graph_return_threshold that
> performs the above check and then relies on trace_graph_return.

So you mean to register a different type of function to the graph tracer
if trace_thresh is enabled? That does sound like a better idea.

-- Steve

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Frederic Weisbecker]

On Mon, Feb 22, 2010 at 09:57:43AM -0500, Steven Rostedt wrote:
> On Sat, 2010-02-20 at 15:43 +0100, Frederic Weisbecker wrote:
> > 
> > Instead of having yet another check here, may be should we
> > have a dedicated stub trace_graph_entry?
> > 
> > 
> > 
> > > @@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array *tr,
> > >  	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
> > >  		return;
> > >  
> > > +	if (tracing_thresh &&
> > > +		(trace->rettime - trace->calltime < tracing_thresh))
> > > +		return;
> > > +
> > 
> > 
> > 
> > And perhaps we can do the same for the return handler?
> > We could have a trace_graph_return_threshold that
> > performs the above check and then relies on trace_graph_return.
> 
> So you mean to register a different type of function to the graph tracer
> if trace_thresh is enabled? That does sound like a better idea.


Yeah, this is going to optimize both types of tracing. And I would
also like to prevent from adding new checks in the common graph
tracing if possible. User's cpus and cachelines deserve better :)

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Tim Bird]

On 02/22/2010 10:17 AM, Frederic Weisbecker wrote:
> On Mon, Feb 22, 2010 at 09:57:43AM -0500, Steven Rostedt wrote:
>> On Sat, 2010-02-20 at 15:43 +0100, Frederic Weisbecker wrote:
>>>
>>> Instead of having yet another check here, may be should we
>>> have a dedicated stub trace_graph_entry?
>>>
>>>> @@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array *tr,
>>>>  	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
>>>>  		return;
>>>>
>>>> +	if (tracing_thresh &&
>>>> +		(trace->rettime - trace->calltime < tracing_thresh))
>>>> +		return;
>>>> +
>>>
>>>
>>>
>>> And perhaps we can do the same for the return handler?
>>> We could have a trace_graph_return_threshold that
>>> performs the above check and then relies on trace_graph_return.
>>
>> So you mean to register a different type of function to the graph tracer
>> if trace_thresh is enabled? That does sound like a better idea.
> 
> 
> Yeah, this is going to optimize both types of tracing. And I would
> also like to prevent from adding new checks in the common graph
> tracing if possible. User's cpus and cachelines deserve better :)

I'll take a look at doing it this way, and see what I come
up with.  If I can re-use most of trace_graph_entry and
trace_graph_return (and I don't see why not), it should be
a pretty small patch.

 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Steven Rostedt]

On Mon, 2010-02-22 at 17:18 -0800, Tim Bird wrote:

> > Yeah, this is going to optimize both types of tracing. And I would
> > also like to prevent from adding new checks in the common graph
> > tracing if possible. User's cpus and cachelines deserve better :)
> 
> I'll take a look at doing it this way, and see what I come
> up with.  If I can re-use most of trace_graph_entry and
> trace_graph_return (and I don't see why not), it should be
> a pretty small patch.

Yeah, I did something similar with the function pid tracing. When you
select that the function tracer should test pids, it registers the
function that does the pid test, and then if the pid matches, it calls
the original function tracer callback.

-- Steve

Re: [PATCH 1/1] ftrace - add support for tracing_thresh to function_graph tracer

[Steven Rostedt]

On Mon, 2010-02-22 at 17:18 -0800, Tim Bird wrote:
> On 02/22/2010 10:17 AM, Frederic Weisbecker wrote:
> > On Mon, Feb 22, 2010 at 09:57:43AM -0500, Steven Rostedt wrote:
> >> On Sat, 2010-02-20 at 15:43 +0100, Frederic Weisbecker wrote:
> >>>
> >>> Instead of having yet another check here, may be should we
> >>> have a dedicated stub trace_graph_entry?
> >>>
> >>>> @@ -254,6 +263,10 @@ static void __trace_graph_return(struct trace_array *tr,
> >>>>  	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
> >>>>  		return;
> >>>>
> >>>> +	if (tracing_thresh &&
> >>>> +		(trace->rettime - trace->calltime < tracing_thresh))
> >>>> +		return;
> >>>> +
> >>>
> >>>
> >>>
> >>> And perhaps we can do the same for the return handler?
> >>> We could have a trace_graph_return_threshold that
> >>> performs the above check and then relies on trace_graph_return.
> >>
> >> So you mean to register a different type of function to the graph tracer
> >> if trace_thresh is enabled? That does sound like a better idea.
> > 
> > 
> > Yeah, this is going to optimize both types of tracing. And I would
> > also like to prevent from adding new checks in the common graph
> > tracing if possible. User's cpus and cachelines deserve better :)
> 
> I'll take a look at doing it this way, and see what I come
> up with.  If I can re-use most of trace_graph_entry and
> trace_graph_return (and I don't see why not), it should be
> a pretty small patch.

If you can get this out quickly, it may still be able to make the merge
window.

-- Steve