| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Wed, 18 Feb 2009 04:25:25 +0100
From: Frederic Weisbecker <fweisbec@...il.com>
To: Ingo Molnar <mingo@...e.hu>, Steven Rostedt <rostedt@...dmis.org>
Cc: Arnaldo Carvalho de Melo <acme@...hat.com>,
linux-kernel@...r.kernel.org
Subject: [PATCH 1/2] 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 on 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@...il.com>
---
kernel/trace/trace_functions_graph.c | 50 +++++++++++++++++++--------------
1 files changed, 29 insertions(+), 21 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 0ff5cb6..5c19937 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -276,16 +276,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);
@@ -371,17 +390,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,
@@ -486,7 +494,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;
@@ -530,11 +538,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 */
@@ -553,7 +561,7 @@ print_graph_return(struct ftrace_graph_ret *trace, 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;
@@ -593,7 +601,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;
@@ -609,6 +617,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);
@@ -616,10 +628,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);
--
1.6.1
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists