Re: Problems on glibc UTRACE

[David Smith <dsmith at redhat dot com>]

On 11/24/2014 12:12 AM, Shane Wayne wrote:
> 2014-11-22 0:40 GMT+08:00 David Smith <dsmith@redhat.com>:
>> On 11/20/2014 08:25 PM, Shane Wayne wrote:
>>> I've recently tap into malloc function of glibc, but I've encounter
>>> some problems.
>>> Firstly, I have install systemtap and glibc-dbg on Ubuntu 14.04(with
>>> kernel 3.13 and UTRACE kernel flag default on).
>>
>> What UTRACE kernel flag are you talking about? In the past (RHEL5 &
>> RHEL6), there was an in-kernel utrace. Now utrace functionality is built
>> on top of kernel tracepoints.
> Sorry, I got it wrong, it was UPROBES flag, in /boot/config-3.13.0-40-generic
> 42:
> CONFIG_ARCH_SUPPORTS_UPROBES=y
> CONFIG_DEFCONFIG_LIST="/lib/modules/$UNAME_RELEASE/.config"
> CONFIG_IRQ_WORK=y
> CONFIG_BUILDTIME_EXTABLE_SORT=y
> 
> But in /boot/config-3.2.0-61-generic in Ubuntu dist there is no flags
> related to UPROBES

If UPROBES isn't on in your kernel, I doubt the systemtap script would
even compile. If by some miracle it did compile, you certainly wouldn't
get any hits from a function probe.

>>> The result show that, I can tap into
>>> process("/lib/x86_64-linux-gnu/libc.so.6").function("malloc"), BUT,
>>> the question is that, I can't get the right $bytes in this system, the
>>> value I've got always like an pointer value start with 0x7f****. I've
>>> tried the script on my own micro benchmark, with a single malloc
>>> function invoke, the result also show that I can't get the right
>>> parameters out, what's more, my micro benchmark triggered the tap
>>> TWICE.
>>> Secondly, I migrate to CentOS 6.6, with kernel
>>> 2.6.32-504.1.3.el6.x86_64 and UTRACE kernel flag default on, at this
>>> time, I can get the right parameter $bytes out, but in my own micro
>>> benchmark, the twice triggered problem also appear.
>>
>> Do you have glibc debuginfo installed on your Ubuntu system? Can you
>> show us your systemtap script?
>>
> I think the following packets was related to Glibc:
> ii  libc6:amd64                           2.19-0ubuntu6.3
>               amd64        Embedded GNU C Library: Shared libraries
> ii  libc6-dbg:amd64                       2.19-0ubuntu6.3
>               amd64        Embedded GNU C Library: detached debugging
> symbols
> ii  libc6-dev:amd64                       2.19-0ubuntu6.3
>               amd64        Embedded GNU C Library: Development
> Libraries and Header Files
> 
> I think libc60dbg:amd64 was the debuginfo?

Sounds reasonable to me, I'm not familiar with Ubuntu. The versions seem
to match, so that looks good.

> The script was:
> probe process("/lib/x86_64-linux-gnu/libc.so.6").function("malloc").return
> {
>   if(execname()==@1)
>   {
>     t = gettimeofday_us()
>     printf("malloc\t%s\treturn=0x%x\tPID:%d\tTID:%d\tCPU:%d\tSTART:%d\tEND:%d\n",$$parms,$return,pid(),tid(),cpu(),@entry(gettimeofday_us()),t)
>   }
> }
> 
> And the result like:
> malloc  bytes=0x7ffff45c7440    return=0x951010 PID:21274
> TID:21274  CPU:16   START:1416809393964834  END:1416809393964865
> malloc  bytes=0x7ffff45c7440    return=0x951010 PID:21274
> TID:21274  CPU:16   START:1416809393964737  END:1416809393964874
> 
> The source file was like:
> #include <stdio.h>
> #include <stdlib.h>
> 
> int main(void)
> {
>   void *ptr;
>   int i;
> 
>   getchar();
>   ptr = malloc(10);
>   printf("%x",ptr);
>   getchar();
>   return 0;
> }
> 
> The result also shows the twice trigger problem
> Thanks for your reply~ David Smith~

So, I ran your test program and script and got similar results. So, I
ran gdb on the test program. Here's what I get:

====
Breakpoint 1, main () at testprog.c:10
10	  ptr = malloc(10);
(gdb) s
__GI___libc_malloc (bytes=140737488347248) at malloc.c:2845
=====

Here are my breakpoints:

=====
(gdb) info b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x00000000004005dd in main at testprog.c:10
	breakpoint already hit 1 time
2       breakpoint     keep y   0x0000003ff7a7fca9 in __GI___libc_malloc
                                                   at malloc.c:2849
	breakpoint already hit 2 times
====

Also note that the 2nd breakpoint gets hit twice.

So, since gdb and systemtap agree here, I think systemtap is operating
correctly.

Now, as to where the odd bytes value is coming from and why malloc is
getting called twice, I don't really know. Perhaps some glibc oddity?
glibc does some odd things with function wrappers, hooks, etc.

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)