tracing/function-graph-tracer: adjustments of the trace informations

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 |       }

From d51090b34602a20984ab0312ef04e47069c0aec6 Mon Sep 17 00:00:00 2001

another thing which i'm sure you are aware of:

# tracer: function_graph
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
------------------------------------------
| 1) S99local--1 => ssh-1724
------------------------------------------

 1)      0.867 us |        }
 1)               |        mark_page_accessed() {
 1)      0.293 us |          constant_test_bit();
 1)      0.294 us |          constant_test_bit();

[...]

the header description is now out of of sync :-)

Also, we should probably not start the trace with a PID-switch event. the last_pid[] markers are probably out of sync when we start printing the trace.

So the output should probably be something like:

# tracer: function_graph
#
# CPU COST FUNCTION-GRAPH
# | | |

 1)      0.867 us |        }
 1)               |        mark_page_accessed() {
 1)      0.293 us |          constant_test_bit();
 1)      0.294 us |          constant_test_bit();

[...]

another detail: it would be nice to annotate IRQ entries some more.

right now if a syscall is interrupted by a hardware interrupt, it looks like this:

 0)               |              skb_dequeue() {
 0)      0.365 us |                _spin_lock_irqsave();
 0)      0.422 us |                _spin_unlock_irqrestore();
 0)      1.912 us |              }
 0)               |              memcpy_toiovec() {
 0)               |                copy_to_user() {
 0)               |                  smp_apic_timer_interrupt() {
 0)      0.450 us |                    native_apic_mem_write();
 0)               |                    irq_enter() {
 0)      0.410 us |                      idle_cpu();
 0)      1.167 us |                    }
 0)               |                    hrtimer_interrupt() {

the natural nesting is nice, but easy to miss. It would be nice to have something like:

 0)               |              skb_dequeue() {
 0)      0.365 us |                _spin_lock_irqsave();
 0)      0.422 us |                _spin_unlock_irqrestore();
 0)      1.912 us |              }
 0)               |              memcpy_toiovec() {
 0)               |                copy_to_user() {
 0)             =====>               smp_apic_timer_interrupt() {
 0)      0.450 us |                    native_apic_mem_write();
 0)               |                    irq_enter() {
 0)      0.410 us |                      idle_cpu();
 0)      1.167 us |                    }
 0)               |                    hrtimer_interrupt() {

and perhaps something like this at the end of the irq frame:

 0)      0.408 us |                          _local_bh_enable();
 0) +   13.139 us |                        }
 0) +   13.887 us |                      }
 0)      0.406 us |                      idle_cpu();
 0) +   15.373 us |                    }
 0) +   74.564 us |                  }
 0)               |                  _cond_resched() {
 0)               |                    need_resched() {
 0)      0.423 us |                      constant_test_bit();
 0)      1.164 us |                    }
 0)      1.915 us <===               } /* IRQ 1 end */
 0) +   78.396 us |                }
 0) +   79.123 us |              }
 0)      0.387 us |              skb_pull();
 0)               |              kfree_skb() {

?

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

I tried to figure out a way to signal a hardirq in a trace, I like this arrow but It
breaks the indentation.
I would suggest:

  0)               |              skb_dequeue() {
  0)      0.365 us |                _spin_lock_irqsave();
  0)      0.422 us |                _spin_unlock_irqrestore();
  0)      1.912 us |              }
  0)               |              memcpy_toiovec() {
  0)               |                copy_to_user() {
             =====>
  0)               |               smp_apic_timer_interrupt() {
  0)      0.450 us |                    native_apic_mem_write();
  0)               |                    irq_enter() {
  0)      0.410 us |                      idle_cpu();
  0)      1.167 us |                    }
  0)               |                    hrtimer_interrupt() {

Your idea solves a part of one of the features I wanted to add: why not using a single character column to print
the current context: workqueue, syscall, kernel thread, tasklet, hardirq .....

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:

Review

Quoted 3 lines

(quoted diff) +3 -0

+     /* 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?

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

Quoted 14 lines

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:

Quoted 8 lines

 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
------------------------------------------

Thanks! That good, but I remember you wanted a limited number of characters for thread name/pid couple?

Quoted 34 lines

Secondly:

Review

Quoted 3 lines

(quoted diff) +3 -0

+     /* 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 ;-)

Quoted 2 lines

The moving decimal point above 10 milliseconds is not a big problem with the '+' and '!' marker. Maybe add a '!!' marker to these lines?

Yeah, I was sure I misunderstood your idea about it in your last email :-) Ok. I will do so, I felt a bit uncomfortable with the fixed width above a limit, so I like it this way. Long sleeping functions will be rare enough in the trace to let us move a bit the columns to the right in such cases...

Yeah, that needs updating. I supposed you'd be working on the task+pid column anyway, and do a helper function that prints the task-pid couple. Then that helper can be used in the context-switch case too to print out a uniform ID.

Another thing that would be nice is to separate out the "cpu)" printing bits into a helper function. Right now what exists cannot be used in a seq-manner, so i couldnt reuse it.

Anyway, i wont change it (just wanted to get a final-ish output to look at) so feel free to clean it all up thoroughly :)

Today i played with the graph-tracer on a testbox _way_ too much. Combined with the wildcard filter it's _really_ addictive. Kernel developers, beware!

One thing that came up: it would be nice to have an 'inverted' wildcard to punch out certain functions from the filter list. For example i did in the shell:

 $ echo 'sys_*'    >> set_ftrace_filter
 $ echo '*socket*' >> set_ftrace_filter
 $ echo '*timer*'  >> set_ftrace_filter
 $ echo '*skb*'    >> set_ftrace_filter

and looked at the trace and found that certain functions are too verbose and not really interesting - so i wanted to exclude them.

We've got set_ftrace_notrace but it's not really an inverse wildcard but a complementary set of filter functions - which is not the same and not as easy to think about as a single set of filter functions.

what i think would be more natural to do is via the filter file itself, via an extension like:

 $ echo '!timer_*' >> set_ftrace_filter

which would eliminate the functions matching that negative pattern. Such negative wildcards would act on the current set of functions, while set_ftrace_notrace is permanent and cannot be used to shape an arbitrary set of functions iteratively.

Quoted 4 lines

Another thing that would be nice is to separate out the "cpu)" printing bits into a helper function. Right now what exists cannot be used in a seq-manner, so i couldnt reuse it.

Isn't it the case with print_graph_cpu() ?