Re: [PATCH] tracing/function-return-tracer: set a more human readable output

[Ingo Molnar <mingo@elte.hu>]

* Ingo Molnar <mingo@elte.hu> wrote:

> Wow, very nice output! :-)
> 
> I've applied them, will comment and test on them as well.

I kept playing with this for almost an hour and kept looking at pages 
and pages of tracer output - it really shows the kernel's flow in a 
completely different dimension!

Talked to Steve about it and we have a few minor suggestions regarding 
the default output:

I think we should optimize the visual qualities of the output some 
more.

Instead of:

 pick_next_task() {   
   pick_next_task_fair() {   
     wakeup_preempt_entity() { 
     } 301
     set_next_entity() {    
       update_stats_wait_end() { 
       } 281
       __dequeue_entity() { 
       } 319
     } 1990
     hrtick_start_fair() { 
     } 276
   } 4524                                 
 } 5341                 

We should print such traces [mockup]:

   pick_next_task() {                     -
     pick_next_task_fair() {                -
       wakeup_preempt_entity();               + 0.301 us
       set_next_entity() {                    -
         update_stats_wait_end();               + 0.281 us
         __dequeue_entity();                    + 0.319 us
       }                                      + 1.990 us
       hrtick_start_fair();                   + 0.276 us
 +   }                                      + 10.524 us
 ! }                                      + 100.341 us
   switch_mm();                           + 0.494 us

The changes would be:

1) Compression of non-nested calls into a single line.

   Implementing this probably necessiates some trickery with the
   ring-buffer: we'd have to look at the next entry as well and see 
   whether it closes the function call.

2) Adding a closing ';' semicolon to single-line calls. It's the C 
   syntax and i'm missing it :-)

3) The first column: single-character visual shortcuts for "overhead". 
   This is a concept we used in the -rt tracer and it still lives in 
   the latency tracer bits of ftrace and is quite useful:

    '+' means "overhead spike": overhead is above 10 usecs.
    '!' means "large overhead": overhead is above 100 usecs.

   These give at-a-glance hotspot analysis - hotspots are easier to 
   miss as pure numbers.

4) Printing out in units of microseconds, with a decimal point and by
   explicitly mentioning the 'us' unit.

   All of these are important properties: microseconds is still the 
   most common 'overhead' unit in kernel circles. It also gives rather 
   human single-digit or two-digit results. Nanoseconds is three or- 
   four-digit - which is too much. Repeating 'us' so many times is not 
   a problem - these lines will be grepped, quoted, etc - constant 
   reminder about the unit is just fine.

5) Nesting the overhead numbers aligned to the right end of the graph. 
 
   This cleans up the view of the source code printout, but not 
   cluttering it with numbers. It also structures the numbers some 
   more. Visual cues are given via '-' and '+' signs, to follow 
   nesting. This nesting aligns up with the function nesting levels on 
   the left side - so it's easy to pair up number and function name. 
   It also separates the numbers from the symbol length effects in the 
   single-line case. (which is the most common trace line)

What do you think? It's lots of work (sorry! :-), but it would produce 
even more stunning graph-tracer output IMO.

	Ingo