[BUG] perf tool: uprobe displays wrong argument value

* [BUG] perf tool: uprobe displays wrong argument value
@ 2016-08-25 12:02 Jiri Olsa
  2016-08-25 13:11 ` Yauheni Kaliuta
  0 siblings, 1 reply; 3+ messages in thread
From: Jiri Olsa @ 2016-08-25 12:02 UTC (permalink / raw)
  To: Masami Hiramatsu
  Cc: Arnaldo Carvalho de Melo, linux-kernel, Peter Zijlstra,
	Ingo Molnar, Michael Petlan, Namhyung Kim, pbunyan

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

^ permalink raw reply	[flat|nested] 3+ messages in thread