Problems on glibc UTRACE

Problems on glibc UTRACE

[Shane Wayne]

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

Re: Problems on glibc UTRACE

[David Smith]

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.

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

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

Re: Problems on glibc UTRACE

[Shane Wayne]

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

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

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~



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



-- 
------------------------------------------------------------
ZHANG Xiao

The Institute of Computer Software Engineering and Theory in Xi'an
Jiaotong University
Master-and-Doctoral Program Student

ACM Student Member
CCF Student Member
IEEE Computer Society Sister Society Associate Member

Xi'an Jiaotong University
Bachelor of Engineering in Computer Science and Technology

The Chinese University of Hong Kong
International Asia Study Program in CS/CE/EE/IE

Re: Problems on glibc UTRACE

[David Smith]

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)

Re: Problems on glibc UTRACE

[Josh Stone]

On 11/24/2014 07:39 AM, David Smith wrote:
> 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.

I don't know about getting called twice, but the odd value may be this:
https://bugzilla.redhat.com/show_bug.cgi?id=1151226

If so, stap -P ought to help by forcing a prologue search.