Re: [PATCH 4/4] tracing/function-return-tracer: Support for dynamicftrace on function return tracer

From: Steven Rostedt
Date: Wed Nov 26 2008 - 14:22:21 EST



[
Sorry Tim to reply again, but alpine broke on Frederic's funny
characters in his email address, and it chopped off all the Cc's :-(
]

On Wed, 26 Nov 2008, Tim Bird wrote:
>
> Very sorry I'm coming to this thread late. I didn't notice it until
> today.
>
> Not to question the whole approach, and sorry if this was
> discussed before, but why wasn't -finstrument-functions used
> to instrument the function exits. This worked well for KFT
> (See http://elinux.org/Kernel_Function_Trace). I'm not sure if the
> function prologue and epilogue modifications done by -mcount are
> different than -finstrument-functions, but I thought I remember
something
> about Steven testing -finstrument-functions in an early version of
ftrace.
>
> By the way, I'm really excited to see this "function_cost" stuff being
> worked on. It has proven to be extremely useful for analyzing early
boot
> latencies at Sony.
>

No prob Tim. I need to make a standard template to explain the reason not
to use -finstrument-functions. (/me goes look for a previous post...)

Here it is:

(here's the original post: http://lkml.org/lkml/2008/10/30/372 that
was posted at the beginning of Frederic's work)

========================================================
Lets take a simple C file called traceme.c:


---
static int x;

void trace_me(void)
{
x++;
}
---

Normal compiling of:

gcc -c traceme.c

produces:

00000000 <trace_me>:
0: 55 push %ebp
1: 89 e5 mov %esp,%ebp
3: a1 00 00 00 00 mov 0x0,%eax
4: R_386_32 .bss
8: 83 c0 01 add $0x1,%eax
b: a3 00 00 00 00 mov %eax,0x0
c: R_386_32 .bss
10: 5d pop %ebp
11: c3 ret


With

gcc -c -pg traceme.c

00000000 <trace_me>:
0: 55 push %ebp
1: 89 e5 mov %esp,%ebp
3: e8 fc ff ff ff call 4 <trace_me+0x4>
4: R_386_PC32 mcount
8: a1 00 00 00 00 mov 0x0,%eax
9: R_386_32 .bss
d: 83 c0 01 add $0x1,%eax
10: a3 00 00 00 00 mov %eax,0x0
11: R_386_32 .bss
15: 5d pop %ebp
16: c3 ret


The only difference between the two is an added "call mcount".
5 byte op to replace with dynamic ftrace.

But now lets look at:

gcc -c -finstrument-functions traceme.c

00000000 <trace_me>:
0: 55 push %ebp
1: 89 e5 mov %esp,%ebp
3: 83 ec 18 sub $0x18,%esp
6: 8b 45 04 mov 0x4(%ebp),%eax
9: 89 44 24 04 mov %eax,0x4(%esp)
d: c7 04 24 00 00 00 00 movl $0x0,(%esp)
10: R_386_32 trace_me
14: e8 fc ff ff ff call 15 <trace_me+0x15>
15: R_386_PC32 __cyg_profile_func_enter
19: a1 00 00 00 00 mov 0x0,%eax
1a: R_386_32 .bss
1e: 83 c0 01 add $0x1,%eax
21: a3 00 00 00 00 mov %eax,0x0
22: R_386_32 .bss
26: 8b 45 04 mov 0x4(%ebp),%eax
29: 89 44 24 04 mov %eax,0x4(%esp)
2d: c7 04 24 00 00 00 00 movl $0x0,(%esp)
30: R_386_32 trace_me
34: e8 fc ff ff ff call 35 <trace_me+0x35>
35: R_386_PC32 __cyg_profile_func_exit
39: c9 leave
3a: c3 ret

Here we see that

mov %eax, 0x4(%esp)
movl $trace_me,(%esp)
call _cyg_profile_func_enter

is added at the beginning and

mov %eax,0x4(%esp)
mov $trace_me,(%esp)
call __cyg_profile_func_exit

is added at the end.

This is not 5 extra bytes but 27 extra bytes for a total of 32 bytes
at every function.

========================================================

The overhead of -finstrument-functions is way too big. Remember, with
using mcount, we can also patch away the callers. It's 5 bytes on both
x86_64 and i386 and 4 bytes on most other archs. To patch away the
-finstrument-functions would be too large, not to mention, you could not
do it with nops. You whould have to have a jump, since patching more than
one op code would lead to race conditions with a task being preempted in
the middle of those nops.

I need to file this information away to give the next person that asks
this question ;-)

> Sorry again I didn't catch this and previous related threads
> earlier. I have some post-processing tools which might be useful here.
> Also, I've found it very handy to have the capability to filter by
minimum
> function duration. Is there any work to do that with the
> current system. If not, maybe I could take a look at that and see if
> I can add something.
>

Actually, I probably should have Cc'd you anyway. I know you did similar
work. You may be able to add that filtering to the dynamic ftrace so that
the tracer will filter them out as well. If you want to work on this,
feel free. There's already been a lot of good ideas (and code) coming from
other developers :-)

-- Steve

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/