| 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: Fri, 28 Nov 2008 10:18:00 +0100
From: Ingo Molnar <mingo@...e.hu>
To: Frederic Weisbecker <fweisbec@...il.com>
Cc: Steven Rostedt <rostedt@...dmis.org>,
Tim Bird <tim.bird@...sony.com>,
Peter Zijlstra <a.p.zijlstra@...llo.nl>,
Linux Kernel <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH] tracing/function-graph-tracer: adjustments of the
trace informations
* Frederic Weisbecker <fweisbec@...il.com> wrote:
> Impact: increase visibility of the output
>
> This patch applies various changes.
>
> _CPU is now a decimal number, followed by a parenthesis.
>
> _Overhead is now on the second column (gives a good visibility)
>
> _Cost is now on the third column, can't exceed 9999.99 us. It is followed
> by a virtual line based on a "|" character.
>
> _Functions calls are now the last column on the right. This way, we haven't
> dynamic column (which flow is harder to follow) on its right.
>
> _CPU and Overhead have their own option flag. They are default-on but you can
> disable them easily:
>
> echo nofuncgraph-cpu > trace_options
> echo nofuncgraph-overhead > trace_options
>
> TODO:
>
> _ Refactoring of the thread switch output.
> _ Give a default-off option to output the thread and its pid on each row.
> _ Provide headers
> _ ....
>
> Here is an example of the new trace style (a wider one is provided in attachment):
>
> 0) | mutex_unlock() {
> 0) 0.639 us | __mutex_unlock_slowpath();
> 0) 1.607 us | }
> 0) | remove_wait_queue() {
> 0) 0.616 us | _spin_lock_irqsave();
> 0) 0.616 us | _spin_unlock_irqrestore();
> 0) 2.779 us | }
> 0) 0.495 us | n_tty_set_room();
> 0) ! 9999.999 us | }
> 0) | tty_ldisc_deref() {
> 0) 0.615 us | _spin_lock_irqsave();
> 0) 0.616 us | _spin_unlock_irqrestore();
> 0) 2.793 us | }
> 0) | current_fs_time() {
> 0) 0.488 us | current_kernel_time();
> 0) 0.495 us | timespec_trunc();
> 0) 2.486 us | }
> 0) ! 9999.999 us | }
> 0) ! 9999.999 us | }
> 0) ! 9999.999 us | }
> 0) | sys_read() {
> 0) 0.796 us | fget_light();
> 0) | vfs_read() {
> 0) | rw_verify_area() {
> 0) | security_file_permission() {
> 0) 0.488 us | cap_file_permission();
> 0) 1.720 us | }
> 0) 3. 4 us | }
> 0) | tty_read() {
> 0) 0.488 us | tty_paranoia_check();
> 0) | tty_ldisc_ref_wait() {
> 0) | tty_ldisc_try() {
> 0) 0.615 us | _spin_lock_irqsave();
> 0) 0.615 us | _spin_unlock_irqrestore();
> 0) 5.436 us | }
> 0) 6.427 us | }
very nice! Applied to tip/tracing/function-graph-tracer
a few comments.
Firstly, what do you think about the additional tweaks i did - see the
patch below?
Before:
0) | sys_read() {
0) 0.796 us | fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
------------8<---------- thread sshd-1755 ------------8<----------
After:
0) | sys_read() {
0) 0.796 us | fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
------------------------------------------
| 1) migration/0--1 => sshd-1755
------------------------------------------
Secondly:
> + /* Must not exceed 8 characters: xxxx.yyy us */
> + if (duration > 10000000ULL)
> + duration = 9999999ULL;
10 milliseconds isnt much or full system calls, etc.- so i believe the
rule should be what i outlined in an earlier mail. The relevant
transition points go like this:
0.000
xxxx.yyy
9999.999
10000.00
xxxxx.yy
99999.99
100000.0
xxxxxx.y
999999.9
1000000
9999999
10000000
xxxxxxxx
99999999 [ 100 seconds ]
100000000 ... up to infinity
this way we can get up to 99999999 usecs with the same fixed width -
or 100 seconds. _That_ is enough in practice.
But even beyond that we should print it all out: we should still not
clip actual information but instead shift the line to the right. The
slightly inconsistent line is not a big problem - we want a 100
seconds delay to stand out anyway ;-)
The moving decimal point above 10 milliseconds is not a big problem
with the '+' and '!' marker. Maybe add a '!!' marker to these lines?
Ingo
------------------->
>From d51090b34602a20984ab0312ef04e47069c0aec6 Mon Sep 17 00:00:00 2001
From: Ingo Molnar <mingo@...e.hu>
Date: Fri, 28 Nov 2008 09:55:16 +0100
Subject: [PATCH] tracing/function-graph-tracer: more output tweaks
Impact: prettify the output some more
Before:
0) | sys_read() {
0) 0.796 us | fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
------------8<---------- thread sshd-1755 ------------8<----------
After:
0) | sys_read() {
0) 0.796 us | fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
------------------------------------------
| 1) migration/0--1 => sshd-1755
------------------------------------------
Signed-off-by: Ingo Molnar <mingo@...e.hu>
---
kernel/trace/trace_functions_graph.c | 45 ++++++++++++++++++++++++++++-----
1 files changed, 38 insertions(+), 7 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 596a3ee..894b50b 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -79,6 +79,19 @@ print_graph_cpu(struct trace_seq *s, int cpu)
int log10_all = log10_cpu(cpus_weight_nr(cpu_online_map));
+ /*
+ * Start with a space character - to make it stand out
+ * to the right a bit when trace output is pasted into
+ * email:
+ */
+ ret = trace_seq_printf(s, " ");
+
+ /*
+ * Tricky - we space the CPU field according to the max
+ * number of online CPUs. On a 2-cpu system it would take
+ * a maximum of 1 digit - on a 128 cpu system it would
+ * take up to 3 digits:
+ */
for (i = 0; i < log10_all - log10_this; i++) {
ret = trace_seq_printf(s, " ");
if (!ret)
@@ -86,7 +99,8 @@ print_graph_cpu(struct trace_seq *s, int cpu)
}
ret = trace_seq_printf(s, "%d) ", cpu);
if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
+ return TRACE_TYPE_PARTIAL_LINE;
+
return TRACE_TYPE_HANDLED;
}
@@ -94,17 +108,34 @@ print_graph_cpu(struct trace_seq *s, int cpu)
/* If the pid changed since the last trace, output this event */
static int verif_pid(struct trace_seq *s, pid_t pid, int cpu)
{
- char *comm;
+ char *comm, *prev_comm;
+ pid_t prev_pid;
+ int ret;
if (last_pid[cpu] != -1 && last_pid[cpu] == pid)
return 1;
+ prev_pid = last_pid[cpu];
last_pid[cpu] = pid;
+
comm = trace_find_cmdline(pid);
+ prev_comm = trace_find_cmdline(prev_pid);
- return trace_seq_printf(s, "\n------------8<---------- thread %s-%d"
- " ------------8<----------\n\n",
- cpu, comm, pid);
+/*
+ * Context-switch trace line:
+
+ ------------------------------------------
+ | 1) migration/0--1 => sshd-1755
+ ------------------------------------------
+
+ */
+ ret = trace_seq_printf(s,
+ " ------------------------------------------\n");
+ ret += trace_seq_printf(s, " | %d) %s-%d => %s-%d\n",
+ cpu, prev_comm, prev_pid, comm, pid);
+ ret += trace_seq_printf(s,
+ " ------------------------------------------\n\n");
+ return ret;
}
static bool
@@ -142,7 +173,7 @@ static inline int
print_graph_duration(unsigned long long duration, struct trace_seq *s)
{
unsigned long nsecs_rem = do_div(duration, 1000);
- return trace_seq_printf(s, "%4llu.%3lu us | ", duration, nsecs_rem);
+ return trace_seq_printf(s, "%4llu.%3lu us | ", duration, nsecs_rem);
}
/* Signal a overhead of time execution to the output */
@@ -229,7 +260,7 @@ print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
}
/* No time */
- ret = trace_seq_printf(s, " | ");
+ ret = trace_seq_printf(s, " | ");
/* Function */
for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
--
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