tracing/function-branch-tracer: enhancements for the trace output

Impact: enhancement

This patch applies some ideas of Ingo Molnar and Steven Rostedt.

* Output leaf functions in one line with parenthesis, semicolon and duration output.

* Add a second column (after cpu) for an overhead sign. if duration > 100 us, "!"
if duration > 10 us, "+"
else " "

* Print output in us with remaining nanosec: u.n

* Print duration on the right end, following the indentation of the functions. Use also visual clues: "-" on entry call (no duration to output) and "+" on return (duration output).

The name of the tracer has been fixed as well: function-branch becomes function_branch.

Here is an example of the new output:

CPU[000] dequeue_entity() { -
CPU[000] update_curr() { -
CPU[000] update_min_vruntime(); + 0.512 us

CPU[000]             }                                + 1.504 us
CPU[000]             clear_buddies();                    + 0.481 us
CPU[000]             update_min_vruntime();                    + 0.504 us

CPU[000] } + 4.557 us
CPU[000] hrtick_update() { -
CPU[000] hrtick_start_fair(); + 0.489 us
CPU[000] } + 1.443 us
CPU[000] + } + 14.655 us
CPU[000] + } + 15.678 us

CPU[000] +   }                                + 16.686 us
CPU[000]     msecs_to_jiffies();                    + 0.481 us
CPU[000]     put_prev_task_fair();                    + 0.504 us
CPU[000]     pick_next_task_fair();                    + 0.482 us
CPU[000]     pick_next_task_rt();                    + 0.504 us
CPU[000]     pick_next_task_fair();                    + 0.481 us
CPU[000]     pick_next_task_idle();                    + 0.489 us
CPU[000]     _spin_trylock();                    + 0.655 us
CPU[000]     _spin_unlock();                    + 0.609 us

CPU[000] ------------8<---------- thread bash-2794 ------------8<----------

CPU[000] finish_task_switch() { -
CPU[000] _spin_unlock_irq(); + 0.722 us
CPU[000] } + 2.369 us
CPU[000] ! } + 501972.605 us
CPU[000] ! } + 501973.763 us
CPU[000] copy_from_read_buf() { -

CPU[000]             _spin_lock_irqsave();                    + 0.670 us
CPU[000]             _spin_unlock_irqrestore();                    + 0.699 us
CPU[000]             copy_to_user() {                    -

CPU[000] might_fault() { -
CPU[000] __might_sleep(); + 0.503 us
CPU[000] } + 1.632 us
CPU[000] __copy_to_user_ll(); + 0.542 us
CPU[000] } + 3.858 us
CPU[000] tty_audit_add_data() { -
CPU[000] _spin_lock_irq(); + 0.609 us
CPU[000] _spin_unlock_irq(); + 0.624 us

CPU[000]             }                                + 3.196 us
CPU[000]             _spin_lock_irqsave();                    + 0.624 us
CPU[000]             _spin_unlock_irqrestore();                    + 0.625 us

CPU[000] + } + 13.611 us
CPU[000] copy_from_read_buf() { -
CPU[000] _spin_lock_irqsave(); + 0.624 us
CPU[000] _spin_unlock_irqrestore(); + 0.616 us
CPU[000] } + 2.820 us
CPU[000]

Signed-off-by Frederic Weisbecker <[email protected]>

---
 kernel/trace/trace_functions_graph.c |  168 ++++++++++++++++++++++++++++++++--
 1 files changed, 159 insertions(+), 9 deletions(-)

kernel/trace/trace_functions_graph.c +159 -10

index d31d695..b958d60 100644
@@ -14,6 +14,10 @@
 #include "trace.h"
 
 #define TRACE_GRAPH_INDENT     2
+/* Spaces between function call and time duration */
+#define TRACE_GRAPH_TIMESPACE_ENTRY    "                    "
+/* Spaces between function call and closing braces */
+#define TRACE_GRAPH_TIMESPACE_RET      "                               "
 
 #define TRACE_GRAPH_PRINT_OVERRUN      0x1
 static struct tracer_opt trace_opts[] = {

@@ -63,26 +67,130 @@ static int verif_pid(struct trace_seq *s, pid_t pid, int cpu)
       last_pid[cpu] = pid;
       comm = trace_find_cmdline(pid);
 
-       return trace_seq_printf(s, "\nCPU[%03d]"
+       return trace_seq_printf(s, "\nCPU[%03d] "
                                   " ------------8<---------- thread %s-%d"
                                   " ------------8<----------\n\n",
                                   cpu, comm, pid);
 }
 
+static bool
+trace_branch_is_leaf(struct trace_iterator *iter,
+               struct ftrace_graph_ent_entry *curr)
+{
+       struct ring_buffer_iter *ring_iter;
+       struct ring_buffer_event *event;
+       struct ftrace_graph_ret_entry *next;
+
+       ring_iter = iter->buffer_iter[iter->cpu];
+
+       if (!ring_iter)
+               return false;
+
+       event = ring_buffer_iter_peek(iter->buffer_iter[iter->cpu], NULL);
+
+       if (!event)
+               return false;
+
+       next = ring_buffer_event_data(event);
+
+       if (next->ent.type != TRACE_GRAPH_RET)
+               return false;
+
+       if (curr->ent.pid != next->ent.pid ||
+                       curr->graph_ent.func != next->ret.func)
+               return false;
+
+       return true;
+}
+
+
+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, "+ %llu.%lu us\n", duration, nsecs_rem);
+}
+
+/* Signal a overhead of time execution to the output */
+static int
+print_graph_overhead(unsigned long long duration, struct trace_seq *s)
+{
+       /* Duration exceeded 100 msecs */
+       if (duration > 100000ULL)
+               return trace_seq_printf(s, "! ");
+
+       /* Duration exceeded 10 msecs */
+       if (duration > 10000ULL)
+               return trace_seq_printf(s, "+ ");
+
+       return trace_seq_printf(s, "  ");
+}
+
+/* Case of a leaf function on its call entry */
 static enum print_line_t
-print_graph_entry(struct ftrace_graph_ent *call, struct trace_seq *s,
-                 struct trace_entry *ent, int cpu)
+print_graph_entry_leaf(struct trace_iterator *iter,
+               struct ftrace_graph_ent_entry *entry, struct trace_seq *s)
 {
+       struct ftrace_graph_ret_entry *ret_entry;
+       struct ftrace_graph_ret *graph_ret;
+       struct ring_buffer_event *event;
+       struct ftrace_graph_ent *call;
+       unsigned long long duration;
       int i;
       int ret;
 
-       if (!verif_pid(s, ent->pid, cpu))
+       event = ring_buffer_read(iter->buffer_iter[iter->cpu], NULL);
+       ret_entry = ring_buffer_event_data(event);
+       graph_ret = &ret_entry->ret;
+       call = &entry->graph_ent;
+       duration = graph_ret->rettime - graph_ret->calltime;
+
+       /* Overhead */
+       ret = print_graph_overhead(duration, s);
+       if (!ret)
               return TRACE_TYPE_PARTIAL_LINE;
 
-       ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
+       /* Function */
+       for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
+               ret = trace_seq_printf(s, " ");
+               if (!ret)
+                       return TRACE_TYPE_PARTIAL_LINE;
+       }
+
+       ret = seq_print_ip_sym(s, call->func, 0);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       ret = trace_seq_printf(s, "();");
       if (!ret)
               return TRACE_TYPE_PARTIAL_LINE;
 
+       /* Duration */
+       ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_ENTRY);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       ret = print_graph_duration(duration, s);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t
+print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
+                       struct trace_seq *s)
+{
+       int i;
+       int ret;
+       struct ftrace_graph_ent *call = &entry->graph_ent;
+
+       /* No overhead */
+       ret = trace_seq_printf(s, "  ");
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       /* Function */
       for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
               ret = trace_seq_printf(s, " ");
               if (!ret)

@@ -93,26 +201,62 @@ print_graph_entry(struct ftrace_graph_ent *call, struct trace_seq *s,
       if (!ret)
               return TRACE_TYPE_PARTIAL_LINE;
 
-       ret = trace_seq_printf(s, "() {\n");
+       ret = trace_seq_printf(s, "() {");
       if (!ret)
               return TRACE_TYPE_PARTIAL_LINE;
+
+       /* No duration to print at this state */
+       ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_ENTRY "-\n");
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
       return TRACE_TYPE_HANDLED;
 }
 
 static enum print_line_t
+print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
+                       struct trace_iterator *iter, int cpu)
+{
+       int ret;
+       struct trace_entry *ent = iter->ent;
+
+       if (!verif_pid(s, ent->pid, cpu))
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       if (trace_branch_is_leaf(iter, field))
+               return print_graph_entry_leaf(iter, field, s);
+       else
+               return print_graph_entry_nested(field, s);
+
+}
+
+static enum print_line_t
 print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
                  struct trace_entry *ent, int cpu)
 {
       int i;
       int ret;
+       unsigned long long duration = trace->rettime - trace->calltime;
 
+       /* Pid */
       if (!verif_pid(s, ent->pid, cpu))
               return TRACE_TYPE_PARTIAL_LINE;
 
+       /* Cpu */
       ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
       if (!ret)
               return TRACE_TYPE_PARTIAL_LINE;
 
+       /* Overhead */
+       ret = print_graph_overhead(duration, s);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       /* Closing brace */
       for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
               ret = trace_seq_printf(s, " ");
               if (!ret)

@@ -123,10 +267,16 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
       if (!ret)
               return TRACE_TYPE_PARTIAL_LINE;
 
-       ret = trace_seq_printf(s, "%llu\n", trace->rettime - trace->calltime);
+       /* Duration */
+       ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_RET);
+       if (!ret)
+               return TRACE_TYPE_PARTIAL_LINE;
+
+       ret = print_graph_duration(duration, s);
       if (!ret)
               return TRACE_TYPE_PARTIAL_LINE;
 
+       /* Overrun */
       if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
               ret = trace_seq_printf(s, " (Overruns: %lu)\n",
                                       trace->overrun);

@@ -146,7 +296,7 @@ print_graph_function(struct trace_iterator *iter)
       case TRACE_GRAPH_ENT: {
               struct ftrace_graph_ent_entry *field;
               trace_assign_type(field, entry);
-               return print_graph_entry(&field->graph_ent, s, entry,
+               return print_graph_entry(field, s, iter,
                                        iter->cpu);
       }
       case TRACE_GRAPH_RET: {

@@ -160,7 +310,7 @@ print_graph_function(struct trace_iterator *iter)
 }
 
 static struct tracer graph_trace __read_mostly = {
-       .name        = "function-graph",
+       .name        = "function_graph",
       .init        = graph_trace_init,
       .reset       = graph_trace_reset,
       .print_line = print_graph_function,
--

1.5.2.5

One detail. If you get a trace through the "trace" file, you will have no problem.
But if you cat trace_pipe, leaf functions are considered as nested.

This is because iter->buffer_iter[iter->cpu]; is very often (always?) false by using this file.
I don't know why yet....
But it makes the tracer unable to check the next entry to verify if it matches its own return.

Quoted 7 lines

One detail. If you get a trace through the "trace" file, you will have no problem.
But if you cat trace_pipe, leaf functions are considered as nested.

Quoted 5 lines

This is because iter->buffer_iter[iter->cpu]; is very often (always?) false by using this file.
I don't know why yet....
But it makes the tracer unable to check the next entry to verify if it matches its own return.

That's because trace_pipe does not use an iterator ;-) It is live stream.

There's two cases: static read and consume. On static read we can take our time and we iterate over the data in the file. The data does not get consumed so we use an iterator to traverse the data.

The consume read will consume each entry as it reads it. We do not need an iterator for this because we are always reading the head of the file. After we read the data, that data is consumed and we read the next item.

Hmm, I may need to make this apparent to the plugins like yours. This way you can do different things whether it is a static read or a consuming read.

Perhaps the info now is what you already found out. "iter->buffer_iter[iter->cpu] will always be NULL when it is a consuming read. Intead you need to use:

ring_buffer_peek instead of ring_buffer_iter_peek

and

ring_buffer_consume instead of ring_buffer_read

This is the way you can use it:

entry = ring_buffer_peek(iter->tr->buffer, iter->cpu, NULL); entry = ring_buffer_consume(iter->tr->buffer, iter->cpu, NULL);

Impact: enhancement

This patch applies some ideas of Ingo Molnar and Steven Rostedt.

* Output leaf functions in one line with parenthesis, semicolon and duration output.

* Add a second column (after cpu) for an overhead sign. if duration > 100 us, "!"
if duration > 10 us, "+"
else " "

* Print output in us with remaining nanosec: u.n

* Print duration on the right end, following the indentation of the functions. Use also visual clues: "-" on entry call (no duration to output) and "+" on return (duration output).

The name of the tracer has been fixed as well: function-branch becomes function_branch.

Here is an example of the new output:

CPU[000] dequeue_entity() { -
CPU[000] update_curr() { -
CPU[000] update_min_vruntime(); + 0.512 us

CPU[000]             }                                + 1.504 us
CPU[000]             clear_buddies();                    + 0.481 us
CPU[000]             update_min_vruntime();                    + 0.504 us

CPU[000] } + 4.557 us
CPU[000] hrtick_update() { -
CPU[000] hrtick_start_fair(); + 0.489 us
CPU[000] } + 1.443 us
CPU[000] + } + 14.655 us
CPU[000] + } + 15.678 us

CPU[000] +   }                                + 16.686 us
CPU[000]     msecs_to_jiffies();                    + 0.481 us
CPU[000]     put_prev_task_fair();                    + 0.504 us
CPU[000]     pick_next_task_fair();                    + 0.482 us
CPU[000]     pick_next_task_rt();                    + 0.504 us
CPU[000]     pick_next_task_fair();                    + 0.481 us
CPU[000]     pick_next_task_idle();                    + 0.489 us
CPU[000]     _spin_trylock();                    + 0.655 us
CPU[000]     _spin_unlock();                    + 0.609 us

CPU[000] ------------8<---------- thread bash-2794 ------------8<----------

CPU[000] finish_task_switch() { -
CPU[000] _spin_unlock_irq(); + 0.722 us
CPU[000] } + 2.369 us
CPU[000] ! } + 501972.605 us
CPU[000] ! } + 501973.763 us
CPU[000] copy_from_read_buf() { -

CPU[000]             _spin_lock_irqsave();                    + 0.670 us
CPU[000]             _spin_unlock_irqrestore();                    + 0.699 us
CPU[000]             copy_to_user() {                    -

CPU[000] might_fault() { -
CPU[000] __might_sleep(); + 0.503 us
CPU[000] } + 1.632 us
CPU[000] __copy_to_user_ll(); + 0.542 us
CPU[000] } + 3.858 us
CPU[000] tty_audit_add_data() { -
CPU[000] _spin_lock_irq(); + 0.609 us
CPU[000] _spin_unlock_irq(); + 0.624 us

CPU[000]             }                                + 3.196 us
CPU[000]             _spin_lock_irqsave();                    + 0.624 us
CPU[000]             _spin_unlock_irqrestore();                    + 0.625 us

CPU[000] + } + 13.611 us
CPU[000] copy_from_read_buf() { -
CPU[000] _spin_lock_irqsave(); + 0.624 us
CPU[000] _spin_unlock_irqrestore(); + 0.616 us
CPU[000] } + 2.820 us
CPU[000]

Furthermore, it would be really sweet if ftrace_printk() output would be at the right indentation level wrt the function it was called from. eg.

CPU[000] - do_sync_read() {
CPU[000] # sock: 0x12345 flag: 1
CPU[000] - sock_aio_read() {
...
CPU[000] + 0.123 }

Where the # line is the ftrace_printk() output.

I didn't think of ftrace_printk yet. That's a good idea, this way we will see where the ftrace_printk was called, in which function at which depth....

Don't you think that would be better to have it as C comments. We are in a C-style output and ftrace_printk are especially designed for comments in a trace. That would make sense to read:

       do_sync_read() {
          /* sock: 0x12345 flag: 1 */
          sock_aio_read() {

Here is an example of the new output:

CPU[000] dequeue_entity() { -
CPU[000] update_curr() { -
CPU[000] update_min_vruntime(); + 0.512 us

CPU[000]             }                                + 1.504 us
CPU[000]             clear_buddies();                    + 0.481 us
CPU[000]             update_min_vruntime();                    + 0.504 us

CPU[000] } + 4.557 us
CPU[000] hrtick_update() { -
CPU[000] hrtick_start_fair(); + 0.489 us
CPU[000] } + 1.443 us
CPU[000] + } + 14.655 us
CPU[000] + } + 15.678 us

CPU[000] +   }                                + 16.686 us
CPU[000]     msecs_to_jiffies();                    + 0.481 us
CPU[000]     put_prev_task_fair();                    + 0.504 us
CPU[000]     pick_next_task_fair();                    + 0.482 us
CPU[000]     pick_next_task_rt();                    + 0.504 us
CPU[000]     pick_next_task_fair();                    + 0.481 us
CPU[000]     pick_next_task_idle();                    + 0.489 us
CPU[000]     _spin_trylock();                    + 0.655 us
CPU[000]     _spin_unlock();                    + 0.609 us

CPU[000] ------------8<---------- thread bash-2794 ------------8<----------

CPU[000] finish_task_switch() { -
CPU[000] _spin_unlock_irq(); + 0.722 us
CPU[000] } + 2.369 us
CPU[000] ! } + 501972.605 us
CPU[000] ! } + 501973.763 us
CPU[000] copy_from_read_buf() { -

CPU[000]             _spin_lock_irqsave();                    + 0.670 us
CPU[000]             _spin_unlock_irqrestore();                    + 0.699 us
CPU[000]             copy_to_user() {                    -

CPU[000] might_fault() { -
CPU[000] __might_sleep(); + 0.503 us
CPU[000] } + 1.632 us
CPU[000] __copy_to_user_ll(); + 0.542 us
CPU[000] } + 3.858 us
CPU[000] tty_audit_add_data() { -
CPU[000] _spin_lock_irq(); + 0.609 us
CPU[000] _spin_unlock_irq(); + 0.624 us

CPU[000]             }                                + 3.196 us
CPU[000]             _spin_lock_irqsave();                    + 0.624 us
CPU[000]             _spin_unlock_irqrestore();                    + 0.625 us

CPU[000] + } + 13.611 us
CPU[000] copy_from_read_buf() { -
CPU[000] _spin_lock_irqsave(); + 0.624 us
CPU[000] _spin_unlock_irqrestore(); + 0.616 us
CPU[000] } + 2.820 us
CPU[000]

Quoted 4 lines · Frederic Weisbecker

Here is an example of the new output:

CPU[000] ------------8<---------- thread bash-2794 ------------8<----------

Quoted 6 lines · Ingo Molnar

Quoted 4 lines · Frederic Weisbecker

Here is an example of the new output:

CPU[000] ------------8<---------- thread bash-2794 ------------8<----------

This is the most horrid thing I've ever seen.

Please just put the comm/pid in another left column and leave a plain "---" string for context switches.

comm/pid only in the separator is useless, you cannot grep stuff like that, also, what's up with those '8's ?

That extra column should be a trace_option though - default-off. (it uses up quite some screen real estate) It would have to have a width of 14 characters to be practical:

   ssssssss-12345

mockup:

----------------------------------------------------------------
CPU) task-PID | cost | function
----------------------------------------------------------------

 0)     bash-54320 |             |  sys_read() {
 0)     bash-54320 |    0.331 us |    fget_light();
 0)     bash-54320 |             |    vfs_read() {
 0) mycomman-1234  |             |      rw_verify_area() {
 0) mycomman-1234  |  121.444 us |        func();

Note some details:

1) longer comm names can be stripped off at 7 chars - 7 chars is enough to recognize most of the things and the PID is good enough for extra separation)

2) the ssssssss-12345 task identifier is _center_ aligned. It's a rare alignment case but useful here: most people look at the command portion and the whole string must be greppable and useful in traces as an identifier - so right-aligning the PID is not a good solution.

3) there's vertical separation after the task portion as well. This helps us ignore the task portion when we want to look at only the code and the cost of it. (the common case)

Quoted 2 lines

comm/pid only in the separator is useless, you cannot grep stuff like that, also, what's up with those '8's ?

yeah, that context-switch separator is horrible.

We can keep the separator, but as something saner, like:

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |    }
 0)             |    do_sync_read() {
                .   -------------------------
 0)             ==> [ bash-2794 => cat-1234 ]
                    -------------------------

 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
 0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

Note the six small details:

1) '==>' sign put to the vertical separator. This shows that something flow-intrusive (context-switch) happened.

2) The context-switch printout is in a little box that separates it from the flow of the outgoing task.

3) there's an extra newline for the incoming flow. Context-switches are usually attached to the outgoing flow - the incoming flow is picked semi-randomly, so the newline is a visual separator for that fact.

4) it uses the ssssssss-12345 taskname convention for both the outgoing and the incoming task. That makes it greppable generally.

5) the '----------' lines of the 'box' have no CPU nor task or cost field. That makes it easy to grep them out - but they are still helpful visual cues. They are variable length but that's solvable by using an 'open box' simplification:

    0)    0.300 us |          cap_file_permission();
    0)    8.909 us |        }
    0)    0.993 us |      }
    0)   11.649 us |    }
    0)             |    do_sync_read() {
                   .   -----------------------------------
    0)             ==> [ bash-2794 => cat-1234
                       -----------------------------------

Note how the box top and bottom is 35 characters, fixed. That looks good with most task identifiers. Even in the worst-case length length situation it looks good:

                   .   -----------------------------------
    0)             ==> [ mycomman-12345 => mycomman-12345
                       -----------------------------------

Or it could be printed out variable length as well - it's a solvable task :-)

6) note the small dot in the leadin to a context-switch: it's intentional.

Ingo

mockup:

----------------------------------------------------------------
CPU) task-PID | cost | function
----------------------------------------------------------------

  0)     bash-54320 |             |  sys_read() {
  0)     bash-54320 |    0.331 us |    fget_light();
  0)     bash-54320 |             |    vfs_read() {
  0) mycomman-1234  |             |      rw_verify_area() {
  0) mycomman-1234  |  121.444 us |        func();

Note some details:

1) longer comm names can be stripped off at 7 chars - 7 chars is enough to recognize most of the things and the PID is good enough for extra separation)

2) the ssssssss-12345 task identifier is _center_ aligned. It's a rare alignment case but useful here: most people look at the command portion and the whole string must be greppable and useful in traces as an identifier - so right-aligning the PID is not a good solution.

3) there's vertical separation after the task portion as well. This helps us ignore the task portion when we want to look at only the code and the cost of it. (the common case)

Quoted 2 lines

comm/pid only in the separator is useless, you cannot grep stuff like that, also, what's up with those '8's ?

yeah, that context-switch separator is horrible.

We can keep the separator, but as something saner, like:

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

  0)             |  sys_read() {
  0)    0.331 us |    fget_light();
  0)             |    vfs_read() {
  0)             |      rw_verify_area() {
  0)             |        security_file_permission() {
  0)    0.306 us |          cap_file_permission();
  0)    0.300 us |          cap_file_permission();
  0)    8.909 us |        }
  0)    0.993 us |      }
  0)   11.649 us |    }
  0)             |    do_sync_read() {
                 .   -------------------------
  0)             ==> [ bash-2794 => cat-1234 ]
                     -------------------------

  0)             |        __sock_recvmsg() {
  0)             |          security_socket_recvmsg() {
  0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

Quoted 55 lines · Ingo Molnar

mockup:

----------------------------------------------------------------
CPU) task-PID | cost | function
----------------------------------------------------------------

  0)     bash-54320 |             |  sys_read() {
  0)     bash-54320 |    0.331 us |    fget_light();
  0)     bash-54320 |             |    vfs_read() {
  0) mycomman-1234  |             |      rw_verify_area() {
  0) mycomman-1234  |  121.444 us |        func();

Note some details:

1) longer comm names can be stripped off at 7 chars - 7 chars is enough to recognize most of the things and the PID is good enough for extra separation)

2) the ssssssss-12345 task identifier is _center_ aligned. It's a rare alignment case but useful here: most people look at the command portion and the whole string must be greppable and useful in traces as an identifier - so right-aligning the PID is not a good solution.

3) there's vertical separation after the task portion as well. This helps us ignore the task portion when we want to look at only the code and the cost of it. (the common case)

Quoted 2 lines

comm/pid only in the separator is useless, you cannot grep stuff like that, also, what's up with those '8's ?

yeah, that context-switch separator is horrible.

We can keep the separator, but as something saner, like:

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

  0)             |  sys_read() {
  0)    0.331 us |    fget_light();
  0)             |    vfs_read() {
  0)             |      rw_verify_area() {
  0)             |        security_file_permission() {
  0)    0.306 us |          cap_file_permission();
  0)    0.300 us |          cap_file_permission();
  0)    8.909 us |        }
  0)    0.993 us |      }
  0)   11.649 us |    }
  0)             |    do_sync_read() {
                 .   -------------------------
  0)             ==> [ bash-2794 => cat-1234 ]
                     -------------------------

Quoted 4 lines

  0)             |        __sock_recvmsg() {
  0)             |          security_socket_recvmsg() {
  0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

Yes please. I like the separator better. Sure, we could add a trace_option that will let us print the name on all lines, which will make it grepable better. But this is better to see when the switch happens.

Also, Frederic could use my ftrace_trace_pid to filter only on a single thread. But that will need to wait till we figure out this namespace issue.

Quoted 6 lines · Frederic Weisbecker

Quoted 5 lines

Here is an example of the new output:

CPU[000] ------------8<---------- thread bash-2794 ------------8<----------

This is the most horrid thing I've ever seen.

Please just put the comm/pid in another left column and leave a plain "---" string for context switches.

comm/pid only in the separator is useless, you cannot grep stuff like that, also, what's up with those '8's ?

2008/11/27 Peter Zijlstra <[email protected]>:

Quoted 13 lines · Ingo Molnar

Quoted 6 lines · Frederic Weisbecker

Quoted 5 lines

Here is an example of the new output:

CPU[000] ------------8<---------- thread bash-2794 ------------8<----------

This is the most horrid thing I've ever seen.

Please just put the comm/pid in another left column and leave a plain "---" string for context switches.

Quoted 2 lines

comm/pid only in the separator is useless, you cannot grep stuff like that, also, what's up with those '8's ?

You don't like my ungreppable but cute scissors? :-) Yes, I will fix it.

But in fact, it might be even better to display the costs like this, on the left side [mockup]:

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |    }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
 0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

note the 8 small tweaks i did to optimize the visual real estate of the tracer output:

1) we done need reminders on the left side that this is about CPU numbers. It will be obvious anyway if it's "all mixed up". (microseconds is different - that is a unit that will be quoted and it's also a number that actually matters more in the daily use of such traces )

2) no need for [] on the left side - a single separator is enough. I picked ')' as it looks pretty natural and unintrusive.

3) we should use the CPU number width on the left side that log10(cpus_weight_nr(cpu_online_map)) tells us. So if a system has just two cores, we should print single-width. If it has 16 CPUs, we should print 00..01....15.

4) I left 4 decimal points for the cost. That's up to 9999.999 microseconds, after that point we should lose precision and print:
99999.99, then should print up to 999999.9, and then print up to 99999999 microseconds. Always keep the length of the number at 8 characters. Above that, just let the rest shift to the right a bit. (but that will be about delays of more than 100 seconds - that does not really matter in practice)

5) Note, by printing the cost at fixed width, we can leave out the '+' and '!' visual alerts (sorry! :-). The visible width of the numbers will be enough of an attention grabber - as you can see it in the mockup above already.

6) Note the vertical '|' separator. I tried it with and without, and i think the code on the right side looks more structured that way. It looks like a sheet of paper, and it looks tidier - so please add it.

7) Note how unobscured the right side code portion looks like this way. Since this is the only piece of information that is heavily variable-width, we keep it at the end and dont worry about length problems.

8) Please print this in the trace header:

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

The tabulation format and the field names makes it all more familar and more friendly to people.

What do you think?

Ingo

2008/11/27 Ingo Molnar <[email protected]>:

Quoted 59 lines

But in fact, it might be even better to display the costs like this, on the left side [mockup]:

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |    }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
 0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

note the 8 small tweaks i did to optimize the visual real estate of the tracer output:

1) we done need reminders on the left side that this is about CPU numbers. It will be obvious anyway if it's "all mixed up". (microseconds is different - that is a unit that will be quoted and it's also a number that actually matters more in the daily use of such traces )

2) no need for [] on the left side - a single separator is enough. I picked ')' as it looks pretty natural and unintrusive.

3) we should use the CPU number width on the left side that log10(cpus_weight_nr(cpu_online_map)) tells us. So if a system has just two cores, we should print single-width. If it has 16 CPUs, we should print 00..01....15.

4) I left 4 decimal points for the cost. That's up to 9999.999 microseconds, after that point we should lose precision and print:
99999.99, then should print up to 999999.9, and then print up to 99999999 microseconds. Always keep the length of the number at 8 characters. Above that, just let the rest shift to the right a bit. (but that will be about delays of more than 100 seconds - that does not really matter in practice)

5) Note, by printing the cost at fixed width, we can leave out the '+' and '!' visual alerts (sorry! :-). The visible width of the numbers will be enough of an attention grabber - as you can see it in the mockup above already.

6) Note the vertical '|' separator. I tried it with and without, and i think the code on the right side looks more structured that way. It looks like a sheet of paper, and it looks tidier - so please add it.

Quoted 4 lines

7) Note how unobscured the right side code portion looks like this way. Since this is the only piece of information that is heavily variable-width, we keep it at the end and dont worry about length problems.

Yeah, I will miss a bit the overhead signs, they were really useful to find in one quick sight a costly function call. I know that the decimal. The visible width of the duration replaces it but not as much efficiently. Moreover, put these times on the full left will be perhaps harder for the eyes to retrieve the concerned function return (thinking of a deep calls).

Quoted 4 lines

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

Quoted 15 lines

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
+0)   11.649 us |    }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
!0)  100.319 us |            cap_socket_recvmsg();

Quoted 1 line

---------------------------------------------------------

Quoted 4 lines

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

Quoted 15 lines

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |+   }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
 0)  100.319 us |!           cap_socket_recvmsg();

Quoted 1 line

---------------------------------------------------------

I don't know, perhaps that will actually be better in practice...

We can still add the overhead signs.

We still have a single space in the first column before the CPU number (that looks better when these traces are pasted into email, which is one of the most common uses of them), and we can add the sign there.

I.e. something like this:

Quoted 4 lines

Quoted 4 lines

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

Quoted 16 lines

Quoted 15 lines

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
+0)   11.649 us |    }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
!0)  100.319 us |            cap_socket_recvmsg();

Quoted 1 line

---------------------------------------------------------

Or we could add them to the function name bit - there we have two free space characters anyway:

Something like this:

Quoted 4 lines

Quoted 4 lines

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

Quoted 16 lines

Quoted 15 lines

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |+   }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
 0)  100.319 us |!           cap_socket_recvmsg();

Quoted 1 line

---------------------------------------------------------

Hm?

Quoted 2 lines

I don't know, perhaps that will actually be better in practice...

i think it will be better. I'm biased, so i gave the output to two people with good visual taste (one of them female), [note, i gave them the mockup from the previous mail] and the first question of both of them was: "why arent the times on the left?".

I think we could make the time column a trace_option as well - default-enabled.

Quoted 8 lines

Quoted 8 lines

Quoted 8 lines

 0)    0.993 us |      }
+0)   11.649 us |    }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
!0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

I like it before the CPU number. The main purpose would be to scroll quickly the file and find the overheads. That would be easy if set as a first character.

I will set it as a default disabled option.

Quoted 10 lines

Quoted 9 lines

Quoted 9 lines

Quoted 9 lines

 0)    0.993 us |      }
+0)   11.649 us |    }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
!0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

Quoted 5 lines

I like it before the CPU number. The main purpose would be to scroll quickly the file and find the overheads. That would be easy if set as a first character.

I will set it as a default disabled option.

lets keep it default-enabled, ok? It makes sense.

2008/11/27 Ingo Molnar <[email protected]>:

Quoted 12 lines · Frédéric Weisbecker

Quoted 10 lines

Quoted 9 lines

Quoted 9 lines

Quoted 9 lines

 0)    0.993 us |      }
+0)   11.649 us |    }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
!0)  100.319 us |            cap_socket_recvmsg();

---------------------------------------------------------

Quoted 7 lines

Quoted 5 lines

I like it before the CPU number. The main purpose would be to scroll quickly the file and find the overheads. That would be easy if set as a first character.

I will set it as a default disabled option.

lets keep it default-enabled, ok? It makes sense.

Ok.
BTW I understand why it is better to have a "pipe" if there is no time:

  0)             |    do_sync_read() {
  0)             |      sock_aio_read() {
  0)             |        __sock_recvmsg() {
  0)             |          security_socket_recvmsg() {

But I don't see why it is necessary to have one just after the time:

!0) 100.319 us | cap_socket_recvmsg();

It appears to me as noise....

if you look at it on a console where you look at code, it all looks like a straight line:

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |    }
 0)             |    do_sync_read() {
                .   -------------------------
 0)             ==> [ bash-2794 => cat-1234 ]
                    -------------------------

as if the code to the right was on a sheet of paper.

If i understand you correct, are you suggesting this format:

0) | sys_read() {
0) 0.331 us fget_light();

 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us            cap_file_permission();
 0)    0.300 us            cap_file_permission();
 0)    8.909 us          }
 0)    0.993 us        }
 0)   11.649 us      }
 0)             |    do_sync_read() {
                .   -------------------------
 0)             ==> [ bash-2794 => cat-1234 ]
                    -------------------------

i dont think that looks very good.

Quoted 22 lines

Quoted 21 lines

Quoted 21 lines

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |+   }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
 0)  100.319 us |!           cap_socket_recvmsg();

---------------------------------------------------------

Quoted 1 line

Hm?

I like it before the CPU number. The main purpose would be to scroll quickly the file and find the overheads. That would be easy if set as a first character.

No, please keep the CPU # first. If anything, you will want to separate out the CPUs first. Otherwise you will see things all mixed up.

Hmm, I could also add a per cpu files.

debugfs/tracing/buffers/cpu0
debugfs/tracing/buffers/cpu1
debugfs/tracing/buffers/cpu2
debugfs/tracing/buffers/cpu3

That would print out the trace for a single CPU.

BTW, I'm really not here. I'm on holiday eating turkeys.

Quoted 22 lines · Fr?d?ric Weisbecker

Quoted 22 lines

Quoted 21 lines

Quoted 21 lines

---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------

 0)             |  sys_read() {
 0)    0.331 us |    fget_light();
 0)             |    vfs_read() {
 0)             |      rw_verify_area() {
 0)             |        security_file_permission() {
 0)    0.306 us |          cap_file_permission();
 0)    0.300 us |          cap_file_permission();
 0)    8.909 us |        }
 0)    0.993 us |      }
 0)   11.649 us |+   }
 0)             |    do_sync_read() {
 0)             |      sock_aio_read() {
 0)             |        __sock_recvmsg() {
 0)             |          security_socket_recvmsg() {
 0)  100.319 us |!           cap_socket_recvmsg();

---------------------------------------------------------

Quoted 5 lines

Quoted 1 line

Hm?

I like it before the CPU number. The main purpose would be to scroll quickly the file and find the overheads. That would be easy if set as a first character.

No, please keep the CPU # first. If anything, you will want to separate out the CPUs first. Otherwise you will see things all mixed up.

Hmm, I could also add a per cpu files.

debugfs/tracing/buffers/cpu0
debugfs/tracing/buffers/cpu1
debugfs/tracing/buffers/cpu2
debugfs/tracing/buffers/cpu3

That would print out the trace for a single CPU.

BTW, I'm really not here. I'm on holiday eating turkeys.