* [PATCH 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency
2011-06-03 14:19 [PATCH 0/5] tracing, function, graph: Fixies for field display Jiri Olsa
@ 2011-06-03 14:19 ` Jiri Olsa
2011-06-03 14:20 ` [PATCH 2/5] tracing, function_graph: Merge overhead and duration display functions Jiri Olsa
` (4 subsequent siblings)
5 siblings, 0 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:19 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The display of absolute time and duration fields is based on the
latency field. This was added during the irqsoff/wakeup tracers
graph support changes.
It's causing confusion in what fields will be displayed for the
function_graph tracer itself. So I'm removing this depency, and
adding absolute time and duration fields to the irqsoff/wakeup
tracers.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 19 +++----------------
kernel/trace/trace_irqsoff.c | 4 +++-
kernel/trace/trace_sched_wakeup.c | 4 +++-
3 files changed, 9 insertions(+), 18 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 962cdb2..352652e 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1207,7 +1207,7 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
enum print_line_t
-__print_graph_function_flags(struct trace_iterator *iter, u32 flags)
+print_graph_function_flags(struct trace_iterator *iter, u32 flags)
{
struct ftrace_graph_ent_entry *field;
struct fgraph_data *data = iter->private;
@@ -1270,18 +1270,7 @@ __print_graph_function_flags(struct trace_iterator *iter, u32 flags)
static enum print_line_t
print_graph_function(struct trace_iterator *iter)
{
- return __print_graph_function_flags(iter, tracer_flags.val);
-}
-
-enum print_line_t print_graph_function_flags(struct trace_iterator *iter,
- u32 flags)
-{
- if (trace_flags & TRACE_ITER_LATENCY_FMT)
- flags |= TRACE_GRAPH_PRINT_DURATION;
- else
- flags |= TRACE_GRAPH_PRINT_ABS_TIME;
-
- return __print_graph_function_flags(iter, flags);
+ return print_graph_function_flags(iter, tracer_flags.val);
}
static enum print_line_t
@@ -1364,9 +1353,7 @@ void print_graph_headers_flags(struct seq_file *s, u32 flags)
return;
print_trace_header(s, iter);
- flags |= TRACE_GRAPH_PRINT_DURATION;
- } else
- flags |= TRACE_GRAPH_PRINT_ABS_TIME;
+ }
__print_graph_headers_flags(s, flags);
}
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index c77424b..667aa8c 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -226,7 +226,9 @@ static void irqsoff_trace_close(struct trace_iterator *iter)
}
#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
- TRACE_GRAPH_PRINT_PROC)
+ TRACE_GRAPH_PRINT_PROC | \
+ TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
{
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index f029dd4..e4a70c0 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -227,7 +227,9 @@ static void wakeup_trace_close(struct trace_iterator *iter)
graph_trace_close(iter);
}
-#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_PROC)
+#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_PROC | \
+ TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
{
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [PATCH 2/5] tracing, function_graph: Merge overhead and duration display functions
2011-06-03 14:19 [PATCH 0/5] tracing, function, graph: Fixies for field display Jiri Olsa
2011-06-03 14:19 ` [PATCH 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency Jiri Olsa
@ 2011-06-03 14:20 ` Jiri Olsa
2011-06-03 14:20 ` [PATCH 3/5] tracing, function: Fix trace header to follow context-info option Jiri Olsa
` (3 subsequent siblings)
5 siblings, 0 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:20 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
Functions print_graph_overhead and print_graph_duration displays
data for one field - DURATION.
I merged them into single function print_graph_duration,
and added way to display empty parts of the field.
This way the print_graph_irq function can use this column to display
the IRQ signs if needed and the DURATION field details stays inside
the print_graph_duration function.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 148 +++++++++++++++++-----------------
1 files changed, 74 insertions(+), 74 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 352652e..44b955f 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -74,6 +74,20 @@ static struct tracer_flags tracer_flags = {
static struct trace_array *graph_array;
+/*
+ * DURATION column is being also used to display IRQ signs,
+ * following values are used by print_graph_irq and others
+ * to fill in space into DURATION column.
+ */
+enum {
+ DURATION_FILL_FULL = -1,
+ DURATION_FILL_START = -2,
+ DURATION_FILL_END = -3,
+};
+
+static enum print_line_t
+print_graph_duration(unsigned long long duration, struct trace_seq *s,
+ u32 flags);
/* Add a function return address to the trace stack on thread info.*/
int
@@ -577,32 +591,6 @@ get_return_for_leaf(struct trace_iterator *iter,
return next;
}
-/* Signal a overhead of time execution to the output */
-static int
-print_graph_overhead(unsigned long long duration, struct trace_seq *s,
- u32 flags)
-{
- /* If duration disappear, we don't need anything */
- if (!(flags & TRACE_GRAPH_PRINT_DURATION))
- return 1;
-
- /* Non nested entry or return */
- if (duration == -1)
- return trace_seq_printf(s, " ");
-
- if (flags & 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 int print_graph_abs_time(u64 t, struct trace_seq *s)
{
unsigned long usecs_rem;
@@ -650,9 +638,9 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
}
/* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
+ ret = print_graph_duration(DURATION_FILL_START, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
if (type == TRACE_GRAPH_ENT)
ret = trace_seq_printf(s, "==========>");
@@ -662,9 +650,10 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
- /* Don't close the duration column if haven't one */
- if (flags & TRACE_GRAPH_PRINT_DURATION)
- trace_seq_printf(s, " |");
+ ret = print_graph_duration(DURATION_FILL_END, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
+
ret = trace_seq_printf(s, "\n");
if (!ret)
@@ -716,9 +705,48 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
}
static enum print_line_t
-print_graph_duration(unsigned long long duration, struct trace_seq *s)
+print_graph_duration(unsigned long long duration, struct trace_seq *s,
+ u32 flags)
{
- int ret;
+ int ret = -1;
+
+ if (!(flags & TRACE_GRAPH_PRINT_DURATION))
+ return TRACE_TYPE_HANDLED;
+
+ /* No real adata, just filling the column with spaces */
+ switch (duration) {
+ case DURATION_FILL_FULL:
+ ret = trace_seq_printf(s, " | ");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ case DURATION_FILL_START:
+ ret = trace_seq_printf(s, " ");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ case DURATION_FILL_END:
+ ret = trace_seq_printf(s, " |");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ }
+
+ /* Signal a overhead of time execution to the output */
+ if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
+ /* Duration exceeded 100 msecs */
+ if (duration > 100000ULL)
+ ret = trace_seq_printf(s, "! ");
+ /* Duration exceeded 10 msecs */
+ else if (duration > 10000ULL)
+ ret = trace_seq_printf(s, "+ ");
+ }
+
+ /*
+ * The -1 means we either did not exceed the duration tresholds
+ * or we dont want to print out the overhead. Either way we need
+ * to fill out the space.
+ */
+ if (ret == -1)
+ ret = trace_seq_printf(s, " ");
+
+ /* Catching here any failure happenned above */
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
ret = trace_print_graph_duration(duration, s);
if (ret != TRACE_TYPE_HANDLED)
@@ -767,18 +795,11 @@ print_graph_entry_leaf(struct trace_iterator *iter,
cpu_data->enter_funcs[call->depth] = 0;
}
- /* Overhead */
- ret = print_graph_overhead(duration, s, flags);
- if (!ret)
+ /* Overhead and duration */
+ ret = print_graph_duration(duration, s, flags);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
- /* Duration */
- if (flags & 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++) {
ret = trace_seq_printf(s, " ");
@@ -815,17 +836,10 @@ print_graph_entry_nested(struct trace_iterator *iter,
cpu_data->enter_funcs[call->depth] = call->func;
}
- /* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* No time */
- if (flags & TRACE_GRAPH_PRINT_DURATION) {
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
/* Function */
for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
@@ -1078,18 +1092,11 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
if (print_graph_prologue(iter, s, 0, 0, flags))
return TRACE_TYPE_PARTIAL_LINE;
- /* Overhead */
- ret = print_graph_overhead(duration, s, flags);
- if (!ret)
+ /* Overhead and duration */
+ ret = print_graph_duration(duration, s, flags);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
- /* Duration */
- if (flags & 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++) {
ret = trace_seq_printf(s, " ");
@@ -1146,17 +1153,10 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
if (print_graph_prologue(iter, s, 0, 0, flags))
return TRACE_TYPE_PARTIAL_LINE;
- /* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* No time */
- if (flags & TRACE_GRAPH_PRINT_DURATION) {
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
/* Indentation */
if (depth > 0)
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [PATCH 3/5] tracing, function: Fix trace header to follow context-info option
2011-06-03 14:19 [PATCH 0/5] tracing, function, graph: Fixies for field display Jiri Olsa
2011-06-03 14:19 ` [PATCH 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency Jiri Olsa
2011-06-03 14:20 ` [PATCH 2/5] tracing, function_graph: Merge overhead and duration display functions Jiri Olsa
@ 2011-06-03 14:20 ` Jiri Olsa
2011-06-03 14:20 ` [PATCH 4/5] tracing, function_graph: Remove lock-depth from latency trace Jiri Olsa
` (2 subsequent siblings)
5 siblings, 0 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:20 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The header display of function tracer does not follow
the context-info option, so field names are displayed even
if this option is off.
Added check for TRACE_ITER_CONTEXT_INFO trace_flags.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace.c | 3 +++
1 files changed, 3 insertions(+), 0 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ee9c921..01fc8d7 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2051,6 +2051,9 @@ void trace_default_header(struct seq_file *m)
{
struct trace_iterator *iter = m->private;
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return;
+
if (iter->iter_flags & TRACE_FILE_LAT_FMT) {
/* print nothing if the buffers are empty */
if (trace_empty(iter))
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [PATCH 4/5] tracing, function_graph: Remove lock-depth from latency trace
2011-06-03 14:19 [PATCH 0/5] tracing, function, graph: Fixies for field display Jiri Olsa
` (2 preceding siblings ...)
2011-06-03 14:20 ` [PATCH 3/5] tracing, function: Fix trace header to follow context-info option Jiri Olsa
@ 2011-06-03 14:20 ` Jiri Olsa
2011-06-03 14:20 ` [PATCH 5/5] tracing, function_graph: Add context-info support for function_graph tracer Jiri Olsa
2011-06-03 14:26 ` [PATCH 0/5] tracing, function, graph: Fixies for field display Steven Rostedt
5 siblings, 0 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:20 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The lock_depth was removed in commit
e6e1e25 tracing: Remove lock_depth from event entry
Removing the lock_depth info from function_graph latency header.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 7 +++----
1 files changed, 3 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 44b955f..1da5b97 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1298,8 +1298,7 @@ static void print_lat_header(struct seq_file *s, u32 flags)
seq_printf(s, "#%.*s / _----=> need-resched \n", size, spaces);
seq_printf(s, "#%.*s| / _---=> hardirq/softirq \n", size, spaces);
seq_printf(s, "#%.*s|| / _--=> preempt-depth \n", size, spaces);
- seq_printf(s, "#%.*s||| / _-=> lock-depth \n", size, spaces);
- seq_printf(s, "#%.*s|||| / \n", size, spaces);
+ seq_printf(s, "#%.*s||| / \n", size, spaces);
}
static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
@@ -1318,7 +1317,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
if (flags & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " TASK/PID ");
if (lat)
- seq_printf(s, "|||||");
+ seq_printf(s, "||||");
if (flags & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " DURATION ");
seq_printf(s, " FUNCTION CALLS\n");
@@ -1332,7 +1331,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
if (flags & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " | | ");
if (lat)
- seq_printf(s, "|||||");
+ seq_printf(s, "||||");
if (flags & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " | | ");
seq_printf(s, " | | | |\n");
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [PATCH 5/5] tracing, function_graph: Add context-info support for function_graph tracer
2011-06-03 14:19 [PATCH 0/5] tracing, function, graph: Fixies for field display Jiri Olsa
` (3 preceding siblings ...)
2011-06-03 14:20 ` [PATCH 4/5] tracing, function_graph: Remove lock-depth from latency trace Jiri Olsa
@ 2011-06-03 14:20 ` Jiri Olsa
2011-06-03 14:26 ` [PATCH 0/5] tracing, function, graph: Fixies for field display Steven Rostedt
5 siblings, 0 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:20 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The function_graph tracer does not follow global context-info option.
Adding TRACE_ITER_CONTEXT_INFO trace_flags check to enable it.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 53 ++++++++++++++++++++--------------
1 files changed, 31 insertions(+), 22 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 1da5b97..e8d6bb5 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -613,28 +613,30 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
addr >= (unsigned long)__irqentry_text_end)
return TRACE_TYPE_UNHANDLED;
- /* Absolute time */
- if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
- ret = print_graph_abs_time(iter->ts, s);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
+ /* Absolute time */
+ if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
+ ret = print_graph_abs_time(iter->ts, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
- /* Cpu */
- if (flags & TRACE_GRAPH_PRINT_CPU) {
- ret = print_graph_cpu(s, cpu);
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ /* Cpu */
+ if (flags & TRACE_GRAPH_PRINT_CPU) {
+ ret = print_graph_cpu(s, cpu);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
- /* Proc */
- if (flags & 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;
+ /* Proc */
+ if (flags & 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;
+ }
}
/* No overhead */
@@ -710,8 +712,9 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,
{
int ret = -1;
- if (!(flags & TRACE_GRAPH_PRINT_DURATION))
- return TRACE_TYPE_HANDLED;
+ if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
+ !(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return TRACE_TYPE_HANDLED;
/* No real adata, just filling the column with spaces */
switch (duration) {
@@ -879,6 +882,9 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return 0;
+
/* Absolute time */
if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
ret = print_graph_abs_time(iter->ts, s);
@@ -1346,6 +1352,9 @@ void print_graph_headers_flags(struct seq_file *s, u32 flags)
{
struct trace_iterator *iter = s->private;
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return;
+
if (trace_flags & TRACE_ITER_LATENCY_FMT) {
/* print nothing if the buffers are empty */
if (trace_empty(iter))
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* Re: [PATCH 0/5] tracing, function, graph: Fixies for field display
2011-06-03 14:19 [PATCH 0/5] tracing, function, graph: Fixies for field display Jiri Olsa
` (4 preceding siblings ...)
2011-06-03 14:20 ` [PATCH 5/5] tracing, function_graph: Add context-info support for function_graph tracer Jiri Olsa
@ 2011-06-03 14:26 ` Steven Rostedt
2011-06-03 14:53 ` Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 " Jiri Olsa
5 siblings, 2 replies; 20+ messages in thread
From: Steven Rostedt @ 2011-06-03 14:26 UTC (permalink / raw)
To: Jiri Olsa; +Cc: fweisbec, mingo, linux-kernel
On Fri, 2011-06-03 at 16:19 +0200, Jiri Olsa wrote:
> hi,
>
> this patchset contains some fixies of trace output for
> function and function_graph tracers.
>
> attached patches:
> 1/5 tracing, function_graph: Remove dependency of abstime and duration fields on latency
> 2/5 tracing, function_graph: Merge overhead and duration display functions
> 3/5 tracing, function: Fix trace header to follow context-info option
> 4/5 tracing, function_graph: Remove lock-depth from latency trace
> 5/5 tracing, function_graph: Add context-info support for function_graph tracer
Hi Jiri,
Thanks for these patches. But could you change the change logs to show
the problems that you see. Just a description does not express what is
really wrong. Basically add a:
This is what it looked like before:
....
This is what it looks like now:
....
That way it is obvious what the patches do. I'll test these anyway to
get a before and after, but it is helpful to see it in the change log.
Thanks,
-- Steve
^ permalink raw reply [flat|nested] 20+ messages in thread* Re: [PATCH 0/5] tracing, function, graph: Fixies for field display
2011-06-03 14:26 ` [PATCH 0/5] tracing, function, graph: Fixies for field display Steven Rostedt
@ 2011-06-03 14:53 ` Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 " Jiri Olsa
1 sibling, 0 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:53 UTC (permalink / raw)
To: Steven Rostedt; +Cc: fweisbec, mingo, linux-kernel
On Fri, Jun 03, 2011 at 10:26:55AM -0400, Steven Rostedt wrote:
> On Fri, 2011-06-03 at 16:19 +0200, Jiri Olsa wrote:
> > hi,
> >
> > this patchset contains some fixies of trace output for
> > function and function_graph tracers.
> >
> > attached patches:
> > 1/5 tracing, function_graph: Remove dependency of abstime and duration fields on latency
> > 2/5 tracing, function_graph: Merge overhead and duration display functions
> > 3/5 tracing, function: Fix trace header to follow context-info option
> > 4/5 tracing, function_graph: Remove lock-depth from latency trace
> > 5/5 tracing, function_graph: Add context-info support for function_graph tracer
>
> Hi Jiri,
>
> Thanks for these patches. But could you change the change logs to show
> the problems that you see. Just a description does not express what is
> really wrong. Basically add a:
>
> This is what it looked like before:
>
> ....
>
>
> This is what it looks like now:
>
> ....
>
>
> That way it is obvious what the patches do. I'll test these anyway to
> get a before and after, but it is helpful to see it in the change log.
>
> Thanks,
>
> -- Steve
>
>
sure, I'll resend v2 shortly
thanks,
jirka
^ permalink raw reply [flat|nested] 20+ messages in thread
* [PATCHv2 0/5] tracing, function, graph: Fixies for field display
2011-06-03 14:26 ` [PATCH 0/5] tracing, function, graph: Fixies for field display Steven Rostedt
2011-06-03 14:53 ` Jiri Olsa
@ 2011-06-03 14:58 ` Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency Jiri Olsa
` (4 more replies)
1 sibling, 5 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:58 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel
hi,
this patchset contains some fixies of trace output for
function and function_graph tracers.
attached patches:
1/5 tracing, function_graph: Remove dependency of abstime and duration fields on latency
2/5 tracing, function_graph: Merge overhead and duration display functions
3/5 tracing, function: Fix trace header to follow context-info option
4/5 tracing, function_graph: Remove lock-depth from latency trace
5/5 tracing, function_graph: Add context-info support for function_graph tracer
v2 changes:
- add description of display changes to patches comments
wbr,
jirka
---
kernel/trace/trace.c | 3 +
kernel/trace/trace_functions_graph.c | 223 +++++++++++++++++-----------------
kernel/trace/trace_irqsoff.c | 4 +-
kernel/trace/trace_sched_wakeup.c | 4 +-
4 files changed, 118 insertions(+), 116 deletions(-)
^ permalink raw reply [flat|nested] 20+ messages in thread* [PATCHv2 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency
2011-06-03 14:58 ` [PATCHv2 " Jiri Olsa
@ 2011-06-03 14:58 ` Jiri Olsa
2011-06-03 15:02 ` Steven Rostedt
2011-07-05 12:51 ` [tip:perf/core] " tip-bot for Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 2/5] tracing, function_graph: Merge overhead and duration display functions Jiri Olsa
` (3 subsequent siblings)
4 siblings, 2 replies; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:58 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The display of absolute time and duration fields is based on the
latency field. This was added during the irqsoff/wakeup tracers
graph support changes.
It's causing confusion in what fields will be displayed for the
function_graph tracer itself. So I'm removing this depency, and
adding absolute time and duration fields to the preemptirqsoff
preemptoff irqsoff wakeup tracers.
With following commands:
# echo function_graph > ./current_tracer
# cat trace
This is what it looked like before:
# tracer: function_graph
#
# TIME CPU DURATION FUNCTION CALLS
# | | | | | | | |
0) 0.068 us | } /* page_add_file_rmap */
0) | _raw_spin_unlock() {
...
This is what it looks like now:
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) 0.068 us | } /* add_preempt_count */
0) 0.993 us | } /* vfsmount_lock_local_lock */
...
For preemptirqsoff preemptoff irqsoff wakeup tracers,
this is what it looked like before:
SNIP
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> lock-depth
# |||| /
# CPU TASK/PID ||||| DURATION FUNCTION CALLS
# | | | ||||| | | | | | |
1) <idle>-0 | d..1 0.000 us | acpi_idle_enter_simple();
...
This is what it looks like now:
SNIP
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
# | | | | |||| | | | | | |
19.847735 | 1) <idle>-0 | d..1 0.000 us | acpi_idle_enter_simple();
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 19 +++----------------
kernel/trace/trace_irqsoff.c | 4 +++-
kernel/trace/trace_sched_wakeup.c | 4 +++-
3 files changed, 9 insertions(+), 18 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 962cdb2..352652e 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1207,7 +1207,7 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
enum print_line_t
-__print_graph_function_flags(struct trace_iterator *iter, u32 flags)
+print_graph_function_flags(struct trace_iterator *iter, u32 flags)
{
struct ftrace_graph_ent_entry *field;
struct fgraph_data *data = iter->private;
@@ -1270,18 +1270,7 @@ __print_graph_function_flags(struct trace_iterator *iter, u32 flags)
static enum print_line_t
print_graph_function(struct trace_iterator *iter)
{
- return __print_graph_function_flags(iter, tracer_flags.val);
-}
-
-enum print_line_t print_graph_function_flags(struct trace_iterator *iter,
- u32 flags)
-{
- if (trace_flags & TRACE_ITER_LATENCY_FMT)
- flags |= TRACE_GRAPH_PRINT_DURATION;
- else
- flags |= TRACE_GRAPH_PRINT_ABS_TIME;
-
- return __print_graph_function_flags(iter, flags);
+ return print_graph_function_flags(iter, tracer_flags.val);
}
static enum print_line_t
@@ -1364,9 +1353,7 @@ void print_graph_headers_flags(struct seq_file *s, u32 flags)
return;
print_trace_header(s, iter);
- flags |= TRACE_GRAPH_PRINT_DURATION;
- } else
- flags |= TRACE_GRAPH_PRINT_ABS_TIME;
+ }
__print_graph_headers_flags(s, flags);
}
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index c77424b..667aa8c 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -226,7 +226,9 @@ static void irqsoff_trace_close(struct trace_iterator *iter)
}
#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
- TRACE_GRAPH_PRINT_PROC)
+ TRACE_GRAPH_PRINT_PROC | \
+ TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
{
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index f029dd4..e4a70c0 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -227,7 +227,9 @@ static void wakeup_trace_close(struct trace_iterator *iter)
graph_trace_close(iter);
}
-#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_PROC)
+#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_PROC | \
+ TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
{
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* Re: [PATCHv2 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency
2011-06-03 14:58 ` [PATCHv2 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency Jiri Olsa
@ 2011-06-03 15:02 ` Steven Rostedt
2011-07-05 12:51 ` [tip:perf/core] " tip-bot for Jiri Olsa
1 sibling, 0 replies; 20+ messages in thread
From: Steven Rostedt @ 2011-06-03 15:02 UTC (permalink / raw)
To: Jiri Olsa; +Cc: fweisbec, mingo, linux-kernel
On Fri, 2011-06-03 at 16:58 +0200, Jiri Olsa wrote:
> With following commands:
> # echo function_graph > ./current_tracer
> # cat trace
>
> This is what it looked like before:
> # tracer: function_graph
> #
> # TIME CPU DURATION FUNCTION CALLS
> # | | | | | | | |
> 0) 0.068 us | } /* page_add_file_rmap */
> 0) | _raw_spin_unlock() {
> ...
>
> This is what it looks like now:
> # tracer: function_graph
> #
> # CPU DURATION FUNCTION CALLS
> # | | | | | | |
> 0) 0.068 us | } /* add_preempt_count */
> 0) 0.993 us | } /* vfsmount_lock_local_lock */
> ...
Much nicer change log.
Thanks!
Seems that every patch I test I stumble across another (unrelated) bug.
And then I get side tracked into fixing that bug. So it may be a while
before I get to these.
-- Steve
^ permalink raw reply [flat|nested] 20+ messages in thread* [tip:perf/core] tracing, function_graph: Remove dependency of abstime and duration fields on latency
2011-06-03 14:58 ` [PATCHv2 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency Jiri Olsa
2011-06-03 15:02 ` Steven Rostedt
@ 2011-07-05 12:51 ` tip-bot for Jiri Olsa
1 sibling, 0 replies; 20+ messages in thread
From: tip-bot for Jiri Olsa @ 2011-07-05 12:51 UTC (permalink / raw)
To: linux-tip-commits; +Cc: linux-kernel, hpa, mingo, rostedt, tglx, jolsa
Commit-ID: 321e68b095addc473ca52ced9acfa59be88f76e6
Gitweb: http://git.kernel.org/tip/321e68b095addc473ca52ced9acfa59be88f76e6
Author: Jiri Olsa <jolsa@redhat.com>
AuthorDate: Fri, 3 Jun 2011 16:58:47 +0200
Committer: Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 14 Jun 2011 22:48:47 -0400
tracing, function_graph: Remove dependency of abstime and duration fields on latency
The display of absolute time and duration fields is based on the
latency field. This was added during the irqsoff/wakeup tracers
graph support changes.
It's causing confusion in what fields will be displayed for the
function_graph tracer itself. So I'm removing this depency, and
adding absolute time and duration fields to the preemptirqsoff
preemptoff irqsoff wakeup tracers.
With following commands:
# echo function_graph > ./current_tracer
# cat trace
This is what it looked like before:
# tracer: function_graph
#
# TIME CPU DURATION FUNCTION CALLS
# | | | | | | | |
0) 0.068 us | } /* page_add_file_rmap */
0) | _raw_spin_unlock() {
...
This is what it looks like now:
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) 0.068 us | } /* add_preempt_count */
0) 0.993 us | } /* vfsmount_lock_local_lock */
...
For preemptirqsoff preemptoff irqsoff wakeup tracers,
this is what it looked like before:
SNIP
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> lock-depth
# |||| /
# CPU TASK/PID ||||| DURATION FUNCTION CALLS
# | | | ||||| | | | | | |
1) <idle>-0 | d..1 0.000 us | acpi_idle_enter_simple();
...
This is what it looks like now:
SNIP
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
# | | | | |||| | | | | | |
19.847735 | 1) <idle>-0 | d..1 0.000 us | acpi_idle_enter_simple();
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/1307113131-10045-2-git-send-email-jolsa@redhat.com
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
kernel/trace/trace_functions_graph.c | 19 +++----------------
kernel/trace/trace_irqsoff.c | 4 +++-
kernel/trace/trace_sched_wakeup.c | 4 +++-
3 files changed, 9 insertions(+), 18 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 962cdb2..352652e 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1207,7 +1207,7 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
enum print_line_t
-__print_graph_function_flags(struct trace_iterator *iter, u32 flags)
+print_graph_function_flags(struct trace_iterator *iter, u32 flags)
{
struct ftrace_graph_ent_entry *field;
struct fgraph_data *data = iter->private;
@@ -1270,18 +1270,7 @@ __print_graph_function_flags(struct trace_iterator *iter, u32 flags)
static enum print_line_t
print_graph_function(struct trace_iterator *iter)
{
- return __print_graph_function_flags(iter, tracer_flags.val);
-}
-
-enum print_line_t print_graph_function_flags(struct trace_iterator *iter,
- u32 flags)
-{
- if (trace_flags & TRACE_ITER_LATENCY_FMT)
- flags |= TRACE_GRAPH_PRINT_DURATION;
- else
- flags |= TRACE_GRAPH_PRINT_ABS_TIME;
-
- return __print_graph_function_flags(iter, flags);
+ return print_graph_function_flags(iter, tracer_flags.val);
}
static enum print_line_t
@@ -1364,9 +1353,7 @@ void print_graph_headers_flags(struct seq_file *s, u32 flags)
return;
print_trace_header(s, iter);
- flags |= TRACE_GRAPH_PRINT_DURATION;
- } else
- flags |= TRACE_GRAPH_PRINT_ABS_TIME;
+ }
__print_graph_headers_flags(s, flags);
}
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index c77424b..667aa8c 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -226,7 +226,9 @@ static void irqsoff_trace_close(struct trace_iterator *iter)
}
#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
- TRACE_GRAPH_PRINT_PROC)
+ TRACE_GRAPH_PRINT_PROC | \
+ TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
{
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index f029dd4..e4a70c0 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -227,7 +227,9 @@ static void wakeup_trace_close(struct trace_iterator *iter)
graph_trace_close(iter);
}
-#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_PROC)
+#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_PROC | \
+ TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
{
^ permalink raw reply related [flat|nested] 20+ messages in thread
* [PATCHv2 2/5] tracing, function_graph: Merge overhead and duration display functions
2011-06-03 14:58 ` [PATCHv2 " Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency Jiri Olsa
@ 2011-06-03 14:58 ` Jiri Olsa
2011-07-05 12:52 ` [tip:perf/core] " tip-bot for Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 3/5] tracing, function: Fix trace header to follow context-info option Jiri Olsa
` (2 subsequent siblings)
4 siblings, 1 reply; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:58 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
Functions print_graph_overhead and print_graph_duration displays
data for one field - DURATION.
I merged them into single function print_graph_duration,
and added way to display empty parts of the field.
This way the print_graph_irq function can use this column to display
the IRQ signs if needed and the DURATION field details stays inside
the print_graph_duration function.
There's no actuall change in the display of the output.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 148 +++++++++++++++++-----------------
1 files changed, 74 insertions(+), 74 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 352652e..44b955f 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -74,6 +74,20 @@ static struct tracer_flags tracer_flags = {
static struct trace_array *graph_array;
+/*
+ * DURATION column is being also used to display IRQ signs,
+ * following values are used by print_graph_irq and others
+ * to fill in space into DURATION column.
+ */
+enum {
+ DURATION_FILL_FULL = -1,
+ DURATION_FILL_START = -2,
+ DURATION_FILL_END = -3,
+};
+
+static enum print_line_t
+print_graph_duration(unsigned long long duration, struct trace_seq *s,
+ u32 flags);
/* Add a function return address to the trace stack on thread info.*/
int
@@ -577,32 +591,6 @@ get_return_for_leaf(struct trace_iterator *iter,
return next;
}
-/* Signal a overhead of time execution to the output */
-static int
-print_graph_overhead(unsigned long long duration, struct trace_seq *s,
- u32 flags)
-{
- /* If duration disappear, we don't need anything */
- if (!(flags & TRACE_GRAPH_PRINT_DURATION))
- return 1;
-
- /* Non nested entry or return */
- if (duration == -1)
- return trace_seq_printf(s, " ");
-
- if (flags & 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 int print_graph_abs_time(u64 t, struct trace_seq *s)
{
unsigned long usecs_rem;
@@ -650,9 +638,9 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
}
/* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
+ ret = print_graph_duration(DURATION_FILL_START, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
if (type == TRACE_GRAPH_ENT)
ret = trace_seq_printf(s, "==========>");
@@ -662,9 +650,10 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
- /* Don't close the duration column if haven't one */
- if (flags & TRACE_GRAPH_PRINT_DURATION)
- trace_seq_printf(s, " |");
+ ret = print_graph_duration(DURATION_FILL_END, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
+
ret = trace_seq_printf(s, "\n");
if (!ret)
@@ -716,9 +705,48 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
}
static enum print_line_t
-print_graph_duration(unsigned long long duration, struct trace_seq *s)
+print_graph_duration(unsigned long long duration, struct trace_seq *s,
+ u32 flags)
{
- int ret;
+ int ret = -1;
+
+ if (!(flags & TRACE_GRAPH_PRINT_DURATION))
+ return TRACE_TYPE_HANDLED;
+
+ /* No real adata, just filling the column with spaces */
+ switch (duration) {
+ case DURATION_FILL_FULL:
+ ret = trace_seq_printf(s, " | ");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ case DURATION_FILL_START:
+ ret = trace_seq_printf(s, " ");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ case DURATION_FILL_END:
+ ret = trace_seq_printf(s, " |");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ }
+
+ /* Signal a overhead of time execution to the output */
+ if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
+ /* Duration exceeded 100 msecs */
+ if (duration > 100000ULL)
+ ret = trace_seq_printf(s, "! ");
+ /* Duration exceeded 10 msecs */
+ else if (duration > 10000ULL)
+ ret = trace_seq_printf(s, "+ ");
+ }
+
+ /*
+ * The -1 means we either did not exceed the duration tresholds
+ * or we dont want to print out the overhead. Either way we need
+ * to fill out the space.
+ */
+ if (ret == -1)
+ ret = trace_seq_printf(s, " ");
+
+ /* Catching here any failure happenned above */
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
ret = trace_print_graph_duration(duration, s);
if (ret != TRACE_TYPE_HANDLED)
@@ -767,18 +795,11 @@ print_graph_entry_leaf(struct trace_iterator *iter,
cpu_data->enter_funcs[call->depth] = 0;
}
- /* Overhead */
- ret = print_graph_overhead(duration, s, flags);
- if (!ret)
+ /* Overhead and duration */
+ ret = print_graph_duration(duration, s, flags);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
- /* Duration */
- if (flags & 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++) {
ret = trace_seq_printf(s, " ");
@@ -815,17 +836,10 @@ print_graph_entry_nested(struct trace_iterator *iter,
cpu_data->enter_funcs[call->depth] = call->func;
}
- /* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* No time */
- if (flags & TRACE_GRAPH_PRINT_DURATION) {
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
/* Function */
for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
@@ -1078,18 +1092,11 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
if (print_graph_prologue(iter, s, 0, 0, flags))
return TRACE_TYPE_PARTIAL_LINE;
- /* Overhead */
- ret = print_graph_overhead(duration, s, flags);
- if (!ret)
+ /* Overhead and duration */
+ ret = print_graph_duration(duration, s, flags);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
- /* Duration */
- if (flags & 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++) {
ret = trace_seq_printf(s, " ");
@@ -1146,17 +1153,10 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
if (print_graph_prologue(iter, s, 0, 0, flags))
return TRACE_TYPE_PARTIAL_LINE;
- /* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* No time */
- if (flags & TRACE_GRAPH_PRINT_DURATION) {
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
/* Indentation */
if (depth > 0)
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [tip:perf/core] tracing, function_graph: Merge overhead and duration display functions
2011-06-03 14:58 ` [PATCHv2 2/5] tracing, function_graph: Merge overhead and duration display functions Jiri Olsa
@ 2011-07-05 12:52 ` tip-bot for Jiri Olsa
0 siblings, 0 replies; 20+ messages in thread
From: tip-bot for Jiri Olsa @ 2011-07-05 12:52 UTC (permalink / raw)
To: linux-tip-commits; +Cc: linux-kernel, hpa, mingo, rostedt, tglx, jolsa
Commit-ID: ffeb80fc30acbf6bd51cb47a1815f621a9d017dc
Gitweb: http://git.kernel.org/tip/ffeb80fc30acbf6bd51cb47a1815f621a9d017dc
Author: Jiri Olsa <jolsa@redhat.com>
AuthorDate: Fri, 3 Jun 2011 16:58:48 +0200
Committer: Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 14 Jun 2011 22:48:47 -0400
tracing, function_graph: Merge overhead and duration display functions
Functions print_graph_overhead() and print_graph_duration() displays
data for one field - DURATION.
I merged them into single function print_graph_duration(),
and added a way to display the empty parts of the field.
This way the print_graph_irq() function can use this column to display
the IRQ signs if needed and the DURATION field details stays inside
the print_graph_duration() function.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/1307113131-10045-3-git-send-email-jolsa@redhat.com
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
kernel/trace/trace_functions_graph.c | 148 +++++++++++++++++-----------------
1 files changed, 74 insertions(+), 74 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 352652e..44b955f 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -74,6 +74,20 @@ static struct tracer_flags tracer_flags = {
static struct trace_array *graph_array;
+/*
+ * DURATION column is being also used to display IRQ signs,
+ * following values are used by print_graph_irq and others
+ * to fill in space into DURATION column.
+ */
+enum {
+ DURATION_FILL_FULL = -1,
+ DURATION_FILL_START = -2,
+ DURATION_FILL_END = -3,
+};
+
+static enum print_line_t
+print_graph_duration(unsigned long long duration, struct trace_seq *s,
+ u32 flags);
/* Add a function return address to the trace stack on thread info.*/
int
@@ -577,32 +591,6 @@ get_return_for_leaf(struct trace_iterator *iter,
return next;
}
-/* Signal a overhead of time execution to the output */
-static int
-print_graph_overhead(unsigned long long duration, struct trace_seq *s,
- u32 flags)
-{
- /* If duration disappear, we don't need anything */
- if (!(flags & TRACE_GRAPH_PRINT_DURATION))
- return 1;
-
- /* Non nested entry or return */
- if (duration == -1)
- return trace_seq_printf(s, " ");
-
- if (flags & 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 int print_graph_abs_time(u64 t, struct trace_seq *s)
{
unsigned long usecs_rem;
@@ -650,9 +638,9 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
}
/* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
+ ret = print_graph_duration(DURATION_FILL_START, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
if (type == TRACE_GRAPH_ENT)
ret = trace_seq_printf(s, "==========>");
@@ -662,9 +650,10 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
- /* Don't close the duration column if haven't one */
- if (flags & TRACE_GRAPH_PRINT_DURATION)
- trace_seq_printf(s, " |");
+ ret = print_graph_duration(DURATION_FILL_END, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
+
ret = trace_seq_printf(s, "\n");
if (!ret)
@@ -716,9 +705,48 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
}
static enum print_line_t
-print_graph_duration(unsigned long long duration, struct trace_seq *s)
+print_graph_duration(unsigned long long duration, struct trace_seq *s,
+ u32 flags)
{
- int ret;
+ int ret = -1;
+
+ if (!(flags & TRACE_GRAPH_PRINT_DURATION))
+ return TRACE_TYPE_HANDLED;
+
+ /* No real adata, just filling the column with spaces */
+ switch (duration) {
+ case DURATION_FILL_FULL:
+ ret = trace_seq_printf(s, " | ");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ case DURATION_FILL_START:
+ ret = trace_seq_printf(s, " ");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ case DURATION_FILL_END:
+ ret = trace_seq_printf(s, " |");
+ return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
+ }
+
+ /* Signal a overhead of time execution to the output */
+ if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
+ /* Duration exceeded 100 msecs */
+ if (duration > 100000ULL)
+ ret = trace_seq_printf(s, "! ");
+ /* Duration exceeded 10 msecs */
+ else if (duration > 10000ULL)
+ ret = trace_seq_printf(s, "+ ");
+ }
+
+ /*
+ * The -1 means we either did not exceed the duration tresholds
+ * or we dont want to print out the overhead. Either way we need
+ * to fill out the space.
+ */
+ if (ret == -1)
+ ret = trace_seq_printf(s, " ");
+
+ /* Catching here any failure happenned above */
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
ret = trace_print_graph_duration(duration, s);
if (ret != TRACE_TYPE_HANDLED)
@@ -767,18 +795,11 @@ print_graph_entry_leaf(struct trace_iterator *iter,
cpu_data->enter_funcs[call->depth] = 0;
}
- /* Overhead */
- ret = print_graph_overhead(duration, s, flags);
- if (!ret)
+ /* Overhead and duration */
+ ret = print_graph_duration(duration, s, flags);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
- /* Duration */
- if (flags & 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++) {
ret = trace_seq_printf(s, " ");
@@ -815,17 +836,10 @@ print_graph_entry_nested(struct trace_iterator *iter,
cpu_data->enter_funcs[call->depth] = call->func;
}
- /* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* No time */
- if (flags & TRACE_GRAPH_PRINT_DURATION) {
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
/* Function */
for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
@@ -1078,18 +1092,11 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
if (print_graph_prologue(iter, s, 0, 0, flags))
return TRACE_TYPE_PARTIAL_LINE;
- /* Overhead */
- ret = print_graph_overhead(duration, s, flags);
- if (!ret)
+ /* Overhead and duration */
+ ret = print_graph_duration(duration, s, flags);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
- /* Duration */
- if (flags & 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++) {
ret = trace_seq_printf(s, " ");
@@ -1146,17 +1153,10 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
if (print_graph_prologue(iter, s, 0, 0, flags))
return TRACE_TYPE_PARTIAL_LINE;
- /* No overhead */
- ret = print_graph_overhead(-1, s, flags);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* No time */
- if (flags & TRACE_GRAPH_PRINT_DURATION) {
- ret = trace_seq_printf(s, " | ");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
+ if (ret != TRACE_TYPE_HANDLED)
+ return ret;
/* Indentation */
if (depth > 0)
^ permalink raw reply related [flat|nested] 20+ messages in thread
* [PATCHv2 3/5] tracing, function: Fix trace header to follow context-info option
2011-06-03 14:58 ` [PATCHv2 " Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 1/5] tracing, function_graph: Remove dependency of abstime and duration fields on latency Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 2/5] tracing, function_graph: Merge overhead and duration display functions Jiri Olsa
@ 2011-06-03 14:58 ` Jiri Olsa
2011-07-05 12:52 ` [tip:perf/core] " tip-bot for Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 4/5] tracing, function_graph: Remove lock-depth from latency trace Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 5/5] tracing, function_graph: Add context-info support for function_graph tracer Jiri Olsa
4 siblings, 1 reply; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:58 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The header display of function tracer does not follow
the context-info option, so field names are displayed even
if this option is off.
Added check for TRACE_ITER_CONTEXT_INFO trace_flags.
With following commands:
# echo function > ./current_tracer
# echo 0 > options/context-info
# cat trace
This is what it looked like before:
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
add_preempt_count <-schedule
rcu_note_context_switch <-schedule
...
This is what it looks like now:
# tracer: function
#
_raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace.c | 3 +++
1 files changed, 3 insertions(+), 0 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ee9c921..01fc8d7 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2051,6 +2051,9 @@ void trace_default_header(struct seq_file *m)
{
struct trace_iterator *iter = m->private;
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return;
+
if (iter->iter_flags & TRACE_FILE_LAT_FMT) {
/* print nothing if the buffers are empty */
if (trace_empty(iter))
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [tip:perf/core] tracing, function: Fix trace header to follow context-info option
2011-06-03 14:58 ` [PATCHv2 3/5] tracing, function: Fix trace header to follow context-info option Jiri Olsa
@ 2011-07-05 12:52 ` tip-bot for Jiri Olsa
0 siblings, 0 replies; 20+ messages in thread
From: tip-bot for Jiri Olsa @ 2011-07-05 12:52 UTC (permalink / raw)
To: linux-tip-commits; +Cc: linux-kernel, hpa, mingo, rostedt, tglx, jolsa
Commit-ID: f56e7f8efb4ec200364f690a9902713410e24d47
Gitweb: http://git.kernel.org/tip/f56e7f8efb4ec200364f690a9902713410e24d47
Author: Jiri Olsa <jolsa@redhat.com>
AuthorDate: Fri, 3 Jun 2011 16:58:49 +0200
Committer: Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 14 Jun 2011 22:48:48 -0400
tracing, function: Fix trace header to follow context-info option
The header display of function tracer does not follow
the context-info option, so field names are displayed even
if this option is off.
Added check for TRACE_ITER_CONTEXT_INFO trace_flags.
With following commands:
# echo function > ./current_tracer
# echo 0 > options/context-info
# cat trace
This is what it looked like before:
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
add_preempt_count <-schedule
rcu_note_context_switch <-schedule
...
This is what it looks like now:
# tracer: function
#
_raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/1307113131-10045-4-git-send-email-jolsa@redhat.com
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
kernel/trace/trace.c | 3 +++
1 files changed, 3 insertions(+), 0 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 42fdf3a..cf22b4b 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2053,6 +2053,9 @@ void trace_default_header(struct seq_file *m)
{
struct trace_iterator *iter = m->private;
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return;
+
if (iter->iter_flags & TRACE_FILE_LAT_FMT) {
/* print nothing if the buffers are empty */
if (trace_empty(iter))
^ permalink raw reply related [flat|nested] 20+ messages in thread
* [PATCHv2 4/5] tracing, function_graph: Remove lock-depth from latency trace
2011-06-03 14:58 ` [PATCHv2 " Jiri Olsa
` (2 preceding siblings ...)
2011-06-03 14:58 ` [PATCHv2 3/5] tracing, function: Fix trace header to follow context-info option Jiri Olsa
@ 2011-06-03 14:58 ` Jiri Olsa
2011-07-05 12:52 ` [tip:perf/core] " tip-bot for Jiri Olsa
2011-06-03 14:58 ` [PATCHv2 5/5] tracing, function_graph: Add context-info support for function_graph tracer Jiri Olsa
4 siblings, 1 reply; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:58 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The lock_depth was removed in commit
e6e1e25 tracing: Remove lock_depth from event entry
Removing the lock_depth info from function_graph latency header.
With following commands:
# echo function_graph > ./current_tracer
# echo 1 > options/latency-format
# cat trace
This is what it looked like before:
# tracer: function_graph
#
# function_graph latency trace v1.1.5 on 3.0.0-rc1-tip+
# --------------------------------------------------------------------
# latency: 0 us, #59756/311298, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> lock-depth
# |||| /
# CPU||||| DURATION FUNCTION CALLS
# | ||||| | | | | | |
0) .... 0.068 us | } /* __rcu_read_unlock */
...
This is what it looks like now:
# tracer: function_graph
#
# function_graph latency trace v1.1.5 on 3.0.0-rc1-tip+
# --------------------------------------------------------------------
# latency: 0 us, #59747/1744610, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# CPU|||| DURATION FUNCTION CALLS
# | |||| | | | | | |
0) ..s. 1.641 us | } /* __rcu_process_callbacks */
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 7 +++----
1 files changed, 3 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 44b955f..1da5b97 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1298,8 +1298,7 @@ static void print_lat_header(struct seq_file *s, u32 flags)
seq_printf(s, "#%.*s / _----=> need-resched \n", size, spaces);
seq_printf(s, "#%.*s| / _---=> hardirq/softirq \n", size, spaces);
seq_printf(s, "#%.*s|| / _--=> preempt-depth \n", size, spaces);
- seq_printf(s, "#%.*s||| / _-=> lock-depth \n", size, spaces);
- seq_printf(s, "#%.*s|||| / \n", size, spaces);
+ seq_printf(s, "#%.*s||| / \n", size, spaces);
}
static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
@@ -1318,7 +1317,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
if (flags & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " TASK/PID ");
if (lat)
- seq_printf(s, "|||||");
+ seq_printf(s, "||||");
if (flags & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " DURATION ");
seq_printf(s, " FUNCTION CALLS\n");
@@ -1332,7 +1331,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
if (flags & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " | | ");
if (lat)
- seq_printf(s, "|||||");
+ seq_printf(s, "||||");
if (flags & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " | | ");
seq_printf(s, " | | | |\n");
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [tip:perf/core] tracing, function_graph: Remove lock-depth from latency trace
2011-06-03 14:58 ` [PATCHv2 4/5] tracing, function_graph: Remove lock-depth from latency trace Jiri Olsa
@ 2011-07-05 12:52 ` tip-bot for Jiri Olsa
0 siblings, 0 replies; 20+ messages in thread
From: tip-bot for Jiri Olsa @ 2011-07-05 12:52 UTC (permalink / raw)
To: linux-tip-commits; +Cc: linux-kernel, hpa, mingo, rostedt, tglx, jolsa
Commit-ID: 199abfab40389963b397c2982222e68ea782b2cf
Gitweb: http://git.kernel.org/tip/199abfab40389963b397c2982222e68ea782b2cf
Author: Jiri Olsa <jolsa@redhat.com>
AuthorDate: Fri, 3 Jun 2011 16:58:50 +0200
Committer: Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 14 Jun 2011 22:48:49 -0400
tracing, function_graph: Remove lock-depth from latency trace
The lock_depth was removed in commit
e6e1e25 tracing: Remove lock_depth from event entry
Removing the lock_depth info from function_graph latency header.
With following commands:
# echo function_graph > ./current_tracer
# echo 1 > options/latency-format
# cat trace
This is what it looked like before:
# tracer: function_graph
#
# function_graph latency trace v1.1.5 on 3.0.0-rc1-tip+
# --------------------------------------------------------------------
# latency: 0 us, #59756/311298, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> lock-depth
# |||| /
# CPU||||| DURATION FUNCTION CALLS
# | ||||| | | | | | |
0) .... 0.068 us | } /* __rcu_read_unlock */
...
This is what it looks like now:
# tracer: function_graph
#
# function_graph latency trace v1.1.5 on 3.0.0-rc1-tip+
# --------------------------------------------------------------------
# latency: 0 us, #59747/1744610, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# CPU|||| DURATION FUNCTION CALLS
# | |||| | | | | | |
0) ..s. 1.641 us | } /* __rcu_process_callbacks */
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/1307113131-10045-5-git-send-email-jolsa@redhat.com
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
kernel/trace/trace_functions_graph.c | 7 +++----
1 files changed, 3 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 44b955f..1da5b97 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1298,8 +1298,7 @@ static void print_lat_header(struct seq_file *s, u32 flags)
seq_printf(s, "#%.*s / _----=> need-resched \n", size, spaces);
seq_printf(s, "#%.*s| / _---=> hardirq/softirq \n", size, spaces);
seq_printf(s, "#%.*s|| / _--=> preempt-depth \n", size, spaces);
- seq_printf(s, "#%.*s||| / _-=> lock-depth \n", size, spaces);
- seq_printf(s, "#%.*s|||| / \n", size, spaces);
+ seq_printf(s, "#%.*s||| / \n", size, spaces);
}
static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
@@ -1318,7 +1317,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
if (flags & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " TASK/PID ");
if (lat)
- seq_printf(s, "|||||");
+ seq_printf(s, "||||");
if (flags & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " DURATION ");
seq_printf(s, " FUNCTION CALLS\n");
@@ -1332,7 +1331,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)
if (flags & TRACE_GRAPH_PRINT_PROC)
seq_printf(s, " | | ");
if (lat)
- seq_printf(s, "|||||");
+ seq_printf(s, "||||");
if (flags & TRACE_GRAPH_PRINT_DURATION)
seq_printf(s, " | | ");
seq_printf(s, " | | | |\n");
^ permalink raw reply related [flat|nested] 20+ messages in thread
* [PATCHv2 5/5] tracing, function_graph: Add context-info support for function_graph tracer
2011-06-03 14:58 ` [PATCHv2 " Jiri Olsa
` (3 preceding siblings ...)
2011-06-03 14:58 ` [PATCHv2 4/5] tracing, function_graph: Remove lock-depth from latency trace Jiri Olsa
@ 2011-06-03 14:58 ` Jiri Olsa
2011-07-05 12:53 ` [tip:perf/core] " tip-bot for Jiri Olsa
4 siblings, 1 reply; 20+ messages in thread
From: Jiri Olsa @ 2011-06-03 14:58 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
The function_graph tracer does not follow global context-info option.
Adding TRACE_ITER_CONTEXT_INFO trace_flags check to enable it.
With following commands:
# echo function_graph > ./current_tracer
# echo 0 > options/context-info
# cat trace
This is what it looked like before:
# tracer: function_graph
#
# TIME CPU DURATION FUNCTION CALLS
# | | | | | | | |
1) 0.079 us | } /* __vma_link_rb */
1) 0.056 us | copy_page_range();
1) | security_vm_enough_memory() {
...
This is what it looks like now:
# tracer: function_graph
#
} /* update_ts_time_stats */
timekeeping_max_deferment();
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace_functions_graph.c | 53 ++++++++++++++++++++--------------
1 files changed, 31 insertions(+), 22 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 1da5b97..e8d6bb5 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -613,28 +613,30 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
addr >= (unsigned long)__irqentry_text_end)
return TRACE_TYPE_UNHANDLED;
- /* Absolute time */
- if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
- ret = print_graph_abs_time(iter->ts, s);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
+ /* Absolute time */
+ if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
+ ret = print_graph_abs_time(iter->ts, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
- /* Cpu */
- if (flags & TRACE_GRAPH_PRINT_CPU) {
- ret = print_graph_cpu(s, cpu);
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ /* Cpu */
+ if (flags & TRACE_GRAPH_PRINT_CPU) {
+ ret = print_graph_cpu(s, cpu);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
- /* Proc */
- if (flags & 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;
+ /* Proc */
+ if (flags & 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;
+ }
}
/* No overhead */
@@ -710,8 +712,9 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,
{
int ret = -1;
- if (!(flags & TRACE_GRAPH_PRINT_DURATION))
- return TRACE_TYPE_HANDLED;
+ if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
+ !(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return TRACE_TYPE_HANDLED;
/* No real adata, just filling the column with spaces */
switch (duration) {
@@ -879,6 +882,9 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return 0;
+
/* Absolute time */
if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
ret = print_graph_abs_time(iter->ts, s);
@@ -1346,6 +1352,9 @@ void print_graph_headers_flags(struct seq_file *s, u32 flags)
{
struct trace_iterator *iter = s->private;
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return;
+
if (trace_flags & TRACE_ITER_LATENCY_FMT) {
/* print nothing if the buffers are empty */
if (trace_empty(iter))
--
1.7.1
^ permalink raw reply related [flat|nested] 20+ messages in thread* [tip:perf/core] tracing, function_graph: Add context-info support for function_graph tracer
2011-06-03 14:58 ` [PATCHv2 5/5] tracing, function_graph: Add context-info support for function_graph tracer Jiri Olsa
@ 2011-07-05 12:53 ` tip-bot for Jiri Olsa
0 siblings, 0 replies; 20+ messages in thread
From: tip-bot for Jiri Olsa @ 2011-07-05 12:53 UTC (permalink / raw)
To: linux-tip-commits; +Cc: linux-kernel, hpa, mingo, rostedt, tglx, jolsa
Commit-ID: 749230b06a753a22f6ed96e5dd60815d6ab12865
Gitweb: http://git.kernel.org/tip/749230b06a753a22f6ed96e5dd60815d6ab12865
Author: Jiri Olsa <jolsa@redhat.com>
AuthorDate: Fri, 3 Jun 2011 16:58:51 +0200
Committer: Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 14 Jun 2011 22:48:49 -0400
tracing, function_graph: Add context-info support for function_graph tracer
The function_graph tracer does not follow global context-info option.
Adding TRACE_ITER_CONTEXT_INFO trace_flags check to enable it.
With following commands:
# echo function_graph > ./current_tracer
# echo 0 > options/context-info
# cat trace
This is what it looked like before:
# tracer: function_graph
#
# TIME CPU DURATION FUNCTION CALLS
# | | | | | | | |
1) 0.079 us | } /* __vma_link_rb */
1) 0.056 us | copy_page_range();
1) | security_vm_enough_memory() {
...
This is what it looks like now:
# tracer: function_graph
#
} /* update_ts_time_stats */
timekeeping_max_deferment();
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/1307113131-10045-6-git-send-email-jolsa@redhat.com
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
kernel/trace/trace_functions_graph.c | 53 ++++++++++++++++++++--------------
1 files changed, 31 insertions(+), 22 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 1da5b97..e8d6bb5 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -613,28 +613,30 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
addr >= (unsigned long)__irqentry_text_end)
return TRACE_TYPE_UNHANDLED;
- /* Absolute time */
- if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
- ret = print_graph_abs_time(iter->ts, s);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
+ /* Absolute time */
+ if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
+ ret = print_graph_abs_time(iter->ts, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
- /* Cpu */
- if (flags & TRACE_GRAPH_PRINT_CPU) {
- ret = print_graph_cpu(s, cpu);
- if (ret == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ /* Cpu */
+ if (flags & TRACE_GRAPH_PRINT_CPU) {
+ ret = print_graph_cpu(s, cpu);
+ if (ret == TRACE_TYPE_PARTIAL_LINE)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
- /* Proc */
- if (flags & 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;
+ /* Proc */
+ if (flags & 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;
+ }
}
/* No overhead */
@@ -710,8 +712,9 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,
{
int ret = -1;
- if (!(flags & TRACE_GRAPH_PRINT_DURATION))
- return TRACE_TYPE_HANDLED;
+ if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
+ !(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return TRACE_TYPE_HANDLED;
/* No real adata, just filling the column with spaces */
switch (duration) {
@@ -879,6 +882,9 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return 0;
+
/* Absolute time */
if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
ret = print_graph_abs_time(iter->ts, s);
@@ -1346,6 +1352,9 @@ void print_graph_headers_flags(struct seq_file *s, u32 flags)
{
struct trace_iterator *iter = s->private;
+ if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
+ return;
+
if (trace_flags & TRACE_ITER_LATENCY_FMT) {
/* print nothing if the buffers are empty */
if (trace_empty(iter))
^ permalink raw reply related [flat|nested] 20+ messages in thread