tracing/function-graph-tracer: improve duration output

Impact: better output of duration for long calls

The old duration output didn't exceeded 9999.999 us to fit the column and the nanosecs were always 3 numbers. As Ingo suggested, it's better to have the whole microseconds elapsed time and shift the nanosecs precision if needed to fit the maximum 7 numbers. And usec need more number, the case should be rare and important enough to break a bit the column alignment to show it.

So, depending of the duration value, we now have these patterns:

u.nnn
uu.nnn
uuu.nnn
uuuu.nnn
uuuuu.nn
uuuuuu.n
uuuuuuuu.....

Quoted 11 lines · Frederic Weisbecker

Impact: better output of duration for long calls

The old duration output didn't exceeded 9999.999 us to fit the column and the nanosecs were always 3 numbers. As Ingo suggested, it's better to have the whole microseconds elapsed time and shift the nanosecs precision if needed to fit the maximum 7 numbers. And usec need more number, the case should be rare and important enough to break a bit the column alignment to show it.

So, depending of the duration value, we now have these patterns:

Quoted 7 lines

u.nnn
uu.nnn
uuu.nnn
uuuu.nnn
uuuuu.nn
uuuuuu.n
uuuuuuuu.....

An example of a trace after these two patches (with funcgraph-proc enabled):

 0)    cat-2796    |               |            put_prev_task_fair() {
 0)    cat-2796    |   0.609 us    |              update_curr();
 0)    cat-2796    |   1.842 us    |            }
 0)    cat-2796    |               |            pick_next_task_fair() {
 0)    cat-2796    |   0.526 us    |              wakeup_preempt_entity();
 0)    cat-2796    |   0.797 us    |              set_next_entity();
 0)    cat-2796    |   0.541 us    |              hrtick_start_fair();
 0)    cat-2796    |   4.195 us    |            }
 0)    cat-2796    |   1.263 us    |            _spin_trylock();
 0)    cat-2796    |   0.624 us    |            _spin_unlock();
 0)    cat-2796    |   0.789 us    |            _spin_trylock();
 0)    cat-2796    |   0.617 us    |            _spin_unlock();
 0)    cat-2796    |   0.579 us    |            native_load_sp0();
 0)    cat-2796    |   0.722 us    |            native_load_tls();

------------------------------------------
| 0) cat-2796 => events/-9
------------------------------------------

 0)    cat-2796    |   0.579 us    |            native_load_sp0();
 0)    cat-2796    |   0.722 us    |            native_load_tls();

------------------------------------------
| 0) cat-2796 => events/-9
------------------------------------------

 0)   events/-9    |               |    finish_task_switch() {
 0)   events/-9    |   0.789 us    |      _spin_unlock_irq();
 0)   events/-9    |   2.309 us    |    }
 0)   events/-9    | ! 269848.5 us |  }

small detail: i'd suggest to remove the newline before the context-switch box. That makes it appear visually to attach logically with the switch-out place, not the switch-in place:

Quoted 6 lines

 0)    cat-2796    |   0.579 us    |            native_load_sp0();
 0)    cat-2796    |   0.722 us    |            native_load_tls();

------------------------------------------
| 0) cat-2796 => events/-9
------------------------------------------

Quoted 4 lines

 0)   events/-9    |               |    finish_task_switch() {
 0)   events/-9    |   0.789 us    |      _spin_unlock_irq();
 0)   events/-9    |   2.309 us    |    }
 0)   events/-9    | ! 269848.5 us |  }

which is what we want to express.

btw., i tested the graph tracer on a 16-way 64-bit box as well, and the multi-digit CPU field printout magic works fine there too:

 9)               |    pick_next_task() {
 9)   0.283 us    |      pick_next_task_fair();
 9)   0.276 us    |      pick_next_task_rt();
 9)   0.273 us    |      pick_next_task_fair();
 9)   0.279 us    |      pick_next_task_idle();
 9)   2.596 us    |    }
 9)   0.566 us    |    __lock_text_start();
 10)   0.299 us    |        }
 10)               |        mm_init() {
 10)               |          pgd_alloc() {
 10)               |            __get_free_pages() {
 10)               |              alloc_pages_current() {
 10)   0.330 us    |                policy_zonelist();
 10)               |                __alloc_pages_internal() {

Ingo

Quoted 4 lines

btw., i tested the graph tracer on a 16-way 64-bit box as well, and

the

Quoted 17 lines

multi-digit CPU field printout magic works fine there too:

 9)               |    pick_next_task() {
 9)   0.283 us    |      pick_next_task_fair();
 9)   0.276 us    |      pick_next_task_rt();
 9)   0.273 us    |      pick_next_task_fair();
 9)   0.279 us    |      pick_next_task_idle();
 9)   2.596 us    |    }
 9)   0.566 us    |    __lock_text_start();
 10)   0.299 us    |        }
 10)               |        mm_init() {
 10)               |          pgd_alloc() {
 10)               |            __get_free_pages() {
 10)               |              alloc_pages_current() {
 10)   0.330 us    |                policy_zonelist();
 10)               |                __alloc_pages_internal() {

Quoted 2 lines

Ingo

Hmm not really, there should be one space more before the 9 to fit the log10(MAX_CPU) here and not break
the column.

Quoted 22 lines

Quoted 4 lines

btw., i tested the graph tracer on a 16-way 64-bit box as well, and

the

Quoted 17 lines

multi-digit CPU field printout magic works fine there too:

 9)               |    pick_next_task() {
 9)   0.283 us    |      pick_next_task_fair();
 9)   0.276 us    |      pick_next_task_rt();
 9)   0.273 us    |      pick_next_task_fair();
 9)   0.279 us    |      pick_next_task_idle();
 9)   2.596 us    |    }
 9)   0.566 us    |    __lock_text_start();
 10)   0.299 us    |        }
 10)               |        mm_init() {
 10)               |          pgd_alloc() {
 10)               |            __get_free_pages() {
 10)               |              alloc_pages_current() {
 10)   0.330 us    |                policy_zonelist();
 10)               |                __alloc_pages_internal() {

Quoted 6 lines

Quoted 2 lines

Ingo

Hmm not really, there should be one space more before the 9 to fit the log10(MAX_CPU) here and not break
the column.

It did in my copy of Ingo's email...

2008/12/3 Peter Zijlstra <[email protected]>:

Quoted 26 lines · Frédéric Weisbecker

Quoted 25 lines

Quoted 4 lines

btw., i tested the graph tracer on a 16-way 64-bit box as well, and

the

Quoted 19 lines

multi-digit CPU field printout magic works fine there too:

 9)               |    pick_next_task() {
 9)   0.283 us    |      pick_next_task_fair();
 9)   0.276 us    |      pick_next_task_rt();
 9)   0.273 us    |      pick_next_task_fair();
 9)   0.279 us    |      pick_next_task_idle();
 9)   2.596 us    |    }
 9)   0.566 us    |    __lock_text_start();
 10)   0.299 us    |        }
 10)               |        mm_init() {
 10)               |          pgd_alloc() {
 10)               |            __get_free_pages() {
 10)               |              alloc_pages_current() {
 10)   0.330 us    |                policy_zonelist();
 10)               |                __alloc_pages_internal() {

Ingo

Quoted 5 lines

Quoted 3 lines

Hmm not really, there should be one space more before the 9 to fit the log10(MAX_CPU) here and not break
the column.

It did in my copy of Ingo's email...

So perhaps I should drop gmail...... :-(

I've been told that gmail has ways of extracting email through POP3. Perhaps that manages to preserve layout.. if not, I'll file a bug with google and get a real mail account pronto :-)

Quoted 18 lines

An example of a trace after these two patches (with funcgraph-proc enabled):

 0)    cat-2796    |               |            put_prev_task_fair() {
 0)    cat-2796    |   0.609 us    |              update_curr();
 0)    cat-2796    |   1.842 us    |            }
 0)    cat-2796    |               |            pick_next_task_fair() {
 0)    cat-2796    |   0.526 us    |              wakeup_preempt_entity();
 0)    cat-2796    |   0.797 us    |              set_next_entity();
 0)    cat-2796    |   0.541 us    |              hrtick_start_fair();
 0)    cat-2796    |   4.195 us    |            }
 0)    cat-2796    |   1.263 us    |            _spin_trylock();
 0)    cat-2796    |   0.624 us    |            _spin_unlock();
 0)    cat-2796    |   0.789 us    |            _spin_trylock();
 0)    cat-2796    |   0.617 us    |            _spin_unlock();
 0)    cat-2796    |   0.579 us    |            native_load_sp0();
 0)    cat-2796    |   0.722 us    |            native_load_tls();

Quoted 3 lines

------------------------------------------
| 0) cat-2796 => events/-9
------------------------------------------

small detail: i'd suggest to remove the newline before the context-switch box. That makes it appear visually to attach logically with the switch-out place, not the switch-in place:

Quoted 11 lines

 0)    cat-2796    |   0.579 us    |            native_load_sp0();
 0)    cat-2796    |   0.722 us    |            native_load_tls();

------------------------------------------
| 0) cat-2796 => events/-9
------------------------------------------

 0)   events/-9    |               |    finish_task_switch() {
 0)   events/-9    |   0.789 us    |      _spin_unlock_irq();
 0)   events/-9    |   2.309 us    |    }
 0)   events/-9    | ! 269848.5 us |  }

which is what we want to express.

Ingo

Actually, I was also thinking of keeping the CPU number in front:

------------------------------------------
0) cat-2796 => events/-9
------------------------------------------

This way we can easily grep for a common CPU and still get the context switches:

grep '^0)' trace > /tmp/trace0

Of course it will probably also work without the '^' now, but then it might grab ftrace_printks with a '0)' if we add those.

2008/12/3 Steven Rostedt <[email protected]>:

Quoted 6 lines

Actually, I was also thinking of keeping the CPU number in front:

------------------------------------------
0) cat-2796 => events/-9
------------------------------------------

Quoted 4 lines

This way we can easily grep for a common CPU and still get the context switches:

grep '^0)' trace > /tmp/trace0

I agree. More easy to grep. Ingo, Peter, others, what do you think?

Quoted 2 lines

Of course it will probably also work without the '^' now, but then it might grab ftrace_printks with a '0)' if we add those.

I proposed a solution for ftrace_printk (which I planned to implement this evening).
Since we are in a C-style output, that would be good to put the ftrace_printk as /* C comments */ inside just below the function that called it. Like this:

func_that_called_ftrace_printk {
    /* Message from ftrace_printk */
}

This way we keep the idea of comment which comes along the role of ftrace_printk and we know
which function called it, at which depth.....

Do you like it this way?

I proposed a solution for ftrace_printk (which I planned to implement this evening).
Since we are in a C-style output, that would be good to put the ftrace_printk as /* C comments */ inside just below the function that called it. Like this:

func_that_called_ftrace_printk {
    /* Message from ftrace_printk */
}

This way we keep the idea of comment which comes along the role of ftrace_printk and we know
which function called it, at which depth.....

Do you like it this way?

Quoted 12 lines

I proposed a solution for ftrace_printk (which I planned to implement this evening).
Since we are in a C-style output, that would be good to put the ftrace_printk as /* C comments */ inside just below the function that called it. Like this:

func_that_called_ftrace_printk {
    /* Message from ftrace_printk */
}

Quoted 5 lines

This way we keep the idea of comment which comes along the role of ftrace_printk and we know
which function called it, at which depth.....

Do you like it this way?

Yes definitely. I thought we already decided to do it that way ;-)

A proposition about this. I want to use __ftrace_printk, make it generic for both function tracers and have a way to store the current depth.
One solution: changing the print_entry to have the ip available for function-tracer and depth available for return-function_tracer.

struct print_entry {
	struct trace_entry	ent;
        union {
	    unsigned long	ip;
            unsigned long       depth;
        } from;
	char			buf[];
};

We could make __ftrace_printk verify which tracer is running.

If normal tracer then

     trace_vprintk(__builtin_return_address(0), .....)
else if graph-tracer
     trace_vprintk(current->curr_ret_stack, ......)

This way we can even forget the ip argument of __trace_printk. I prefer to ask before changing an exported symbol API....

2008/12/3 Steven Rostedt <[email protected]>:

Quoted 6 lines

Actually, I was also thinking of keeping the CPU number in front:

------------------------------------------
0) cat-2796 => events/-9
------------------------------------------

Quoted 4 lines

This way we can easily grep for a common CPU and still get the context switches:

grep '^0)' trace > /tmp/trace0

I agree. More easy to grep. Ingo, Peter, others, what do you think?

Quoted 2 lines

Of course it will probably also work without the '^' now, but then it might grab ftrace_printks with a '0)' if we add those.

I proposed a solution for ftrace_printk (which I planned to implement this evening). Since we are in a C-style output, that would be good to put the ftrace_printk as /* C comments */ inside just below the function that called it. Like this:

func_that_called_ftrace_printk {
    /* Message from ftrace_printk */
}

This way we keep the idea of comment which comes along the role of ftrace_printk and we know
which function called it, at which depth.....

Do you like it this way?