summaryrefslogtreecommitdiffstats
path: root/kernel/trace/trace_functions_graph.c
diff options
context:
space:
mode:
authorFrederic Weisbecker <fweisbec@gmail.com>2009-02-18 04:25:25 +0100
committerIngo Molnar <mingo@elte.hu>2009-02-19 12:33:21 +0100
commitd1f9cbd78841f1a797c77e9117e4882f932c2ef6 (patch)
tree385b85ae60dfca6b4d2c5d8093db07cd6c5fbb20 /kernel/trace/trace_functions_graph.c
parent4cd0332db7e8f57cc082bab11d82c064a9721737 (diff)
downloadop-kernel-dev-d1f9cbd78841f1a797c77e9117e4882f932c2ef6.zip
op-kernel-dev-d1f9cbd78841f1a797c77e9117e4882f932c2ef6.tar.gz
tracing/function-graph-tracer: fix traces weirdness while absolute time printing
Impact: trace output cleanup/reordering When an interrupt occurs and and the abstime option is selected: echo funcgraph-abstime > /debug/tracing/trace_options then we observe broken traces: 30581.025422 | 0) Xorg-4291 | 0.503 us | idle_cpu(); 30581.025424 | 0) Xorg-4291 | 2.576 us | } 30581.025424 | 0) Xorg-4291 | + 75.771 us | } 0) Xorg-4291 | <========== | 30581.025425 | 0) Xorg-4291 | | schedule() { 30581.025426 | 0) Xorg-4291 | | __schedule() { 30581.025426 | 0) Xorg-4291 | 0.705 us | _spin_lock_irq(); With this patch, the interrupts output better adapts to absolute time printing: 414.856543 | 1) Xorg-4279 | 8.816 us | } 414.856544 | 1) Xorg-4279 | 0.525 us | rcu_irq_exit(); 414.856545 | 1) Xorg-4279 | 0.526 us | idle_cpu(); 414.856546 | 1) Xorg-4279 | + 12.157 us | } 414.856549 | 1) Xorg-4279 | ! 104.114 us | } 414.856549 | 1) Xorg-4279 | <========== | 414.856549 | 1) Xorg-4279 | ! 107.944 us | } 414.856550 | 1) Xorg-4279 | ! 137.010 us | } 414.856551 | 1) Xorg-4279 | 0.624 us | _read_unlock(); 414.856552 | 1) Xorg-4279 | ! 140.930 us | } 414.856552 | 1) Xorg-4279 | ! 166.159 us | } Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> Signed-off-by: Ingo Molnar <mingo@elte.hu>
Diffstat (limited to 'kernel/trace/trace_functions_graph.c')
-rw-r--r--kernel/trace/trace_functions_graph.c50
1 files changed, 29 insertions, 21 deletions
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 6c7738e..8f4004a 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -351,16 +351,35 @@ print_graph_overhead(unsigned long long duration, struct trace_seq *s)
return trace_seq_printf(s, " ");
}
+static int print_graph_abs_time(u64 t, struct trace_seq *s)
+{
+ unsigned long usecs_rem;
+
+ usecs_rem = do_div(t, NSEC_PER_SEC);
+ usecs_rem /= 1000;
+
+ return trace_seq_printf(s, "%5lu.%06lu | ",
+ (unsigned long)t, usecs_rem);
+}
+
static enum print_line_t
-print_graph_irq(struct trace_seq *s, unsigned long addr,
+print_graph_irq(struct trace_iterator *iter, unsigned long addr,
enum trace_type type, int cpu, pid_t pid)
{
int ret;
+ struct trace_seq *s = &iter->seq;
if (addr < (unsigned long)__irqentry_text_start ||
addr >= (unsigned long)__irqentry_text_end)
return TRACE_TYPE_UNHANDLED;
+ /* 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);
@@ -446,17 +465,6 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s)
}
-static int print_graph_abs_time(u64 t, struct trace_seq *s)
-{
- unsigned long usecs_rem;
-
- usecs_rem = do_div(t, 1000000000);
- usecs_rem /= 1000;
-
- return trace_seq_printf(s, "%5lu.%06lu | ",
- (unsigned long)t, usecs_rem);
-}
-
/* Case of a leaf function on its call entry */
static enum print_line_t
print_graph_entry_leaf(struct trace_iterator *iter,
@@ -561,7 +569,7 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
/* Interrupt */
- ret = print_graph_irq(s, call->func, TRACE_GRAPH_ENT, cpu, ent->pid);
+ ret = print_graph_irq(iter, call->func, TRACE_GRAPH_ENT, cpu, ent->pid);
if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
@@ -581,7 +589,7 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
/* Proc */
if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
- ret = print_graph_proc(s, ent->pid);
+ ret = print_graph_proc(s, pid);
if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
@@ -605,11 +613,11 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
int i;
int ret;
int cpu = iter->cpu;
- pid_t *last_pid = iter->private;
+ pid_t *last_pid = iter->private, pid = ent->pid;
unsigned long long duration = trace->rettime - trace->calltime;
/* Pid */
- if (verif_pid(s, ent->pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
+ if (verif_pid(s, pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
/* Absolute time */
@@ -668,7 +676,7 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}
- ret = print_graph_irq(s, trace->func, TRACE_GRAPH_RET, cpu, ent->pid);
+ ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET, cpu, pid);
if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE;
@@ -684,6 +692,10 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
int cpu = iter->cpu;
pid_t *last_pid = iter->private;
+ /* Pid */
+ if (verif_pid(s, ent->pid, cpu, last_pid) == 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);
@@ -691,10 +703,6 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}
- /* Pid */
- if (verif_pid(s, ent->pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
- return TRACE_TYPE_PARTIAL_LINE;
-
/* Cpu */
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
ret = print_graph_cpu(s, cpu);
OpenPOWER on IntegriCloud