| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-Id: <1265929831.2737.340.camel@localhost.localdomain>
Date: Thu, 11 Feb 2010 18:10:31 -0500
From: Steven Rostedt <srostedt@...hat.com>
To: Tim Bird <tim.bird@...sony.com>
Cc: linux kernel <linux-kernel@...r.kernel.org>,
Frederic Weisbecker <fweisbec@...il.com>
Subject: Re: [PATCH 1/1] ftrace - add support for tracing_thresh to
function_graph tracer
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@...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;
>
>
>
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists