Commit d1f9cbd7 authored by Frederic Weisbecker's avatar Frederic Weisbecker Committed by Ingo Molnar

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: default avatarFrederic Weisbecker <fweisbec@gmail.com>
Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
parent 4cd0332d
...@@ -351,16 +351,35 @@ print_graph_overhead(unsigned long long duration, struct trace_seq *s) ...@@ -351,16 +351,35 @@ print_graph_overhead(unsigned long long duration, struct trace_seq *s)
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;
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 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) enum trace_type type, int cpu, pid_t pid)
{ {
int ret; int ret;
struct trace_seq *s = &iter->seq;
if (addr < (unsigned long)__irqentry_text_start || if (addr < (unsigned long)__irqentry_text_start ||
addr >= (unsigned long)__irqentry_text_end) addr >= (unsigned long)__irqentry_text_end)
return TRACE_TYPE_UNHANDLED; 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 */ /* Cpu */
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) { if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
ret = print_graph_cpu(s, cpu); ret = print_graph_cpu(s, cpu);
...@@ -446,17 +465,6 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s) ...@@ -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 */ /* Case of a leaf function on its call entry */
static enum print_line_t static enum print_line_t
print_graph_entry_leaf(struct trace_iterator *iter, 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, ...@@ -561,7 +569,7 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE; return TRACE_TYPE_PARTIAL_LINE;
/* Interrupt */ /* 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) if (ret == TRACE_TYPE_PARTIAL_LINE)
return 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, ...@@ -581,7 +589,7 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
/* Proc */ /* Proc */
if (tracer_flags.val & TRACE_GRAPH_PRINT_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) if (ret == TRACE_TYPE_PARTIAL_LINE)
return 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, ...@@ -605,11 +613,11 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
int i; int i;
int ret; int ret;
int cpu = iter->cpu; 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; unsigned long long duration = trace->rettime - trace->calltime;
/* Pid */ /* 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; return TRACE_TYPE_PARTIAL_LINE;
/* Absolute time */ /* Absolute time */
...@@ -668,7 +676,7 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s, ...@@ -668,7 +676,7 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE; 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) if (ret == TRACE_TYPE_PARTIAL_LINE)
return TRACE_TYPE_PARTIAL_LINE; return TRACE_TYPE_PARTIAL_LINE;
...@@ -684,6 +692,10 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s, ...@@ -684,6 +692,10 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
int cpu = iter->cpu; int cpu = iter->cpu;
pid_t *last_pid = iter->private; 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 */ /* Absolute time */
if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) { if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
ret = print_graph_abs_time(iter->ts, s); ret = print_graph_abs_time(iter->ts, s);
...@@ -691,10 +703,6 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s, ...@@ -691,10 +703,6 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE; 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 */ /* Cpu */
if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) { if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
ret = print_graph_cpu(s, cpu); ret = print_graph_cpu(s, cpu);
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment