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/



Relevant Pages

  • Re: RT patch acceptance (scheduler)
    ... > lock up the CPU in IRQ mode for human-perceptible time, ... For non-DMA IDE access data copies are CPU driven ... which can create tons of latency problems for that case. ... I suggest that you read the patch for the answer to softirq ...
    (Linux-Kernel)
  • Re: Erratum 383 fix for 32 bit x86 kernels
    ... This patch fixes the occurence of AMD Erratum 383 on ... Please consider to include this patch into the -stable kernel series. ... CPU hotplug codepaths on a 32-bit kernel. ... These TLB entries are marked global and large. ...
    (Linux-Kernel)
  • Re: [PATCH try 5] CFS: Add hierarchical tree-based penalty.
    ... Find below the reply Peter sent to William's v5 patch. ... making deadlines offset by the fork depth from init. ... As can be seen, on the dual core machine, a load of 2 makes the benchmark run ... almost precisely 1/3 slower as would be expected with BFS' fair CPU ...
    (Linux-Kernel)
  • Re: better wake-balancing: respin
    ... >>I guess I missed the objection for dropping the patch. ... correlation between the CPU the interrupt arrives on and the CPU the ... There is no point in immediate balancing either: ... If this patch hurts other workloads (and please ...
    (Linux-Kernel)
  • [PATCH] v5 Teach RCU that idle task is not quiscent state at boot
    ... The boot CPU runs in the context of its idle thread during boot-up. ... RCU to prematurely end grace periods during this time. ... This patch changes the rcutree.c and rcuclassic.c rcu_check_callbacks ...
    (Linux-Kernel)