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>
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 @@
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 @@
}
-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 @@
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 @@
/* 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 @@
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 @@
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 @@
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 @@
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);
