Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1470096 > unrolled thread

[BUG] perf tool: uprobe displays wrong argument value

Back to article view | Back to linux.kernel

Contents

  [BUG] perf tool: uprobe displays wrong argument value Jiri Olsa <jolsa@redhat.com> - 2016-08-25 14:10 +0200
    Re: [BUG] perf tool: uprobe displays wrong argument value Yauheni Kaliuta <yauheni.kaliuta@redhat.com> - 2016-08-25 15:20 +0200
      Re: [BUG] perf tool: uprobe displays wrong argument value Namhyung Kim <namhyung@kernel.org> - 2016-08-26 05:50 +0200

#1470096 — [BUG] perf tool: uprobe displays wrong argument value

hi,
Michael reported wrong values for function arguments being shown
when adding uprobe on function with argument, I dig in and got
even more confused.. ;-)

This is the testing binary:

        ---
        #include <stdio.h>

        int func(int par)
        {
                return par;
        }

        int main(void)
        {
                int a = 1;
                return func(a);
        }
        ---

Adding the uprobe:

        # ./perf probe -x ./ex --add 'func par'
        Added new event:
          probe_ex:func        (on func in /home/jolsa/linux-perf/tools/perf/ex with par)

        You can now use it in all perf tools, such as:

                perf record -e probe_ex:func -aR sleep 1

Enabling globaly:
        # echo 1 > events/probe_ex/func/enable 


After running the binary, this is the 'trace' output:
        # cat trace
          ...
                      ex-15942 [014] d...   371.608516: func: (0x4004f6) par=0

Same with perf record:
        # ./perf record -e probe_ex:func -aR ./ex
        [ perf record: Woken up 1 times to write data ]
        [ perf record: Captured and wrote 0.157 MB perf.data (1 samples) ]
        # ./perf script
                      ex 15954 [017]   489.298178: probe_ex:func: (4004f6) par=0


So, there's clearly bug in there..


Now here's where I got confused..  please continue reading only on your own risk ;-)

The uprobe_events shows following record:
        # cat uprobe_events 
        p:probe_ex/func /home/jolsa/linux-perf/tools/perf/ex:0x00000000000004f6 par=-12(%sp):s32

I can't see how ($rsp - 12) address could hold the 'par' value,
when we stop at the 'func' addreess, so where did it come from?

I figured it's the debug info, namely the par argument's CU:

        $ readelf --debug-dump ./ex | less
        ...

         <2><94>: Abbrev Number: 5 (DW_TAG_formal_parameter)
            <95>   DW_AT_name        : par
            <99>   DW_AT_decl_file   : 1
            <9a>   DW_AT_decl_line   : 3
            <9b>   DW_AT_type        : <0x57>
            <9f>   DW_AT_location    : 2 byte block: 91 6c      (DW_OP_fbreg: -20)

which says the value is frame buffer reg -20.. I can't see
this will get the proper value for any of $rbp or $rsp even
after new func's stack frame is set..

Also if I set gdb to stop directly on the function address,
it shows wrong value:

        # gdb ./ex
        (gdb) b *0x4004f6
        Breakpoint 1 at 0x4004f6: file ex.c, line 4.
        (gdb) r
        Starting program: /home/jolsa/linux-perf/tools/perf/ex 
        Missing separate debuginfos, use: dnf debuginfo-install glibc-2.21-13.fc22.x86_64

        Breakpoint 1, func (par=0) at ex.c:4
        4       {
        (gdb) 

Apart from when I set the breakpoint after the new stack frame is set:

        (gdb) b func
        Breakpoint 1 at 0x4004fd: file ex.c, line 5.
        (gdb) r
        Starting program: /home/jolsa/linux-perf/tools/perf/ex 
        Missing separate debuginfos, use: dnf debuginfo-install glibc-2.21-13.fc22.x86_64

        Breakpoint 1, func (par=1) at ex.c:5
        5               return par;


I'm clearly missing something..

thanks for help,
jirka


---
kernel version: 4.8.0-rc2
perf version: latest Arnaldo's perf/core

[toc] | [next] | [standalone]

#1470133

Hi, Jiri!

>>>>> On Thu, 25 Aug 2016 14:02:50 +0200, Jiri Olsa  wrote:

[...]

 > Now here's where I got confused..  please continue reading only on your own risk ;-)

 > The uprobe_events shows following record:
 >         # cat uprobe_events 
 >         p:probe_ex/func /home/jolsa/linux-perf/tools/perf/ex:0x00000000000004f6 par=-12(%sp):s32

 > I can't see how ($rsp - 12) address could hold the 'par' value,
 > when we stop at the 'func' addreess, so where did it come from?

 > I figured it's the debug info, namely the par argument's CU:

 >         $ readelf --debug-dump ./ex | less
 >         ...

 >          <2><94>: Abbrev Number: 5 (DW_TAG_formal_parameter)
 >             <95>   DW_AT_name        : par
 >             <99>   DW_AT_decl_file   : 1
 >             <9a>   DW_AT_decl_line   : 3
 >             <9b>   DW_AT_type        : <0x57>
 >             <9f>   DW_AT_location    : 2 byte block: 91 6c      (DW_OP_fbreg: -20)

 > which says the value is frame buffer reg -20.. I can't see
 > this will get the proper value for any of $rbp or $rsp even
 > after new func's stack frame is set..

I see how it can do that:

Breakpoint 1, main () at 1.c:10
10        int a = 1;
(gdb) p &a
$1 = (int *) 0x7fffffffe9cc
(gdb) br *0x00000000004004d6
Breakpoint 2 at 0x4004d6: file 1.c, line 4.

(before the prologue, as you did)

Breakpoint 2, func (par=0) at 1.c:4
4       {
(gdb) p $rsp + 20
$2 = (void *) 0x7fffffffe9cc (same as &a).


So DW_OP_call_frame_cfa restores %rsp before the function call.



 > Also if I set gdb to stop directly on the function address,
 > it shows wrong value:

 >         # gdb ./ex
 >         (gdb) b *0x4004f6
 >         Breakpoint 1 at 0x4004f6: file ex.c, line 4.
 >         (gdb) r
 >         Starting program: /home/jolsa/linux-perf/tools/perf/ex 
 >         Missing separate debuginfos, use: dnf debuginfo-install glibc-2.21-13.fc22.x86_64

 >         Breakpoint 1, func (par=0) at ex.c:4
 >         4       {
 >         (gdb) 

 > Apart from when I set the breakpoint after the new stack frame is set:

 >         (gdb) b func
 >         Breakpoint 1 at 0x4004fd: file ex.c, line 5.
 >         (gdb) r
 >         Starting program: /home/jolsa/linux-perf/tools/perf/ex 
 >         Missing separate debuginfos, use: dnf debuginfo-install glibc-2.21-13.fc22.x86_64

 >         Breakpoint 1, func (par=1) at ex.c:5
 >         5               return par;


 > I'm clearly missing something..

 > thanks for help,
 > jirka


 > ---
 > kernel version: 4.8.0-rc2
 > perf version: latest Arnaldo's perf/core


-- 
WBR,
Yauheni Kaliuta

[toc] | [prev] | [next] | [standalone]

#1470533

Hello,

On Thu, Aug 25, 2016 at 04:11:47PM +0300, Yauheni Kaliuta wrote:
> Hi, Jiri!
> 
> >>>>> On Thu, 25 Aug 2016 14:02:50 +0200, Jiri Olsa  wrote:
> 
> [...]
> 
>  > Now here's where I got confused..  please continue reading only on your own risk ;-)
> 
>  > The uprobe_events shows following record:
>  >         # cat uprobe_events 
>  >         p:probe_ex/func /home/jolsa/linux-perf/tools/perf/ex:0x00000000000004f6 par=-12(%sp):s32
> 
>  > I can't see how ($rsp - 12) address could hold the 'par' value,
>  > when we stop at the 'func' addreess, so where did it come from?
> 
>  > I figured it's the debug info, namely the par argument's CU:
> 
>  >         $ readelf --debug-dump ./ex | less
>  >         ...
> 
>  >          <2><94>: Abbrev Number: 5 (DW_TAG_formal_parameter)
>  >             <95>   DW_AT_name        : par
>  >             <99>   DW_AT_decl_file   : 1
>  >             <9a>   DW_AT_decl_line   : 3
>  >             <9b>   DW_AT_type        : <0x57>
>  >             <9f>   DW_AT_location    : 2 byte block: 91 6c      (DW_OP_fbreg: -20)
> 
>  > which says the value is frame buffer reg -20.. I can't see
>  > this will get the proper value for any of $rbp or $rsp even
>  > after new func's stack frame is set..
> 
> I see how it can do that:
> 
> Breakpoint 1, main () at 1.c:10
> 10        int a = 1;
> (gdb) p &a
> $1 = (int *) 0x7fffffffe9cc
> (gdb) br *0x00000000004004d6
> Breakpoint 2 at 0x4004d6: file 1.c, line 4.
> 
> (before the prologue, as you did)
> 
> Breakpoint 2, func (par=0) at 1.c:4
> 4       {
> (gdb) p $rsp + 20
> $2 = (void *) 0x7fffffffe9cc (same as &a).

No, that's the address of 'a' in main function, not the address of
'par' in the func.  I was also confused at first (due to same offset
of 20, but it's positive not negative), but the frame base is not the
value of %rsp.  It's the default CFA of '%rsp + 8'.

  <1><331>: Abbrev Number: 20 (DW_TAG_subprogram)
     <332>   DW_AT_external    : 1
     <332>   DW_AT_name        : (indirect string, offset: 0x12a): func
     <336>   DW_AT_decl_file   : 1
     <337>   DW_AT_decl_line   : 3
     <338>   DW_AT_prototyped  : 1
     <338>   DW_AT_type        : <0x62>
     <33c>   DW_AT_low_pc      : 0x4004a6
     <344>   DW_AT_high_pc     : 0xc
     <34c>   DW_AT_frame_base  : 1 byte block: 9c (DW_OP_call_frame_cfa)

And in the CIE:

  DW_CFA_def_cfa: r7 (rsp) ofs 8

Hence,

  (fbreg - 20) = ((%rsp + 8) - 20) = (%rsp - 12).

So the location of 'par' (%rsp - 12) is correct but we are in a point
before setting the value of the variable.  As you know, on x86_64 the
first argument is passed via %rdi (or %edi in this case since it's
'int') and then copied to the (%rsp - 12) in 0x4004aa:

  00000000004004a6 <func>:
    4004a6:	 55			push   %rbp
    4004a7:	 48 89 e5             	mov    %rsp,%rbp
    4004aa:	 89 7d fc             	mov    %edi,-0x4(%rbp)  <-- here
    4004ad:	 8b 45 fc             	mov    -0x4(%rbp),%eax
    4004b0:      5d                     pop    %rbp
    4004b1:      c3                     retq   

Note that after executing 'push rbp' the value of %rsp decreased by 8
and it's copied to %rbp at 0x4004a7.  So (%rsp - 12) at 0x4004a6 is
same as (%rbp - 4) at 0x4004aa, right?  And the value of 'par' is only
meaningful after 0x4004ad.

So I think the location of 'par' should be 'rdi' (or 'edi') register,
and it's indeed true when compiling with -O2 AFAICS.  But for some
reason it seems that gcc prefers to carry it on the stack by default,
assuming that programs make use of debuginfo will access the variable
after setting the frame and variables/arguments correctly.


> 
> 
> So DW_OP_call_frame_cfa restores %rsp before the function call.
> 
> 
> 
>  > Also if I set gdb to stop directly on the function address,
>  > it shows wrong value:
> 
>  >         # gdb ./ex
>  >         (gdb) b *0x4004f6
>  >         Breakpoint 1 at 0x4004f6: file ex.c, line 4.
>  >         (gdb) r
>  >         Starting program: /home/jolsa/linux-perf/tools/perf/ex 
>  >         Missing separate debuginfos, use: dnf debuginfo-install glibc-2.21-13.fc22.x86_64
> 
>  >         Breakpoint 1, func (par=0) at ex.c:4
>  >         4       {
>  >         (gdb) 
> 
>  > Apart from when I set the breakpoint after the new stack frame is set:
> 
>  >         (gdb) b func
>  >         Breakpoint 1 at 0x4004fd: file ex.c, line 5.

I don't know how the gdb can point to 0x4004fd when adding a
breakpoint at 'func'.  It seems to know the right place where the
variables are all set.

Thanks,
Namhyung


>  >         (gdb) r
>  >         Starting program: /home/jolsa/linux-perf/tools/perf/ex 
>  >         Missing separate debuginfos, use: dnf debuginfo-install glibc-2.21-13.fc22.x86_64
> 
>  >         Breakpoint 1, func (par=1) at ex.c:5
>  >         5               return par;
> 
> 
>  > I'm clearly missing something..
> 
>  > thanks for help,
>  > jirka
> 
> 
>  > ---
>  > kernel version: 4.8.0-rc2
>  > perf version: latest Arnaldo's perf/core
> 
> 
> -- 
> WBR,
> Yauheni Kaliuta

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web