Perf misreports userspace args to unoptimized functions

[Dima Kogan]

Hi.

I'm seeing an issue with the way perf interfaces with uprobes that
results in incorrect printing of function arguments under fairly normal
conditions. Example:

Let's say I have a trivial C program tst.c:

=============================
  #include <stdio.h>
  #include <stdlib.h>
  int f(int x)
  {
      return !printf("%d\n", x);
  }
  int main(int argc, char* argv[])
  {
      return f(argc);
  }
==============================

I ask perf to trap all calls to f() and to give me the value of the x
argument:

==============================
  $ gcc-5 -g -o tst tst.c &&
    perf probe -x tst --add 'f x' &&
    perf record -eprobe_tst:f ./tst 2 3 4 &&
    perf script    

  Added new event:
    probe_tst:f          (on f in /tmp/tst with x)

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

          perf record -e probe_tst:f -aR sleep 1

  4
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.016 MB perf.data (1 samples) ]
               tst 24626 [003] 98586.485680: probe_tst:f: (4004e6) x=0
==============================

Note that the value passed to f() was 4, but perf reported it as 0
instead.

If I look at what uprobes was actually asked to report, I see this:

==============================
  $ cat /sys/kernel/debug/tracing/uprobe_events 

  p:probe_tst/f /tmp/tst:0x00000000000004e6 x=-12(%sp):s32
==============================

The corresponding disassembly is:

==============================
  $ objdump -d tst | awk '/<f>:/,/^$/'
  00000000004004e6 <f>:
    4004e6:       55                      push   %rbp
    4004e7:       48 89 e5                mov    %rsp,%rbp
    4004ea:       48 83 ec 10             sub    $0x10,%rsp
    4004ee:       89 7d fc                mov    %edi,-0x4(%rbp)
    4004f1:       8b 45 fc                mov    -0x4(%rbp),%eax
    4004f4:       89 c6                   mov    %eax,%esi
    4004f6:       bf b4 05 40 00          mov    $0x4005b4,%edi
    4004fb:       b8 00 00 00 00          mov    $0x0,%eax
    400500:       e8 bb fe ff ff          callq  4003c0 <printf@plt>
    400505:       85 c0                   test   %eax,%eax
    400507:       0f 94 c0                sete   %al
    40050a:       0f b6 c0                movzbl %al,%eax
    40050d:       c9                      leaveq 
    40050e:       c3                      retq   
==============================

So uprobes was looking at the argument as a local stack variable.
However the trap was placed at the start of the function, where the
stack variable wasn't yet available (the argument is still in %di).

This doesn't happen with optimized code, because (at least in this
simple example) the variable is simply kept in %di, the DWARF data
indicates this, and perf picks that up. Any particular thoughts about
how to solve this? Options are

1. place the trace after the local variables are set (4004f1 in this
   example)
2. Look at %di instead of the stack variable

Is there enough information in the DWARF to know to do either of these?
I didn't see anything obvious. Is either option reliable? I.e. could the
optimizer break them?

Thanks
dima