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

[Ingo Molnar]

* 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

------------------->