Hi,
I'm planning to apply an idea proposed by Ingo to make the output on
the function return tracer
more "eyes-parsable".
The idea consists on a trace which has flow similar to C code:
func1() {
func2() {
func3() {
}
}
func4() {
}
}
(With time of execution added on closing braces).
The problem is that the traces arrive in the reverse order, according
to the fact that functions
are traced on return.
The order corresponding to the above example would be as the following:
func3, func2, func4, func1
Oh and we have the parent in a return trace, so we would actually have:
func2->func3
func1->func4
.... ->func1
This trace flow doesn't make the things easy to produce our C like code.
So I found only one solution which have both pros and cons.
I could send a "pre-trace" to the ring-buffer to signal that function
x with depth y is beeing called
(when we enter the function).
The pros:
_ It will be easy to draw our C 'like trace, without any special
pre-output work.
_ The name could be definetly full-function-tracer with this new pre-trace :-)
_ Automatic trace parsing, tree of calls building will be more easy....
The cons:
_ The function-return-tracer slows down the system.
It will be worst with a new insertion in the ring-buffer. But if it is mostly
used with dynamic ftrace and a good set of filtered functions, I
don't think that will be
an issue.
If you think about an other solution, don't hesitate to tell me :-)
Thanks....
* Fr?d?ric Weisbecker <[email protected]> wrote:
> Hi,
>
> I'm planning to apply an idea proposed by Ingo to make the output on
> the function return tracer
> more "eyes-parsable".
> The idea consists on a trace which has flow similar to C code:
>
> func1() {
> func2() {
> func3() {
> }
> }
> func4() {
> }
> }
>
> (With time of execution added on closing braces).
>
> The problem is that the traces arrive in the reverse order, according
> to the fact that functions
> are traced on return.
> The order corresponding to the above example would be as the following:
>
> func3, func2, func4, func1
>
> Oh and we have the parent in a return trace, so we would actually have:
>
> func2->func3
[ Note: here we'd also have: ]
func1->func2
> func1->func4
> .... ->func1
it's basicaly a representation of the callgraph in polish notation.
> This trace flow doesn't make the things easy to produce our C like
> code.
>
> So I found only one solution which have both pros and cons. I could
> send a "pre-trace" to the ring-buffer to signal that function x with
> depth y is beeing called (when we enter the function).
that's OK i think. It will double the number of events, but will
simplify everything immensely - especially if we have small
imperfections in the callgraph arising out of IRQ entries.
Note that we _could_ render it all from the return events alone,
because we have the full callgraph available. But it would be either
very memory-intense or very CPU-intense: we'd either have to buffer up
all the return events in a reverse-stack sort of construct (which
could grow much larger than the return stack itself), or we'd have to
reconstruct it on the fly by constantly scanning forwards to discover
the context of the printout. Both can have pretty ugly worst-case
behavior with certain call graph layouts.
So i think you made a good call - lets keep it simple for now.
Also, do you have any thoughts about how to extend the return-tracer
to 64-bit x86? It should work pretty well i think - the return value
has to be extended to 64 bits but that's pretty much all.
Ingo
2008/11/24 Ingo Molnar <[email protected]>:
> that's OK i think. It will double the number of events, but will
> simplify everything immensely - especially if we have small
> imperfections in the callgraph arising out of IRQ entries.
Great!
> Note that we _could_ render it all from the return events alone,
> because we have the full callgraph available. But it would be either
> very memory-intense or very CPU-intense: we'd either have to buffer up
> all the return events in a reverse-stack sort of construct (which
> could grow much larger than the return stack itself), or we'd have to
> reconstruct it on the fly by constantly scanning forwards to discover
> the context of the printout. Both can have pretty ugly worst-case
> behavior with certain call graph layouts.
Yes, too much complex, too much error prone.... And such a thing
would have been better done from user space...
> So i think you made a good call - lets keep it simple for now.
>
> Also, do you have any thoughts about how to extend the return-tracer
> to 64-bit x86? It should work pretty well i think - the return value
> has to be extended to 64 bits but that's pretty much all.
Yes, I'm currently burning a 64 bits distro :-)
Very few things should be added or modified to work on 64. The most adds
will be in entry64.S and perhaps very few things in ftrace.c ...
That should come soon.
Note that I plan to adapt it for other archs too such as ARM and Sparc64, but
perhaps more likely for 2.6.30, I will see.....
Thanks :-)
On Mon, 24 Nov 2008, Fr?d?ric Weisbecker wrote:
> Hi,
>
> I'm planning to apply an idea proposed by Ingo to make the output on
> the function return tracer
> more "eyes-parsable".
> The idea consists on a trace which has flow similar to C code:
>
> func1() {
> func2() {
> func3() {
> }
> }
> func4() {
> }
> }
A little off topic, but how do you handle collapsed returns?
func1() {
[...]
func2();
return;
}
Instead of using call *func2, gcc may decide to collapse it. That is,
since it is the last thing done on func1, it may pop func1's frame all the
way to func1's return address, and then do a "jmp" to func2. func2 will
still call mcount, but on its return, it will jump to the func1 return
address.
Perhaps this is OK. The call to func1's mcount will store the original
return address and replace it with the function return code. The call to
func2 will store that return address and replace it with the func2
function return code. And both of them will still be processed.
OK, I think I answered my own question, but I'm keeping it in this post
just to make sure I understand it correctly.
>
> (With time of execution added on closing braces).
>
> The problem is that the traces arrive in the reverse order, according
> to the fact that functions
> are traced on return.
> The order corresponding to the above example would be as the following:
>
> func3, func2, func4, func1
>
> Oh and we have the parent in a return trace, so we would actually have:
>
> func2->func3
> func1->func4
> .... ->func1
>
> This trace flow doesn't make the things easy to produce our C like code.
>
> So I found only one solution which have both pros and cons.
> I could send a "pre-trace" to the ring-buffer to signal that function
> x with depth y is beeing called
> (when we enter the function).
>
> The pros:
>
> _ It will be easy to draw our C 'like trace, without any special
> pre-output work.
> _ The name could be definetly full-function-tracer with this new pre-trace :-)
> _ Automatic trace parsing, tree of calls building will be more easy....
>
> The cons:
>
> _ The function-return-tracer slows down the system.
> It will be worst with a new insertion in the ring-buffer. But if it is mostly
> used with dynamic ftrace and a good set of filtered functions, I
> don't think that will be
> an issue.
>
> If you think about an other solution, don't hesitate to tell me :-)
> Thanks....
Do you have a record that you store when you make the first mcount call.
In this record, could you save the depth of the parent there too. I do not
remember the code exactly, so I might be off here ;-)
-- Steve
2008/11/24 Steven Rostedt <[email protected]>:
> A little off topic, but how do you handle collapsed returns?
>
> func1() {
> [...]
> func2();
> return;
> }
>
> Instead of using call *func2, gcc may decide to collapse it. That is,
> since it is the last thing done on func1, it may pop func1's frame all the
> way to func1's return address, and then do a "jmp" to func2. func2 will
> still call mcount, but on its return, it will jump to the func1 return
> address.
>
> Perhaps this is OK. The call to func1's mcount will store the original
> return address and replace it with the function return code. The call to
> func2 will store that return address and replace it with the func2
> function return code. And both of them will still be processed.
>
> OK, I think I answered my own question, but I'm keeping it in this post
> just to make sure I understand it correctly.
Yes, perhaps it is done that way. Or perhaps CONFIG_FRAME_POINTER avoids
such collapsing calls... I don't know.
Perhaps I should look at some disassembly dumps to ensure things are safe, but
I didn't have any problem with that...
> Do you have a record that you store when you make the first mcount call.
> In this record, could you save the depth of the parent there too. I do not
> remember the code exactly, so I might be off here ;-)
No. At this time I don't do any insertion at the call time :-)
But I don't think I will need the parent depth. The current depth will
be sufficient for the trace printing.
Em Mon, Nov 24, 2008 at 03:39:45PM +0100, Fr?d?ric Weisbecker escreveu:
> Hi,
>
> I'm planning to apply an idea proposed by Ingo to make the output on
> the function return tracer
> more "eyes-parsable".
> The idea consists on a trace which has flow similar to C code:
>
> func1() {
> func2() {
> func3() {
> }
> }
> func4() {
> }
> }
>
> (With time of execution added on closing braces).
I do something like that in my ctracer tool[1], take a look at one of
the callgraphs:
http://oops.ghostprotocols.net:81/ostra/dccp/tx/
To save space I the above sequence is represented as:
func1() {
func2() {
func3() 1us
} 5us
func4() 5us
} 12us
I.e. the leaf functions doesn't use {}
> The problem is that the traces arrive in the reverse order, according
> to the fact that functions
> are traced on return.
> The order corresponding to the above example would be as the following:
>
> func3, func2, func4, func1
On ctracer I didn't had this problem as I don't trace all functions,
just the ones that receive as one of its parameters a pointer to the
desired struct, and this pointer is present in all the trace buffer
entries, so as part of postprocessing it separates the callgraphs per
object.
- Arnaldo
[1] git://git.kernel.org/pub/scm/linux/kernel/git/acme/pahole.git
http://git.kernel.org/?p=linux/kernel/git/acme/pahole.git;a=blob_plain;f=README.ctracer
2008/11/24 Arnaldo Carvalho de Melo <[email protected]>:
> I do something like that in my ctracer tool[1], take a look at one of
> the callgraphs:
>
> http://oops.ghostprotocols.net:81/ostra/dccp/tx/
Oh yes, that's what I would see as an end result. Except that it would be more
easy for me to have the time of execution on the left (I don't need the time
they are called since it's just a cost measure).
> I.e. the leaf functions doesn't use {}
I guess I could avoid it too..
> On ctracer I didn't had this problem as I don't trace all functions,
> just the ones that receive as one of its parameters a pointer to the
> desired struct, and this pointer is present in all the trace buffer
> entries,
How do you do this tracing by only passing a structure?
> so as part of postprocessing it separates the callgraphs per
> object.
I would like to separate the callgraph per thread. I'm not sure how. Perhaps
by only drawing a simple
------8<----- switch to task nr x -----------8<-------------------
Em Mon, Nov 24, 2008 at 08:10:47PM +0100, Fr?d?ric Weisbecker escreveu:
> 2008/11/24 Arnaldo Carvalho de Melo <[email protected]>:
> > I do something like that in my ctracer tool[1], take a look at one of
> > the callgraphs:
> >
> > http://oops.ghostprotocols.net:81/ostra/dccp/tx/
>
>
> Oh yes, that's what I would see as an end result. Except that it would be more
> easy for me to have the time of execution on the left (I don't need the time
> they are called since it's just a cost measure).
>
>
> > I.e. the leaf functions doesn't use {}
>
> I guess I could avoid it too..
>
>
> > On ctracer I didn't had this problem as I don't trace all functions,
> > just the ones that receive as one of its parameters a pointer to the
> > desired struct, and this pointer is present in all the trace buffer
> > entries,
>
> How do you do this tracing by only passing a structure?
[acme@doppio linux-2.6-x86]$ pfunct --verbose --class=inode fs/ext4/ext4.ko | head
ext4_fsblk_t ext4_new_blocks(handle_t * handle, struct inode * inode, ext4_lblk_t iblock, ext4_fsblk_t goal, long unsigned int * count, int * errp);
ext4_fsblk_t ext4_new_meta_blocks(handle_t * handle, struct inode * inode, ext4_fsblk_t goal, long unsigned int * count, int * errp);
ext4_fsblk_t ext4_new_meta_block(handle_t * handle, struct inode * inode, ext4_fsblk_t goal, int * errp);
void ext4_free_blocks(handle_t * handle, struct inode * inode, ext4_fsblk_t block, long unsigned int count, int metadata);
int ext4_check_dir_entry(const char * function, struct inode * dir, struct ext4_dir_entry_2 * de, struct buffer_head * bh, long unsigned int offset);
int ext4_release_dir(struct inode * inode, struct file * filp);
int ext4_release_file(struct inode * inode, struct file * filp);
void vfs_dq_init(struct inode * inode);
struct inode * ext4_new_inode(handle_t * handle, struct inode * dir, int mode);
void ext4_free_inode(handle_t * handle, struct inode * inode);
[acme@doppio linux-2.6-x86]$
My first attempt at this kind of tracing used a sparse (the kernel
checker tool uses it too), preprocessing and inserting the calls if,
looking that the tokens, I found I was at the start of a function source
code, and, for return tracing I just looke for return calls, inserting
at each return point, in the source code, the call, that way I could
even know which one of the returns were taken, and how many times.
Looking at Steven's redefinition of "if", I think we could do the same
for returns 8)
Then I used the DWARF debug info to find out which functions in the
objects of interest have as one of its args a pointer to the struct of
interest, i.e. I find its methods, then write a kernel module
registering jprobes and kretprobes for the functions I was interested
in.
Then I moved this to generate a systemtap script.
Then came the mcount approach, but it lacked return hooks.
Thanks to you I guess now I should rewrite this thing again :-)
> > so as part of postprocessing it separates the callgraphs per
> > object.
>
> I would like to separate the callgraph per thread. I'm not sure how. Perhaps
> by only drawing a simple
>
> ------8<----- switch to task nr x -----------8<-------------------
Well, you can record, for each entry, the thread id, but then you will
not know to what file, say, a close operation relates to.
- Arnaldo
2008/11/24 Arnaldo Carvalho de Melo <[email protected]>:
> Em Mon, Nov 24, 2008 at 08:10:47PM +0100, Fr?d?ric Weisbecker escreveu:
>> 2008/11/24 Arnaldo Carvalho de Melo <[email protected]>:
>> > I do something like that in my ctracer tool[1], take a look at one of
>> > the callgraphs:
>> >
>> > http://oops.ghostprotocols.net:81/ostra/dccp/tx/
>>
>>
>> Oh yes, that's what I would see as an end result. Except that it would be more
>> easy for me to have the time of execution on the left (I don't need the time
>> they are called since it's just a cost measure).
>>
>>
>> > I.e. the leaf functions doesn't use {}
>>
>> I guess I could avoid it too..
>>
>>
>> > On ctracer I didn't had this problem as I don't trace all functions,
>> > just the ones that receive as one of its parameters a pointer to the
>> > desired struct, and this pointer is present in all the trace buffer
>> > entries,
>>
>> How do you do this tracing by only passing a structure?
>
> [acme@doppio linux-2.6-x86]$ pfunct --verbose --class=inode fs/ext4/ext4.ko | head
> ext4_fsblk_t ext4_new_blocks(handle_t * handle, struct inode * inode, ext4_lblk_t iblock, ext4_fsblk_t goal, long unsigned int * count, int * errp);
> ext4_fsblk_t ext4_new_meta_blocks(handle_t * handle, struct inode * inode, ext4_fsblk_t goal, long unsigned int * count, int * errp);
> ext4_fsblk_t ext4_new_meta_block(handle_t * handle, struct inode * inode, ext4_fsblk_t goal, int * errp);
> void ext4_free_blocks(handle_t * handle, struct inode * inode, ext4_fsblk_t block, long unsigned int count, int metadata);
> int ext4_check_dir_entry(const char * function, struct inode * dir, struct ext4_dir_entry_2 * de, struct buffer_head * bh, long unsigned int offset);
> int ext4_release_dir(struct inode * inode, struct file * filp);
> int ext4_release_file(struct inode * inode, struct file * filp);
> void vfs_dq_init(struct inode * inode);
> struct inode * ext4_new_inode(handle_t * handle, struct inode * dir, int mode);
> void ext4_free_inode(handle_t * handle, struct inode * inode);
> [acme@doppio linux-2.6-x86]$
>
> My first attempt at this kind of tracing used a sparse (the kernel
> checker tool uses it too), preprocessing and inserting the calls if,
> looking that the tokens, I found I was at the start of a function source
> code, and, for return tracing I just looke for return calls, inserting
> at each return point, in the source code, the call, that way I could
> even know which one of the returns were taken, and how many times.
>
> Looking at Steven's redefinition of "if", I think we could do the same
> for returns 8)
>
> Then I used the DWARF debug info to find out which functions in the
> objects of interest have as one of its args a pointer to the struct of
> interest, i.e. I find its methods, then write a kernel module
> registering jprobes and kretprobes for the functions I was interested
> in.
>
> Then I moved this to generate a systemtap script.
Ok. I see now...
> Then came the mcount approach, but it lacked return hooks.
>
> Thanks to you I guess now I should rewrite this thing again :-)
:-)
>> > so as part of postprocessing it separates the callgraphs per
>> > object.
>>
>> I would like to separate the callgraph per thread. I'm not sure how. Perhaps
>> by only drawing a simple
>>
>> ------8<----- switch to task nr x -----------8<-------------------
>
> Well, you can record, for each entry, the thread id, but then you will
> not know to what file, say, a close operation relates to.
The pid is registered automatically for each trace that uses the ring-buffer.
This way I will be able to find the files related :-)
2008/11/24 Arnaldo Carvalho de Melo <[email protected]>:
> Well, you can record, for each entry, the thread id, but then you will
> not know to what file, say, a close operation relates to.
Oh ok, I see...yes. Hmm, I will see later, when the output will be...stable.
I made a patch last evening and I almost finished implementing the
desired output.
But while I went through, I was adding some more keywords with other
"return-function-tracing" semantics, plus the risk of confusion
resulting from the entry-on-function-for-return-tracing keywords....
I planned to change all the keywords according to a new name for this
tracer just after this patch.
But I can't seriously submit such a mess, even with a second patch
that fixes the keywords....
I would like to change the name of the tracer and its keywords before
sending the output changes.
Do you agree with "full function tracer" (since we hook now on the two sides)?
Thanks.... :-)
* Fr?d?ric Weisbecker <[email protected]> wrote:
> I made a patch last evening and I almost finished implementing the
> desired output.
>
> But while I went through, I was adding some more keywords with other
> "return-function-tracing" semantics, plus the risk of confusion
> resulting from the entry-on-function-for-return-tracing keywords....
>
> I planned to change all the keywords according to a new name for
> this tracer just after this patch. But I can't seriously submit such
> a mess, even with a second patch that fixes the keywords....
>
> I would like to change the name of the tracer and its keywords
> before sending the output changes.
> Do you agree with "full function tracer" (since we hook now on the
> two sides)?
"full function tracer" sounds a bit funny and quirky. How about
"function call tracer"? Versus the "function tracer" or "function
entry tracer" which is the lighter variant - both in name and in
overhead. So we'd have:
# cat /debug/tracing/available_tracers
mmiotrace wakeup irqsoff function function-call sysprof sched_switch initcall nop
note how intuitive it is: "function-call" is 'more' than just the
plain function-tracer. It also expresses its main property: it traces
the full call, entry and exit and return code as well.
Hm?
Ingo
* Ingo Molnar <[email protected]> wrote:
> > Do you agree with "full function tracer" (since we hook now on the
> > two sides)?
>
> "full function tracer" sounds a bit funny and quirky. How about
> "function call tracer"? Versus the "function tracer" or "function
> entry tracer" which is the lighter variant - both in name and in
> overhead. So we'd have:
>
> # cat /debug/tracing/available_tracers
> mmiotrace wakeup irqsoff function function-call sysprof sched_switch initcall nop
>
> note how intuitive it is: "function-call" is 'more' than just the
> plain function-tracer. It also expresses its main property: it
> traces the full call, entry and exit and return code as well.
another similar naming would be: the "function-graph" tracer.
function-callgraph would be too long.
i think "function-call" is the best of all - relatively short and
expressive.
Ingo
2008/11/25 Ingo Molnar <[email protected]>:
>
> * Ingo Molnar <[email protected]> wrote:
>
>> > Do you agree with "full function tracer" (since we hook now on the
>> > two sides)?
>>
>> "full function tracer" sounds a bit funny and quirky. How about
>> "function call tracer"? Versus the "function tracer" or "function
>> entry tracer" which is the lighter variant - both in name and in
>> overhead. So we'd have:
>>
>> # cat /debug/tracing/available_tracers
>> mmiotrace wakeup irqsoff function function-call sysprof sched_switch initcall nop
>>
>> note how intuitive it is: "function-call" is 'more' than just the
>> plain function-tracer. It also expresses its main property: it
>> traces the full call, entry and exit and return code as well.
>
> another similar naming would be: the "function-graph" tracer.
> function-callgraph would be too long.
>
> i think "function-call" is the best of all - relatively short and
> expressive.
>
> Ingo
>
Ok. No problem for me. But if ftrace is not renamed to ftrace-entry, I
think that it will be
confusing...
* Ingo Molnar <[email protected]> wrote:
>
> * Ingo Molnar <[email protected]> wrote:
>
> > > Do you agree with "full function tracer" (since we hook now on the
> > > two sides)?
> >
> > "full function tracer" sounds a bit funny and quirky. How about
> > "function call tracer"? Versus the "function tracer" or "function
> > entry tracer" which is the lighter variant - both in name and in
> > overhead. So we'd have:
> >
> > # cat /debug/tracing/available_tracers
> > mmiotrace wakeup irqsoff function function-call sysprof sched_switch initcall nop
> >
> > note how intuitive it is: "function-call" is 'more' than just the
> > plain function-tracer. It also expresses its main property: it
> > traces the full call, entry and exit and return code as well.
>
> another similar naming would be: the "function-graph" tracer.
> function-callgraph would be too long.
Steve thinks function-graph is even more expressive, so lets go with
that instead :)
it will certainly make sure there's no misunderstanding about the role
and scope of this tracer, and it's short and expressive as well.
so i'd suggest the following sed -i rules:
s/FUNCTION_RET_TRACER/FUNCTION_GRAPH_TRACER/g
i'd suggest to keep the ret_stack names - those are proper. (the thing
that is used to construct the graph is the return stack)
also, please do:
git mv kernel/tracing/trace_functions_return.c kernel/tracing/trace_functions_graph.c
and Makefile glue fixup:
s/functions_return/functions_graph/g
Ingo
2008/11/25 Ingo Molnar <[email protected]>:
>
> * Ingo Molnar <[email protected]> wrote:
>
>>
>> * Ingo Molnar <[email protected]> wrote:
>>
>> > > Do you agree with "full function tracer" (since we hook now on the
>> > > two sides)?
>> >
>> > "full function tracer" sounds a bit funny and quirky. How about
>> > "function call tracer"? Versus the "function tracer" or "function
>> > entry tracer" which is the lighter variant - both in name and in
>> > overhead. So we'd have:
>> >
>> > # cat /debug/tracing/available_tracers
>> > mmiotrace wakeup irqsoff function function-call sysprof sched_switch initcall nop
>> >
>> > note how intuitive it is: "function-call" is 'more' than just the
>> > plain function-tracer. It also expresses its main property: it
>> > traces the full call, entry and exit and return code as well.
>>
>> another similar naming would be: the "function-graph" tracer.
>> function-callgraph would be too long.
>
> Steve thinks function-graph is even more expressive, so lets go with
> that instead :)
>
> it will certainly make sure there's no misunderstanding about the role
> and scope of this tracer, and it's short and expressive as well.
>
> so i'd suggest the following sed -i rules:
>
> s/FUNCTION_RET_TRACER/FUNCTION_GRAPH_TRACER/g
>
> i'd suggest to keep the ret_stack names - those are proper. (the thing
> that is used to construct the graph is the return stack)
>
> also, please do:
>
> git mv kernel/tracing/trace_functions_return.c kernel/tracing/trace_functions_graph.c
>
> and Makefile glue fixup:
>
> s/functions_return/functions_graph/g
>
> Ingo
>
Ok, and perhaps even several structures and functions.... There are
some in trace_functions_return.c, arch/x86/kernel/ftrace.c,
kernel/trace/ftrace.c
Some of them which act very close to "return hooking" should keep
their name, but for some others, I should put the graph semantics....