* [PATCH 1/2] tracing/function-graph-tracer: various fixes and features
@ 2009-01-22 1:24 Frederic Weisbecker
2009-01-22 1:43 ` Steven Rostedt
0 siblings, 1 reply; 4+ messages in thread
From: Frederic Weisbecker @ 2009-01-22 1:24 UTC (permalink / raw)
To: Steven Rostedt
Cc: Ingo Molnar, Linux Kernel Mailing List, Frederic Weisbecker
I thought I would have the time to implement the callbacks in trace_event too but I
really have to sleep :-(
That will be for later.
--
This patch brings various bugfixes:
_ Drop the first irrelevant task switch on the very beginning of a trace.
But actually that only solves the first time one does print the trace file.
I have to fix the others cases too.
_ Drop the OVERHEAD word from the headers, the DURATION word is sufficient and will not
overlap other columns.
_ Make the headers fit well their respective columns whatever the selected options.
Ie, default options:
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
1) 0.646 us | }
1) | mem_cgroup_del_lru_list() {
1) 0.624 us | lookup_page_cgroup();
1) 1.970 us | }
echo funcgraph-proc > trace_options
# tracer: function_graph
#
# CPU TASK/PID DURATION FUNCTION CALLS
# | | | | | | | | |
0) bash-2937 | 0.895 us | }
0) bash-2937 | 0.888 us | __rcu_read_unlock();
0) bash-2937 | 0.864 us | conv_uni_to_pc();
0) bash-2937 | 1.015 us | __rcu_read_lock();
echo nofuncgraph-cpu > trace_options
echo nofuncgraph-proc > trace_options
# tracer: function_graph
#
# DURATION FUNCTION CALLS
# | | | | | |
3.752 us | native_pud_val();
0.616 us | native_pud_val();
0.624 us | native_pmd_val();
About features, one can now disable the duration (this will hide the overhead too
for convenient reasons and because on doesn't need overhead if it hasn't the duration
echo nofuncgraph-duration > trace_options
# tracer: function_graph
#
# FUNCTION CALLS
# | | | |
cap_vm_enough_memory() {
__vm_enough_memory() {
vm_acct_memory();
}
}
}
And at last, an option to print the absolute time:
//Restart from default options
echo funcgraph-abstime > trace_options
# tracer: function_graph
#
# TIME CPU DURATION FUNCTION CALLS
# | | | | | | | |
261.339774 | 1) + 42.823 us | }
261.339775 | 1) 1.045 us | _spin_lock_irq();
261.339777 | 1) 0.940 us | _spin_lock_irqsave();
261.339778 | 1) 0.752 us | _spin_unlock_irqrestore();
261.339780 | 1) 0.857 us | _spin_unlock_irq();
261.339782 | 1) | flush_to_ldisc() {
261.339783 | 1) | tty_ldisc_ref() {
261.339783 | 1) | tty_ldisc_try() {
261.339784 | 1) 1.075 us | _spin_lock_irqsave();
261.339786 | 1) 0.842 us | _spin_unlock_irqrestore();
261.339788 | 1) 4.211 us | }
261.339788 | 1) 5.662 us | }
The format is seconds.usecs
I guess no one needs the nanosec precision here, the main goal is to find when happened
the events on a cpu when the trace switches from one cpu to another.
ie:
274.874760 | 1) 0.676 us | _spin_unlock();
274.874762 | 1) 0.609 us | native_load_sp0();
274.874763 | 1) 0.602 us | native_load_tls();
274.878739 | 0) 0.722 us | }
274.878740 | 0) 0.714 us | native_pmd_val();
274.878741 | 0) 0.730 us | native_pmd_val();
Here there is a 4000 usecs difference when we switch the cpu.
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
kernel/trace/trace_functions_graph.c | 245 +++++++++++++++++++++-------------
1 files changed, 151 insertions(+), 94 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 3c54598..a65947c 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1,7 +1,7 @@
/*
*
* Function graph tracer.
- * Copyright (c) 2008 Frederic Weisbecker <fweisbec@gmail.com>
+ * Copyright (c) 2008-2009 Frederic Weisbecker <fweisbec@gmail.com>
* Mostly borrowed from function tracer which
* is Copyright (c) Steven Rostedt <srostedt@redhat.com>
*
@@ -21,9 +21,11 @@
#define TRACE_GRAPH_PRINT_CPU 0x2
#define TRACE_GRAPH_PRINT_OVERHEAD 0x4
#define TRACE_GRAPH_PRINT_PROC 0x8
+#define TRACE_GRAPH_PRINT_DURATION 0x10
+#define TRACE_GRAPH_PRINT_ABS_TIME 0X20
static struct tracer_opt trace_opts[] = {
- /* Display overruns ? */
+ /* Display overruns? (for self-debug purpose) */
{ TRACER_OPT(funcgraph-overrun, TRACE_GRAPH_PRINT_OVERRUN) },
/* Display CPU ? */
{ TRACER_OPT(funcgraph-cpu, TRACE_GRAPH_PRINT_CPU) },
@@ -31,12 +33,17 @@ static struct tracer_opt trace_opts[] = {
{ TRACER_OPT(funcgraph-overhead, TRACE_GRAPH_PRINT_OVERHEAD) },
/* Display proc name/pid */
{ TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
+ /* Display duration of execution */
+ { TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
+ /* Display absolute time of an entry */
+ { TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
{ } /* Empty entry */
};
static struct tracer_flags tracer_flags = {
/* Don't display overruns and proc by default */
- .val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD,
+ .val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
+ TRACE_GRAPH_PRINT_DURATION,
.opts = trace_opts
};
@@ -165,6 +172,8 @@ verif_pid(struct trace_seq *s, pid_t pid, int cpu)
prev_pid = last_pid[cpu];
last_pid[cpu] = pid;
+ if (prev_pid == -1)
+ return TRACE_TYPE_HANDLED;
/*
* Context-switch trace line:
@@ -232,9 +241,34 @@ trace_branch_is_leaf(struct trace_iterator *iter,
return true;
}
+/* Signal a overhead of time execution to the output */
+static int
+print_graph_overhead(unsigned long long duration, struct trace_seq *s)
+{
+ /* If duration disappear, we don't need anything */
+ if (!(tracer_flags.val & TRACE_GRAPH_PRINT_DURATION))
+ return 1;
+
+ /* Non nested entry or return */
+ if (duration == -1)
+ return trace_seq_printf(s, " ");
+
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
+ /* Duration exceeded 100 msecs */
+ if (duration > 100000ULL)
+ return trace_seq_printf(s, "! ");
+
+ /* Duration exceeded 10 msecs */
+ if (duration > 10000ULL)
+ return trace_seq_printf(s, "+ ");
+ }
+
+ return trace_seq_printf(s, " ");
+}
+
static enum print_line_t
print_graph_irq(struct trace_seq *s, unsigned long addr,
- enum trace_type type, int cpu, pid_t pid)
+ enum trace_type type, int cpu, pid_t pid)
{
int ret;
@@ -242,35 +276,40 @@ print_graph_irq(struct trace_seq *s, unsigned long addr,
addr >= (unsigned long)__irqentry_text_end)
return TRACE_TYPE_UNHANDLED;
- if (type == TRACE_GRAPH_ENT) {
- ret = trace_seq_printf(s, "==========> | ");
- } else {
- /* Cpu */
- if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
- ret = print_graph_cpu(s, cpu);
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
- }
- /* Proc */
- if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
- ret = print_graph_proc(s, pid);
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
+ /* Cpu */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
+ ret = print_graph_cpu(s, cpu);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
+ /* Proc */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
+ ret = print_graph_proc(s, pid);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ ret = trace_seq_printf(s, " | ");
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ /* No overhead */
+ ret = print_graph_overhead(-1, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
- /* No overhead */
- if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
- ret = trace_seq_printf(s, " ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ if (type == TRACE_GRAPH_ENT)
+ ret = trace_seq_printf(s, "==========>");
+ else
+ ret = trace_seq_printf(s, "<==========");
+
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ /* Don't close the duration column if haven't one */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
+ trace_seq_printf(s, " |");
+ ret = trace_seq_printf(s, "\n");
- ret = trace_seq_printf(s, "<========== |\n");
- }
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
return TRACE_TYPE_HANDLED;
@@ -289,7 +328,7 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s)
sprintf(msecs_str, "%lu", (unsigned long) duration);
/* Print msecs */
- ret = trace_seq_printf(s, msecs_str);
+ ret = trace_seq_printf(s, "%s", msecs_str);
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
@@ -322,19 +361,15 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s)
}
-/* Signal a overhead of time execution to the output */
-static int
-print_graph_overhead(unsigned long long duration, struct trace_seq *s)
+static int print_graph_abs_time(u64 t, struct trace_seq *s)
{
- /* Duration exceeded 100 msecs */
- if (duration > 100000ULL)
- return trace_seq_printf(s, "! ");
+ unsigned long usecs_rem;
- /* Duration exceeded 10 msecs */
- if (duration > 10000ULL)
- return trace_seq_printf(s, "+ ");
+ usecs_rem = do_div(t, 1000000000);
+ usecs_rem /= 1000;
- return trace_seq_printf(s, " ");
+ return trace_seq_printf(s, "%5lu.%06lu | ",
+ (unsigned long)t, usecs_rem);
}
/* Case of a leaf function on its call entry */
@@ -357,16 +392,16 @@ print_graph_entry_leaf(struct trace_iterator *iter,
duration = graph_ret->rettime - graph_ret->calltime;
/* Overhead */
- if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
- ret = print_graph_overhead(duration, s);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_overhead(duration, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
/* Duration */
- ret = print_graph_duration(duration, s);
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
+ ret = print_graph_duration(duration, s);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
/* Function */
for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
@@ -395,25 +430,17 @@ print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
struct ftrace_graph_ent *call = &entry->graph_ent;
/* No overhead */
- if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
- ret = trace_seq_printf(s, " ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_overhead(-1, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
- /* Interrupt */
- ret = print_graph_irq(s, call->func, TRACE_GRAPH_ENT, cpu, pid);
- if (ret == TRACE_TYPE_UNHANDLED) {
- /* No time */
+ /* No time */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
ret = trace_seq_printf(s, " | ");
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
- } else {
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
}
-
/* Function */
for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
ret = trace_seq_printf(s, " ");
@@ -434,15 +461,29 @@ print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
- struct trace_iterator *iter, int cpu)
+ struct trace_iterator *iter)
{
int ret;
+ int cpu = iter->cpu;
struct trace_entry *ent = iter->ent;
+ struct ftrace_graph_ent *call = &field->graph_ent;
/* Pid */
if (verif_pid(s, ent->pid, cpu) == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
+ /* Interrupt */
+ ret = print_graph_irq(s, call->func, TRACE_GRAPH_ENT, cpu, ent->pid);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ /* Absolute time */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
+ ret = print_graph_abs_time(iter->ts, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
+
/* Cpu */
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
ret = print_graph_cpu(s, cpu);
@@ -470,16 +511,24 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
- struct trace_entry *ent, int cpu)
+ struct trace_entry *ent, struct trace_iterator *iter)
{
int i;
int ret;
+ int cpu = iter->cpu;
unsigned long long duration = trace->rettime - trace->calltime;
/* Pid */
if (verif_pid(s, ent->pid, cpu) == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
+ /* Absolute time */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
+ ret = print_graph_abs_time(iter->ts, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
+
/* Cpu */
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
ret = print_graph_cpu(s, cpu);
@@ -499,16 +548,16 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
}
/* Overhead */
- if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
- ret = print_graph_overhead(duration, s);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_overhead(duration, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
/* Duration */
- ret = print_graph_duration(duration, s);
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
+ ret = print_graph_duration(duration, s);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
/* Closing brace */
for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
@@ -543,6 +592,13 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
int i;
int ret;
+ /* Absolute time */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
+ ret = print_graph_abs_time(iter->ts, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
+
/* Pid */
if (verif_pid(s, ent->pid, iter->cpu) == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
@@ -566,17 +622,17 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
}
/* No overhead */
- if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
- ret = trace_seq_printf(s, " ");
+ ret = print_graph_overhead(-1, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ /* No time */
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
+ ret = trace_seq_printf(s, " | ");
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
}
- /* No time */
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* Indentation */
if (trace->depth > 0)
for (i = 0; i < (trace->depth + 1) * TRACE_GRAPH_INDENT; i++) {
@@ -614,13 +670,12 @@ print_graph_function(struct trace_iterator *iter)
case TRACE_GRAPH_ENT: {
struct ftrace_graph_ent_entry *field;
trace_assign_type(field, entry);
- return print_graph_entry(field, s, iter,
- iter->cpu);
+ return print_graph_entry(field, s, iter);
}
case TRACE_GRAPH_RET: {
struct ftrace_graph_ret_entry *field;
trace_assign_type(field, entry);
- return print_graph_return(&field->ret, s, entry, iter->cpu);
+ return print_graph_return(&field->ret, s, entry, iter);
}
case TRACE_PRINT: {
struct print_entry *field;
@@ -636,25 +691,27 @@ static void print_graph_headers(struct seq_file *s)
{
/* 1st line */
seq_printf(s, "# ");
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
+ seq_printf(s, " TIME ");
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
- seq_printf(s, "CPU ");
+ seq_printf(s, "CPU");
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
- seq_printf(s, "TASK/PID ");
- if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD)
- seq_printf(s, "OVERHEAD/");
- seq_printf(s, "DURATION FUNCTION CALLS\n");
+ seq_printf(s, " TASK/PID ");
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
+ seq_printf(s, " DURATION ");
+ seq_printf(s, " FUNCTION CALLS\n");
/* 2nd line */
seq_printf(s, "# ");
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
+ seq_printf(s, " | ");
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
- seq_printf(s, "| ");
+ seq_printf(s, "| ");
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
- seq_printf(s, "| | ");
- if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
- seq_printf(s, "| ");
- seq_printf(s, "| | | | |\n");
- } else
- seq_printf(s, " | | | | |\n");
+ seq_printf(s, " | | ");
+ if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
+ seq_printf(s, " | | ");
+ seq_printf(s, " | | | |\n");
}
static struct tracer graph_trace __read_mostly = {
.name = "function_graph",
--
1.6.0.4
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH 1/2] tracing/function-graph-tracer: various fixes and features
2009-01-22 1:24 [PATCH 1/2] tracing/function-graph-tracer: various fixes and features Frederic Weisbecker
@ 2009-01-22 1:43 ` Steven Rostedt
2009-01-22 9:02 ` Frederic Weisbecker
2009-01-22 9:33 ` Ingo Molnar
0 siblings, 2 replies; 4+ messages in thread
From: Steven Rostedt @ 2009-01-22 1:43 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Ingo Molnar, Linux Kernel Mailing List
On Wed, 21 Jan 2009, Frederic Weisbecker wrote:
> I thought I would have the time to implement the callbacks in trace_event too but I
> really have to sleep :-(
> That will be for later.
No need to rush. Get to sleep.
> --
>
> This patch brings various bugfixes:
>
> _ Drop the first irrelevant task switch on the very beginning of a trace.
> But actually that only solves the first time one does print the trace file.
> I have to fix the others cases too.
I'm not sure what you mean by the first time here. Can you explain it
a bit better.
> _ Drop the OVERHEAD word from the headers, the DURATION word is sufficient and will not
> overlap other columns.
> _ Make the headers fit well their respective columns whatever the selected options.
>
> Ie, default options:
>
> # tracer: function_graph
> #
> # CPU DURATION FUNCTION CALLS
> # | | | | | | |
>
> 1) 0.646 us | }
> 1) | mem_cgroup_del_lru_list() {
> 1) 0.624 us | lookup_page_cgroup();
> 1) 1.970 us | }
>
> echo funcgraph-proc > trace_options
>
> # tracer: function_graph
> #
> # CPU TASK/PID DURATION FUNCTION CALLS
> # | | | | | | | | |
>
> 0) bash-2937 | 0.895 us | }
> 0) bash-2937 | 0.888 us | __rcu_read_unlock();
> 0) bash-2937 | 0.864 us | conv_uni_to_pc();
> 0) bash-2937 | 1.015 us | __rcu_read_lock();
>
> echo nofuncgraph-cpu > trace_options
> echo nofuncgraph-proc > trace_options
>
> # tracer: function_graph
> #
> # DURATION FUNCTION CALLS
> # | | | | | |
>
> 3.752 us | native_pud_val();
> 0.616 us | native_pud_val();
> 0.624 us | native_pmd_val();
>
>
> About features, one can now disable the duration (this will hide the overhead too
> for convenient reasons and because on doesn't need overhead if it hasn't the duration
>
> echo nofuncgraph-duration > trace_options
>
> # tracer: function_graph
> #
> # FUNCTION CALLS
> # | | | |
>
> cap_vm_enough_memory() {
> __vm_enough_memory() {
> vm_acct_memory();
> }
> }
> }
>
> And at last, an option to print the absolute time:
>
> //Restart from default options
> echo funcgraph-abstime > trace_options
>
> # tracer: function_graph
> #
> # TIME CPU DURATION FUNCTION CALLS
> # | | | | | | | |
>
> 261.339774 | 1) + 42.823 us | }
> 261.339775 | 1) 1.045 us | _spin_lock_irq();
> 261.339777 | 1) 0.940 us | _spin_lock_irqsave();
> 261.339778 | 1) 0.752 us | _spin_unlock_irqrestore();
> 261.339780 | 1) 0.857 us | _spin_unlock_irq();
> 261.339782 | 1) | flush_to_ldisc() {
> 261.339783 | 1) | tty_ldisc_ref() {
> 261.339783 | 1) | tty_ldisc_try() {
> 261.339784 | 1) 1.075 us | _spin_lock_irqsave();
> 261.339786 | 1) 0.842 us | _spin_unlock_irqrestore();
> 261.339788 | 1) 4.211 us | }
> 261.339788 | 1) 5.662 us | }
>
> The format is seconds.usecs
> I guess no one needs the nanosec precision here, the main goal is to find when happened
> the events on a cpu when the trace switches from one cpu to another.
>
> ie:
>
> 274.874760 | 1) 0.676 us | _spin_unlock();
> 274.874762 | 1) 0.609 us | native_load_sp0();
> 274.874763 | 1) 0.602 us | native_load_tls();
> 274.878739 | 0) 0.722 us | }
> 274.878740 | 0) 0.714 us | native_pmd_val();
> 274.878741 | 0) 0.730 us | native_pmd_val();
>
> Here there is a 4000 usecs difference when we switch the cpu.
These examples will most likely be cut from the change log. Updating
ftrace.txt would be nice ;-)
>
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
> kernel/trace/trace_functions_graph.c | 245 +++++++++++++++++++++-------------
> 1 files changed, 151 insertions(+), 94 deletions(-)
>
-- Steve
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH 1/2] tracing/function-graph-tracer: various fixes and features
2009-01-22 1:43 ` Steven Rostedt
@ 2009-01-22 9:02 ` Frederic Weisbecker
2009-01-22 9:33 ` Ingo Molnar
1 sibling, 0 replies; 4+ messages in thread
From: Frederic Weisbecker @ 2009-01-22 9:02 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Ingo Molnar, Linux Kernel Mailing List
On Wed, Jan 21, 2009 at 08:43:24PM -0500, Steven Rostedt wrote:
>
> On Wed, 21 Jan 2009, Frederic Weisbecker wrote:
>
> > I thought I would have the time to implement the callbacks in trace_event too but I
> > really have to sleep :-(
> > That will be for later.
>
> No need to rush. Get to sleep.
>
> > --
> >
> > This patch brings various bugfixes:
> >
> > _ Drop the first irrelevant task switch on the very beginning of a trace.
> > But actually that only solves the first time one does print the trace file.
> > I have to fix the others cases too.
>
> I'm not sure what you mean by the first time here. Can you explain it
> a bit better.
On the very first time one cat the trace file, the per cpu pid array is init to -1.
So the comparison between the current pid and the previous one (-1) is always false
and then a task switch is printed.
This one is fixed.
The other cases are when one cat the trace file after closing it.
The pid array is not anymore filled with -1 values but with old traced pid, and then
a task switch is printed here too.
I will have to hook on open and reset the pid table to -1 to fix that.
> > _ Drop the OVERHEAD word from the headers, the DURATION word is sufficient and will not
> > overlap other columns.
> > _ Make the headers fit well their respective columns whatever the selected options.
> >
> > Ie, default options:
> >
> > # tracer: function_graph
> > #
> > # CPU DURATION FUNCTION CALLS
> > # | | | | | | |
> >
> > 1) 0.646 us | }
> > 1) | mem_cgroup_del_lru_list() {
> > 1) 0.624 us | lookup_page_cgroup();
> > 1) 1.970 us | }
> >
> > echo funcgraph-proc > trace_options
> >
> > # tracer: function_graph
> > #
> > # CPU TASK/PID DURATION FUNCTION CALLS
> > # | | | | | | | | |
> >
> > 0) bash-2937 | 0.895 us | }
> > 0) bash-2937 | 0.888 us | __rcu_read_unlock();
> > 0) bash-2937 | 0.864 us | conv_uni_to_pc();
> > 0) bash-2937 | 1.015 us | __rcu_read_lock();
> >
> > echo nofuncgraph-cpu > trace_options
> > echo nofuncgraph-proc > trace_options
> >
> > # tracer: function_graph
> > #
> > # DURATION FUNCTION CALLS
> > # | | | | | |
> >
> > 3.752 us | native_pud_val();
> > 0.616 us | native_pud_val();
> > 0.624 us | native_pmd_val();
> >
> >
> > About features, one can now disable the duration (this will hide the overhead too
> > for convenient reasons and because on doesn't need overhead if it hasn't the duration
> >
> > echo nofuncgraph-duration > trace_options
> >
> > # tracer: function_graph
> > #
> > # FUNCTION CALLS
> > # | | | |
> >
> > cap_vm_enough_memory() {
> > __vm_enough_memory() {
> > vm_acct_memory();
> > }
> > }
> > }
> >
> > And at last, an option to print the absolute time:
> >
> > //Restart from default options
> > echo funcgraph-abstime > trace_options
> >
> > # tracer: function_graph
> > #
> > # TIME CPU DURATION FUNCTION CALLS
> > # | | | | | | | |
> >
> > 261.339774 | 1) + 42.823 us | }
> > 261.339775 | 1) 1.045 us | _spin_lock_irq();
> > 261.339777 | 1) 0.940 us | _spin_lock_irqsave();
> > 261.339778 | 1) 0.752 us | _spin_unlock_irqrestore();
> > 261.339780 | 1) 0.857 us | _spin_unlock_irq();
> > 261.339782 | 1) | flush_to_ldisc() {
> > 261.339783 | 1) | tty_ldisc_ref() {
> > 261.339783 | 1) | tty_ldisc_try() {
> > 261.339784 | 1) 1.075 us | _spin_lock_irqsave();
> > 261.339786 | 1) 0.842 us | _spin_unlock_irqrestore();
> > 261.339788 | 1) 4.211 us | }
> > 261.339788 | 1) 5.662 us | }
> >
> > The format is seconds.usecs
> > I guess no one needs the nanosec precision here, the main goal is to find when happened
> > the events on a cpu when the trace switches from one cpu to another.
> >
> > ie:
> >
> > 274.874760 | 1) 0.676 us | _spin_unlock();
> > 274.874762 | 1) 0.609 us | native_load_sp0();
> > 274.874763 | 1) 0.602 us | native_load_tls();
> > 274.878739 | 0) 0.722 us | }
> > 274.878740 | 0) 0.714 us | native_pmd_val();
> > 274.878741 | 0) 0.730 us | native_pmd_val();
> >
> > Here there is a 4000 usecs difference when we switch the cpu.
>
> These examples will most likely be cut from the change log. Updating
> ftrace.txt would be nice ;-)
Yes, definetly. I didn't drop my hands into this yet because of my
messy english :-)
But I know some people who could review it :-)
> >
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > ---
> > kernel/trace/trace_functions_graph.c | 245 +++++++++++++++++++++-------------
> > 1 files changed, 151 insertions(+), 94 deletions(-)
> >
>
> -- Steve
>
Thanks.
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH 1/2] tracing/function-graph-tracer: various fixes and features
2009-01-22 1:43 ` Steven Rostedt
2009-01-22 9:02 ` Frederic Weisbecker
@ 2009-01-22 9:33 ` Ingo Molnar
1 sibling, 0 replies; 4+ messages in thread
From: Ingo Molnar @ 2009-01-22 9:33 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Frederic Weisbecker, Linux Kernel Mailing List
* Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 21 Jan 2009, Frederic Weisbecker wrote:
>
> > I thought I would have the time to implement the callbacks in trace_event too but I
> > really have to sleep :-(
> > That will be for later.
>
> No need to rush. Get to sleep.
>
> > --
> >
> > This patch brings various bugfixes:
> >
> > _ Drop the first irrelevant task switch on the very beginning of a trace.
> > But actually that only solves the first time one does print the trace file.
> > I have to fix the others cases too.
>
> I'm not sure what you mean by the first time here. Can you explain it
> a bit better.
>
> > _ Drop the OVERHEAD word from the headers, the DURATION word is sufficient and will not
> > overlap other columns.
> > _ Make the headers fit well their respective columns whatever the selected options.
> >
> > Ie, default options:
> >
> > # tracer: function_graph
> > #
> > # CPU DURATION FUNCTION CALLS
> > # | | | | | | |
> >
> > 1) 0.646 us | }
> > 1) | mem_cgroup_del_lru_list() {
> > 1) 0.624 us | lookup_page_cgroup();
> > 1) 1.970 us | }
> >
> > echo funcgraph-proc > trace_options
> >
> > # tracer: function_graph
> > #
> > # CPU TASK/PID DURATION FUNCTION CALLS
> > # | | | | | | | | |
> >
> > 0) bash-2937 | 0.895 us | }
> > 0) bash-2937 | 0.888 us | __rcu_read_unlock();
> > 0) bash-2937 | 0.864 us | conv_uni_to_pc();
> > 0) bash-2937 | 1.015 us | __rcu_read_lock();
> >
> > echo nofuncgraph-cpu > trace_options
> > echo nofuncgraph-proc > trace_options
> >
> > # tracer: function_graph
> > #
> > # DURATION FUNCTION CALLS
> > # | | | | | |
> >
> > 3.752 us | native_pud_val();
> > 0.616 us | native_pud_val();
> > 0.624 us | native_pmd_val();
> >
> >
> > About features, one can now disable the duration (this will hide the overhead too
> > for convenient reasons and because on doesn't need overhead if it hasn't the duration
> >
> > echo nofuncgraph-duration > trace_options
> >
> > # tracer: function_graph
> > #
> > # FUNCTION CALLS
> > # | | | |
> >
> > cap_vm_enough_memory() {
> > __vm_enough_memory() {
> > vm_acct_memory();
> > }
> > }
> > }
> >
> > And at last, an option to print the absolute time:
> >
> > //Restart from default options
> > echo funcgraph-abstime > trace_options
> >
> > # tracer: function_graph
> > #
> > # TIME CPU DURATION FUNCTION CALLS
> > # | | | | | | | |
> >
> > 261.339774 | 1) + 42.823 us | }
> > 261.339775 | 1) 1.045 us | _spin_lock_irq();
> > 261.339777 | 1) 0.940 us | _spin_lock_irqsave();
> > 261.339778 | 1) 0.752 us | _spin_unlock_irqrestore();
> > 261.339780 | 1) 0.857 us | _spin_unlock_irq();
> > 261.339782 | 1) | flush_to_ldisc() {
> > 261.339783 | 1) | tty_ldisc_ref() {
> > 261.339783 | 1) | tty_ldisc_try() {
> > 261.339784 | 1) 1.075 us | _spin_lock_irqsave();
> > 261.339786 | 1) 0.842 us | _spin_unlock_irqrestore();
> > 261.339788 | 1) 4.211 us | }
> > 261.339788 | 1) 5.662 us | }
> >
> > The format is seconds.usecs
> > I guess no one needs the nanosec precision here, the main goal is to find when happened
> > the events on a cpu when the trace switches from one cpu to another.
> >
> > ie:
> >
> > 274.874760 | 1) 0.676 us | _spin_unlock();
> > 274.874762 | 1) 0.609 us | native_load_sp0();
> > 274.874763 | 1) 0.602 us | native_load_tls();
> > 274.878739 | 0) 0.722 us | }
> > 274.878740 | 0) 0.714 us | native_pmd_val();
> > 274.878741 | 0) 0.730 us | native_pmd_val();
> >
> > Here there is a 4000 usecs difference when we switch the cpu.
>
> These examples will most likely be cut from the change log. Updating
> ftrace.txt would be nice ;-)
Updating ftrace.txt is definitely a good idea, but also, please dont cut
such examples from changelogs ... i keep them most of the time, they are
really useful.
Ingo
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2009-01-22 9:33 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2009-01-22 1:24 [PATCH 1/2] tracing/function-graph-tracer: various fixes and features Frederic Weisbecker
2009-01-22 1:43 ` Steven Rostedt
2009-01-22 9:02 ` Frederic Weisbecker
2009-01-22 9:33 ` Ingo Molnar
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox