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

Hi, Jiri!

[...]

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.

WBR,
Yauheni Kaliuta

Hello,

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.

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