[PATCH 2/2] tracing/function-graph-tracer: improve duration output

[PATCH 2/2] tracing/function-graph-tracer: improve duration output

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

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

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 23e19d2..c66578f 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -232,11 +232,50 @@ trace_branch_is_leaf(struct trace_iterator *iter,
 }
 
 
-static inline int
+static enum print_line_t
 print_graph_duration(unsigned long long duration, struct trace_seq *s)
 {
 	unsigned long nsecs_rem = do_div(duration, 1000);
-	return trace_seq_printf(s, "%4llu.%3lu us |  ", duration, nsecs_rem);
+	/* log10(ULONG_MAX) + '\0' */
+	char msecs_str[21];
+	char nsecs_str[5];
+	int ret, len;
+	int i;
+
+	sprintf(msecs_str, "%lu", (unsigned long) duration);
+
+	/* Print msecs */
+	ret = trace_seq_printf(s, msecs_str);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	len = strlen(msecs_str);
+
+	/* Print nsecs (we don't want to exceed 7 numbers) */
+	if (len < 7) {
+		snprintf(nsecs_str, 8 - len, "%03lu", nsecs_rem);
+		ret = trace_seq_printf(s, ".%s", nsecs_str);
+		if (!ret)
+			return TRACE_TYPE_PARTIAL_LINE;
+		len += strlen(nsecs_str);
+	}
+
+	ret = trace_seq_printf(s, " us ");
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	/* Print remaining spaces to fit the row's width */
+	for (i = len; i < 7; i++) {
+		ret = trace_seq_printf(s, " ");
+		if (!ret)
+			return TRACE_TYPE_PARTIAL_LINE;
+	}
+
+	ret = trace_seq_printf(s, "|  ");
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+	return TRACE_TYPE_HANDLED;
+
 }
 
 /* Signal a overhead of time execution to the output */
@@ -273,10 +312,6 @@ print_graph_entry_leaf(struct trace_iterator *iter,
 	call = &entry->graph_ent;
 	duration = graph_ret->rettime - graph_ret->calltime;
 
-	/* Must not exceed 8 characters: 9999.999 us */
-	if (duration > 10000000ULL)
-		duration = 9999999ULL;
-
 	/* Overhead */
 	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
 		ret = print_graph_overhead(duration, s);
@@ -286,7 +321,7 @@ print_graph_entry_leaf(struct trace_iterator *iter,
 
 	/* Duration */
 	ret = print_graph_duration(duration, s);
-	if (!ret)
+	if (ret == TRACE_TYPE_PARTIAL_LINE)
 		return TRACE_TYPE_PARTIAL_LINE;
 
 	/* Function */
@@ -387,10 +422,6 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 	int ret;
 	unsigned long long duration = trace->rettime - trace->calltime;
 
-	/* Must not exceed 8 characters: xxxx.yyy us */
-	if (duration > 10000000ULL)
-		duration = 9999999ULL;
-
 	/* Pid */
 	if (verif_pid(s, ent->pid, cpu) == TRACE_TYPE_PARTIAL_LINE)
 		return TRACE_TYPE_PARTIAL_LINE;
@@ -422,7 +453,7 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 
 	/* Duration */
 	ret = print_graph_duration(duration, s);
-	if (!ret)
+	if (ret == TRACE_TYPE_PARTIAL_LINE)
 		return TRACE_TYPE_PARTIAL_LINE;
 
 	/* Closing brace */
-- 
1.5.6.3

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Frederic Weisbecker]

Frederic Weisbecker wrote:
> 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.....


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)   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 |  }
 0)   events/-9    |   0.601 us    |  finish_wait();
 0)   events/-9    |   0.662 us    |  kthread_should_stop();
 0)   events/-9    |               |  run_workqueue() {
 0)   events/-9    |   1.136 us    |    _spin_lock_irq();
 0)   events/-9    |   0.918 us    |    _spin_unlock_irq();
 0)   events/-9    |               |    console_callback() {
 0)   events/-9    |               |      acquire_console_sem() {
 0)   events/-9    |               |        down() {
 0)   events/-9    |   1.534 us    |          _spin_lock_irqsave();
 0)   events/-9    |   0.812 us    |          _spin_unlock_irqrestore();
 0)   events/-9    |   4.369 us    |        }
 0)   events/-9    |   5.903 us    |      }

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Frederic Weisbecker wrote:
> > 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.....

applied, thanks!

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

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:

>  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

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Ingo Molnar]

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

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Frédéric Weisbecker]

2008/12/3 Ingo Molnar <mingo@elte.hu>:
> 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:
>
>>  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.
>


Ok, I'll fix it.


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

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

Thanks!

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Peter Zijlstra]

On Wed, 2008-12-03 at 11:07 +0100, Frédéric Weisbecker wrote:
> 
> 
> >
> > 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
> >
> 
> 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...

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Frédéric Weisbecker]

2008/12/3 Peter Zijlstra <a.p.zijlstra@chello.nl>:
> On Wed, 2008-12-03 at 11:07 +0100, Frédéric Weisbecker wrote:
>>
>>
>> >
>> > 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
>> >
>>
>> 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...... :-(

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Peter Zijlstra]

On Wed, 2008-12-03 at 11:23 +0100, Frédéric Weisbecker wrote:
> 2008/12/3 Peter Zijlstra <a.p.zijlstra@chello.nl>:
> > On Wed, 2008-12-03 at 11:07 +0100, Frédéric Weisbecker wrote:
> >>
> >>
> >> >
> >> > 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
> >> >
> >>
> >> 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 :-)

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Frédéric Weisbecker]

2008/12/3 Peter Zijlstra <a.p.zijlstra@chello.nl>:
> 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 :-)


Yes of course, when I am at home I can use pop3 and imap to extract them.
But when I'm at work, I only have access to the Web....

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Steven Rostedt]

On Wed, 3 Dec 2008, Ingo Molnar wrote:
> 
> > 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   
> >  ------------------------------------------
> 
> 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:

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.

-- Steve

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

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Frédéric Weisbecker]

2008/12/3 Steven Rostedt <rostedt@goodmis.org>:
> 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

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

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

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Peter Zijlstra]

On Wed, 2008-12-03 at 14:11 +0100, Frédéric Weisbecker wrote:
> 2008/12/3 Steven Rostedt <rostedt@goodmis.org>:
> > 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
> 
> I agree. More easy to grep. Ingo, Peter, others, what do you think?

Everything that aids parsing is good :-)

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

Yep

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Steven Rostedt]

On Wed, 3 Dec 2008, Fr?d?ric Weisbecker wrote:
> 
> 
> 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?

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

-- Steve

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> 2008/12/3 Steven Rostedt <rostedt@goodmis.org>:
> > 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
> 
> I agree. More easy to grep. Ingo, Peter, others, what do you think?

sure.

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

yeah, that would be lovely to have too.

	Ingo

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Frédéric Weisbecker]

2008/12/3 Steven Rostedt <rostedt@goodmis.org>:
>
> On Wed, 3 Dec 2008, Fr?d?ric Weisbecker wrote:
>>
>>
>> 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?
>
> 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....

Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

[Steven Rostedt]

On Wed, 3 Dec 2008, Fr?d?ric Weisbecker wrote:
> 
> 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....

Actually, I would prefer to keep both.

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

And pass in both. Have the readers of the functions figure out what to do 
with either, and keep the messiness away from the API.

-- Steve