Re: [PATCH] tracing/function-graph-tracer: adjustments of the trace informations




* Frederic Weisbecker <fweisbec@xxxxxxxxx> 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@xxxxxxx>
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@xxxxxxx>
---
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@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/