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
