[PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frederic Weisbecker]

Impact: Optimize a bit the function return tracer

This patch changes the calling convention of prepare_ftrace_return
to pass its arguments by register. This will optimize it a bit and
prepare it to support dynamic tracing.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 arch/x86/kernel/entry_32.S |    5 +----
 arch/x86/kernel/ftrace.c   |    1 -
 2 files changed, 1 insertions(+), 5 deletions(-)

diff --git a/arch/x86/kernel/entry_32.S b/arch/x86/kernel/entry_32.S
index 9a0ac85..f976211 100644
--- a/arch/x86/kernel/entry_32.S
+++ b/arch/x86/kernel/entry_32.S
@@ -1217,12 +1217,9 @@ trace_return:
 	pushl %eax
 	pushl %ecx
 	pushl %edx
-	movl 0xc(%esp), %eax
-	pushl %eax
+	movl 0xc(%esp), %edx
 	lea 0x4(%ebp), %eax
-	pushl %eax
 	call prepare_ftrace_return
-	addl $8, %esp
 	popl %edx
 	popl %ecx
 	popl %eax
diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 1db0e12..fe83273 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -95,7 +95,6 @@ unsigned long ftrace_return_to_handler(void)
  * Hook the return address and push it in the stack of return addrs
  * in current thread info.
  */
-asmlinkage
 void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 {
 	unsigned long old;
-- 
1.5.2.5

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Ingo Molnar]

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

> Impact: Optimize a bit the function return tracer
> 
> This patch changes the calling convention of prepare_ftrace_return
> to pass its arguments by register. This will optimize it a bit and
> prepare it to support dynamic tracing.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> ---
>  arch/x86/kernel/entry_32.S |    5 +----
>  arch/x86/kernel/ftrace.c   |    1 -
>  2 files changed, 1 insertions(+), 5 deletions(-)

applied	to tip/tracing/function-return-tracer, thanks Frederic!

btw., should we now rename it all to the function-cost tracer?

	Ingo

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frédéric Weisbecker]

2008/11/12 Ingo Molnar <mingo@elte.hu>:
>
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
>> Impact: Optimize a bit the function return tracer
>>
>> This patch changes the calling convention of prepare_ftrace_return
>> to pass its arguments by register. This will optimize it a bit and
>> prepare it to support dynamic tracing.
>>
>> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
>> Cc: Steven Rostedt <rostedt@goodmis.org>
>> ---
>>  arch/x86/kernel/entry_32.S |    5 +----
>>  arch/x86/kernel/ftrace.c   |    1 -
>>  2 files changed, 1 insertions(+), 5 deletions(-)
>
> applied to tip/tracing/function-return-tracer, thanks Frederic!
>
> btw., should we now rename it all to the function-cost tracer?
>
>        Ingo
>


Yes. I'm preparing a patch to do these renames....

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Steven Rostedt]

On Wed, 12 Nov 2008, Fr?d?ric Weisbecker wrote:

> 2008/11/12 Ingo Molnar <mingo@elte.hu>:
> >
> > btw., should we now rename it all to the function-cost tracer?
> 
> Yes. I'm preparing a patch to do these renames....

I still need to look deeper at your patch set, but what about 
"ftrace-exit"?  Perhaps in the future this could be used by other tracers 
to record exiting of a function.

-- Steve

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frédéric Weisbecker]

2008/11/13 Steven Rostedt <rostedt@goodmis.org>:
>
> On Wed, 12 Nov 2008, Fr?d?ric Weisbecker wrote:
>
>> 2008/11/12 Ingo Molnar <mingo@elte.hu>:
>> >
>> > btw., should we now rename it all to the function-cost tracer?
>>
>> Yes. I'm preparing a patch to do these renames....
>
> I still need to look deeper at your patch set, but what about
> "ftrace-exit"?  Perhaps in the future this could be used by other tracers
> to record exiting of a function.


Hmm... The whole thing is splitted in two levels: the infrastructure
to trace on call and return (and call
a return handler) and the higher level tracer.
The first could be called ftrace_exit because it is waht it does.
And the second is much more about cost evaluation of functions and so
could be named function_cost. Its
functions and structures could have this in their name whereas the low
level things could have ftrace_exit in
their name.

What do you think?

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Steven Rostedt]

> 
> Hmm... The whole thing is splitted in two levels: the infrastructure
> to trace on call and return (and call
> a return handler) and the higher level tracer.
> The first could be called ftrace_exit because it is waht it does.
> And the second is much more about cost evaluation of functions and so
> could be named function_cost. Its
> functions and structures could have this in their name whereas the low
> level things could have ftrace_exit in
> their name.
> 
> What do you think?

Yeah, I like that.

Ingo, what's your thought on that?

-- Steve

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> > 
> > Hmm... The whole thing is splitted in two levels: the infrastructure
> > to trace on call and return (and call
> > a return handler) and the higher level tracer.
> > The first could be called ftrace_exit because it is waht it does.
> > And the second is much more about cost evaluation of functions and so
> > could be named function_cost. Its
> > functions and structures could have this in their name whereas the low
> > level things could have ftrace_exit in
> > their name.
> > 
> > What do you think?
> 
> Yeah, I like that.
> 
> Ingo, what's your thought on that?

hm, function-exit is a quite bad name i think that tells nothing to 
the user. I like "function-cost tracer" because that tells the user 
what it's all about in the end.

Or perhaps we could name it the "callgraph" tracer? (as opposed to the 
simpler function tracer which traces function entries) Note that we 
could use the output to build function call coverage graphs.

It definitely must convey the idea that this is a more capable (and 
also more expensive) form of function tracing.

	Ingo

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Ingo Molnar]

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

> Or perhaps we could name it the "callgraph" tracer? (as opposed to 
> the simpler function tracer which traces function entries) Note that 
> we could use the output to build function call coverage graphs.
> 
> It definitely must convey the idea that this is a more capable (and 
> also more expensive) form of function tracing.

on a related note.

Frederic, it would be nice to fine-tune the tracer output to convey 
the callgraph information more clearly. Here's a mockup of a good 
default output:

  getnstimeofday() {
   set_normalized_timespec() {
    clocksource_read() {
     acpi_pm_read()                     ( 1547 ns)
    } clocksource_read()                ( 1951 ns)
   } set_normalized_timespec()          ( 2200 ns)
  } getnstimeofday()                    ( 2354 ns)

  [...]

Such output would be _very_ nice and intuitive to have. Developers 
would love it instantly. Note its C-ish syntax - that is obviously the 
easiest to parse for kernel developers.

and note how natural it will be in the future to embellish certain 
function calls in the above trace, for example with function 
arguments:

    clocksource_read("acpi_pm") {

i'd suggest to hide the offset bit of the ksym (like the mockup does 
it - unless a tracing_option is set for more verbose symbol output). 
For these traces it's almost always useless and the context tells us 
in 99% of the cases where a function got called.

Easiest would be to add a depth field to the trace entry as well, to 
make sure we get the right depth in the end, even if we somehow mix up 
the trace entries.

We could also trace function entry and exit separately, and 
post-process the call stack (and the cost) during trace output 
formatting - not during tracing.

Hm?

	Ingo

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frédéric Weisbecker]

2008/11/13 Ingo Molnar <mingo@elte.hu>:
> on a related note.
>
> Frederic, it would be nice to fine-tune the tracer output to convey
> the callgraph information more clearly. Here's a mockup of a good
> default output:
>
>  getnstimeofday() {
>   set_normalized_timespec() {
>    clocksource_read() {
>     acpi_pm_read()                     ( 1547 ns)
>    } clocksource_read()                ( 1951 ns)
>   } set_normalized_timespec()          ( 2200 ns)
>  } getnstimeofday()                    ( 2354 ns)
>
>  [...]


Oh yes. That would be fine. I thought such thing would be better to do
in post-processing.
But I wonder a bit about this, I explain why below.

> Such output would be _very_ nice and intuitive to have. Developers
> would love it instantly. Note its C-ish syntax - that is obviously the
> easiest to parse for kernel developers.


That's right, it's much more better for the eyes. I didn't want to
output such a disposition from the kernel
because I thought that would result in too much strings work from
kernel-space. But actually, as you suggest,
 if I append a depth field in the trace that could be easy and not so
costly. I just have a last thought about
post-processing parsing. Would it make it harder for that?
Why not a flag that could be set through iter_ctrl (which has changed
its name yesterday) and that could let
the user to choose its output? That's where I renew my proposition to
make the tracers able to propose custom
flags for this file with a new callback such as tracer_ctrl, or tracer_opt.

After all perhaps an indented output would be better to build a tree
of calls from parsing. And the current
output would be better to build stats about return values and/or cost.

> and note how natural it will be in the future to embellish certain
> function calls in the above trace, for example with function
> arguments:
>
>    clocksource_read("acpi_pm") {
>
> i'd suggest to hide the offset bit of the ksym (like the mockup does
> it - unless a tracing_option is set for more verbose symbol output).
> For these traces it's almost always useless and the context tells us
> in 99% of the cases where a function got called.

I think it remains useful when a function calls one other in
differents code paths.
But as you say, why not set it through a flag.

> Easiest would be to add a depth field to the trace entry as well, to
> make sure we get the right depth in the end, even if we somehow mix up
> the trace entries.


Yeah, that's good! I will just have to output "\t" * depth to have the
correct indentation.

> We could also trace function entry and exit separately, and
> post-process the call stack (and the cost) during trace output
> formatting - not during tracing.
>
> Hm?


Yes I thought about that. But with a bit post-processing, we could
retrieve the result of the normal function tracing through
the "return tracing" traces... I guess...

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Ingo Molnar]

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

> That's right, it's much more better for the eyes. I didn't want to 
> output such a disposition from the kernel because I thought that 
> would result in too much strings work from kernel-space. But 
> actually, as you suggest,
>  if I append a depth field in the trace that could be easy and not 
> so costly. I just have a last thought about post-processing parsing. 
> Would it make it harder for that?

humans are the priority targets for tracer output - tools are a 
distant second target. Whatever is nice for humans is also usually 
easy to process via tools. A tool can set an option flag just fine.

To help tooling, add a trace_options flag for more predictable/faster 
output. We already have the binary output format for example.

> Why not a flag that could be set through iter_ctrl (which has 
> changed its name yesterday) and that could let the user to choose 
> its output? That's where I renew my proposition to make the tracers 
> able to propose custom flags for this file with a new callback such 
> as tracer_ctrl, or tracer_opt.

yes, your proposal is fine.

> But as you say, why not set it through a flag.

yes - and make the defaults for flags favor human visual parsing.

> > Easiest would be to add a depth field to the trace entry as well, to
> > make sure we get the right depth in the end, even if we somehow mix up
> > the trace entries.
> 
> Yeah, that's good! I will just have to output "\t" * depth to have 
> the correct indentation.

i'd suggest spaces for the function indentation, because we'll also 
have quite deep call stacks in practice.

and i'd suggest you flip around the cost field to something like:

 [...]
               getnstimeofday() {
                set_normalized_timespec() {
                 clocksource_read() { 
 ( 1547 ns)       acpi_pm_read()                     
 ( 1951 ns)      } clocksource_read()
 ( 2200 ns)     } set_normalized_timespec()
 ( 2354 ns)    } getnstimeofday()

that makes it fixed-width up to the inevitable variable-length field, 
the function name.

	Ingo

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frédéric Weisbecker]

2008/11/13 Ingo Molnar <mingo@elte.hu>:
>
> * Frédéric Weisbecker <fweisbec@gmail.com> wrote:
>
>> That's right, it's much more better for the eyes. I didn't want to
>> output such a disposition from the kernel because I thought that
>> would result in too much strings work from kernel-space. But
>> actually, as you suggest,
>>  if I append a depth field in the trace that could be easy and not
>> so costly. I just have a last thought about post-processing parsing.
>> Would it make it harder for that?
>
> humans are the priority targets for tracer output - tools are a
> distant second target. Whatever is nice for humans is also usually
> easy to process via tools. A tool can set an option flag just fine.
>
> To help tooling, add a trace_options flag for more predictable/faster
> output. We already have the binary output format for example.
>
>> Why not a flag that could be set through iter_ctrl (which has
>> changed its name yesterday) and that could let the user to choose
>> its output? That's where I renew my proposition to make the tracers
>> able to propose custom flags for this file with a new callback such
>> as tracer_ctrl, or tracer_opt.
>
> yes, your proposal is fine.
>
>> But as you say, why not set it through a flag.
>
> yes - and make the defaults for flags favor human visual parsing.
>
>> > Easiest would be to add a depth field to the trace entry as well, to
>> > make sure we get the right depth in the end, even if we somehow mix up
>> > the trace entries.
>>
>> Yeah, that's good! I will just have to output "\t" * depth to have
>> the correct indentation.
>
> i'd suggest spaces for the function indentation, because we'll also
> have quite deep call stacks in practice.
>
> and i'd suggest you flip around the cost field to something like:
>
>  [...]
>               getnstimeofday() {
>                set_normalized_timespec() {
>                 clocksource_read() {
>  ( 1547 ns)       acpi_pm_read()
>  ( 1951 ns)      } clocksource_read()
>  ( 2200 ns)     } set_normalized_timespec()
>  ( 2354 ns)    } getnstimeofday()
>
> that makes it fixed-width up to the inevitable variable-length field,
> the function name.
>
>        Ingo
>

Ok, I will add all of these in my workqueue. Thanks :)

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frédéric Weisbecker]

2008/11/13 Ingo Molnar <mingo@elte.hu>:
> hm, function-exit is a quite bad name i think that tells nothing to
> the user. I like "function-cost tracer" because that tells the user
> what it's all about in the end.
>
> Or perhaps we could name it the "callgraph" tracer? (as opposed to the
> simpler function tracer which traces function entries) Note that we
> could use the output to build function call coverage graphs.


But you can build a call graph with the function tracer, that what
does the script draw_trace.py
in a bit loosely way for example.
IMHO, function cost measurement or call graphs are particular uses
that can be made of this engine.
You can also use it to trace function return values for example.

The general sense of this is more about return hooking.
But....
Perhaps defining it as a "return" tracer is not easy to understand at
a first sight and could bring developpers
on misinterpretation (sorry does this word exist?).

So perhaps naming it by thinking on the purpose it could be use at
most would be better that its "general" or "potential"
purpose. I don't know...

> It definitely must convey the idea that this is a more capable (and
> also more expensive) form of function tracing.
>
>        Ingo
>


If we convey/consider it on a sight where it is capable on several
things, so a more generic name should be chosen.

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frédéric Weisbecker]

2008/11/13 Frédéric Weisbecker <fweisbec@gmail.com>:
> So perhaps naming it by thinking on the purpose it could be use at
> most would be better that its "general" or "potential"
> purpose. I don't know...

Oops. s/that/than

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Ingo Molnar]

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

> 2008/11/13 Ingo Molnar <mingo@elte.hu>:
> > hm, function-exit is a quite bad name i think that tells nothing to
> > the user. I like "function-cost tracer" because that tells the user
> > what it's all about in the end.
> >
> > Or perhaps we could name it the "callgraph" tracer? (as opposed to the
> > simpler function tracer which traces function entries) Note that we
> > could use the output to build function call coverage graphs.
> 
> But you can build a call graph with the function tracer, that what 
> does the script draw_trace.py in a bit loosely way for example.

yes, but not reliably so - there's no guaranteed callgraph structure. 
With entry tracing we have entry+parent events, but especially across 
longer callchains there's no truly guaranteed way to preserve the full 
graph.

> IMHO, function cost measurement or call graphs are particular uses 
> that can be made of this engine. You can also use it to trace 
> function return values for example.

yes. The mockup output has place for that.

> So perhaps naming it by thinking on the purpose it could be use at 
> most would be better that its "general" or "potential" purpose. I 
> don't know...

i suggested "full-function" tracer name before, but that sounds a bit 
quirky too.

Perhaps this should be the function-tracer, and the entry tracer would 
be the function-entry tracer?

	Ingo

Re: [PATCH 2/2] tracing/function-return-tracer: Call prepare_ftrace_return by registers

[Frederic Weisbecker]

Ingo Molnar a écrit :
> * Frédéric Weisbecker <fweisbec@gmail.com> wrote:
> 
>> 2008/11/13 Ingo Molnar <mingo@elte.hu>:
>>> hm, function-exit is a quite bad name i think that tells nothing to
>>> the user. I like "function-cost tracer" because that tells the user
>>> what it's all about in the end.
>>>
>>> Or perhaps we could name it the "callgraph" tracer? (as opposed to the
>>> simpler function tracer which traces function entries) Note that we
>>> could use the output to build function call coverage graphs.
>> But you can build a call graph with the function tracer, that what 
>> does the script draw_trace.py in a bit loosely way for example.
> 
> yes, but not reliably so - there's no guaranteed callgraph structure. 
> With entry tracing we have entry+parent events, but especially across 
> longer callchains there's no truly guaranteed way to preserve the full 
> graph.


That's right, with the depth, we could have a more safe result for the call graph.

>> IMHO, function cost measurement or call graphs are particular uses 
>> that can be made of this engine. You can also use it to trace 
>> function return values for example.
> 
> yes. The mockup output has place for that.


The problem with this is that we don't know in advance if the return value fits in 32
or 64 bits...

>> So perhaps naming it by thinking on the purpose it could be use at 
>> most would be better that its "general" or "potential" purpose. I 
>> don't know...
> 
> i suggested "full-function" tracer name before, but that sounds a bit 
> quirky too.
> 
> Perhaps this should be the function-tracer, and the entry tracer would 
> be the function-entry tracer?
> 
> 	Ingo

I still wonder about the name we should choose...
Renaming function to function_entry seems to me a bit wrong because usual function
tracing happens in entry...

Why not two-pass function tracer?