From: Arnaldo Carvalho de Melo <acme@kernel.org>
To: "平松雅巳 / HIRAMATU，MASAMI" <masami.hiramatsu.pt@hitachi.com>
Cc: 'Michael Petlan' <mpetlan@redhat.com>,
"linux-perf-users@vger.kernel.org"
<linux-perf-users@vger.kernel.org>, Jiri Olsa <jolsa@kernel.org>,
Ingo Molnar <mingo@kernel.org>, David Ahern <dsahern@gmail.com>,
Wang Nan <wangnan0@huawei.com>
Subject: Re: bogus values of variables in userspace probes
Date: Tue, 24 Nov 2015 23:24:44 -0300 [thread overview]
Message-ID: <20151125022444.GN18140@kernel.org> (raw)
In-Reply-To: <50399556C9727B4D88A595C8584AAB375262F4C3@GSjpTKYDCembx32.service.hitachi.net>
Em Wed, Nov 25, 2015 at 01:03:47AM +0000, 平松雅巳 / HIRAMATU，MASAMI escreveu:
> From: Michael Petlan [mailto:mpetlan@redhat.com]
> >On Tue, 2015-11-24 at 12:08 -0300, Arnaldo Carvalho de Melo wrote:
> >> Em Tue, Nov 24, 2015 at 12:18:22PM +0100, Michael Petlan escreveu:
> >> > I have been playing with perf-probe tool and I found out that some bogus
> >> > values of a function argument are obtained by perf-record.
> >> >
> >> > How to reproduce:
> >> >
> >> > gcc -O0 -g -o dummy dummy.c
> >> > perf probe -x ./dummy --add 'isprime a'
> >> > perf record -e probe_dummy:isprime ./dummy
> >> > perf script
> >> >
> >> > The actual output looks like the following:
> >> >
> >> > dummy 32476 [000] 3534401.838454: probe_dummy:isprime: (400530) a=32767
> >> > dummy 32476 [000] 3534401.838504: probe_dummy:isprime: (400530) a=32714
> >> > dummy 32476 [000] 3534401.838513: probe_dummy:isprime: (400530) a=3
> >> > dummy 32476 [000] 3534401.838519: probe_dummy:isprime: (400530) a=4
> >> > dummy 32476 [000] 3534401.838525: probe_dummy:isprime: (400530) a=5
> >> > dummy 32476 [000] 3534401.838531: probe_dummy:isprime: (400530) a=6
> >> > dummy 32476 [000] 3534401.838537: probe_dummy:isprime: (400530) a=7
> >> > dummy 32476 [000] 3534401.838543: probe_dummy:isprime: (400530) a=13
> >> > dummy 32476 [000] 3534401.838561: probe_dummy:isprime: (400530) a=17
>
> Hmm, very odd.
>
> Could you try to use ftrace with user stacktrace on that event?
>
> # echo 1 > (debugfs)/tracing/options/stacktrace
> # echo 1 > (debugfs)/tracing/options/userstacktrace
> # echo 1 > events/probe_dummy/isprime/enable
> # ./dummy
> # cat trace
>
> And decode the stack address by using (eu-)addr2line ?
[root@zoo tracing]# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 27/27 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
isprime-21965 [001] d... 199755.374474: isprime: (0x400536) a=0
isprime-21965 [001] d... 199755.374487: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374488: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374561: isprime: (0x400536) a=32618
isprime-21965 [001] d... 199755.374567: <stack trace>
=G> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374568: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374577: isprime: (0x400536) a=3
isprime-21965 [001] d... 199755.374583: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374583: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374591: isprime: (0x400536) a=4
isprime-21965 [001] d... 199755.374597: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374597: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374604: isprime: (0x400536) a=5
isprime-21965 [001] d... 199755.374610: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374610: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374618: isprime: (0x400536) a=6
isprime-21965 [001] d... 199755.374624: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374624: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374631: isprime: (0x400536) a=7
isprime-21965 [001] d... 199755.374637: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374637: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374644: isprime: (0x400536) a=13
isprime-21965 [001] d... 199755.374650: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374650: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
isprime-21965 [001] d... 199755.374657: isprime: (0x400536) a=17
isprime-21965 [001] d... 199755.374663: <stack trace>
=> exit_to_usermode_loop
=> prepare_exit_to_usermode
=> retint_user
isprime-21965 [001] d... 199755.374664: <user stack trace>
=> <0000000000400536>
=> <00007f6a29883fe0>
[root@zoo tracing]#
Tried with 'perf record' to get callchains, but:
[root@zoo ~]# perf record --call-graph dwarf -e probe_isprime:* ~acme/isprime
Error:
The sys_perf_event_open() syscall returned with 4 (Interrupted system call) for event (probe_isprime:isprime).
/bin/dmesg may provide additional information.
No CONFIG_PERF_EVENTS=y kernel support configured?
[root@zoo ~]# perf record -e probe_isprime:isprime ~acme/isprime
Error:
The sys_perf_event_open() syscall returned with 4 (Interrupted system call) for event (probe_isprime:isprime).
/bin/dmesg may provide additional information.
No CONFIG_PERF_EVENTS=y kernel support configured?
[root@zoo ~]#
Doesn't work with or without callchains :-\
Ah, probably that thing was left enabled by the ftrace session?
[root@zoo tracing]# cat events/probe_isprime/enable
1
[root@zoo tracing]# echo 0 > events/probe_isprime/enable
[root@zoo tracing]#
Lets see with it disabled:
[root@zoo ~]# perf record --call-graph dwarf -e probe_isprime:* ~acme/isprime
2 is prime
3 is prime
4 is not prime
5 is prime
6 is not prime
7 is prime
13 is prime
17 is prime
19 is prime
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.090 MB perf.data (9 samples) ]
[root@zoo ~]#
Yeah, that is something else to fix:
The sys_perf_event_open() syscall returned with 4 (Interrupted system call) for event (probe_isprime:isprime).
Is too cryptic for that :-)
Anyway, back to the perf record with callchains:
[root@zoo ~]# perf report --stdio --no-child
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 9 of event 'probe_isprime:isprime'
# Event count (approx.): 9
#
# Overhead Command Shared Object Symbol
# ........ ....... ............. ...........
#
100.00% isprime isprime [.] isprime
|
---isprime
main
__libc_start_main
_start
#
# (For a higher level overview, try: perf report --sort comm,dso)
#
[root@zoo ~]#
See below the output of the above call in verbose mode, should have the
addresses you asked to resolve using addr2line:
registering plugin: /root/.traceevent/plugins/plugin_function.so
registering plugin: /root/.traceevent/plugins/plugin_mac80211.so
registering plugin: /root/.traceevent/plugins/plugin_scsi.so
registering plugin: /root/.traceevent/plugins/plugin_hrtimer.so
registering plugin: /root/.traceevent/plugins/plugin_sched_switch.so
registering plugin: /root/.traceevent/plugins/plugin_cfg80211.so
registering plugin: /root/.traceevent/plugins/plugin_kmem.so
registering plugin: /root/.traceevent/plugins/plugin_kvm.so
registering plugin: /root/.traceevent/plugins/plugin_xen.so
registering plugin: /root/.traceevent/plugins/plugin_jbd2.so
build id event received for /home/acme/isprime: 597554d0e35bcaf7f1b09a205456baf9fbbadc4a
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: find_proc_info dso /home/acme/isprime
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: find_proc_info dso /home/acme/isprime
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: find_proc_info dso /usr/lib64/libc-2.20.so
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: find_proc_info dso /home/acme/isprime
Looking at the vmlinux_path (7 entries long)
Using /lib/modules/4.3.0+/build/vmlinux for symbols
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
unwind: reg 16, val 400536
unwind: reg 7, val 7ffc4f77b648
unwind: access_mem addr 0x7ffc4f77b648 val 4005ea, offset 0
unwind: reg 6, val 7ffc4f77b690
unwind: access_mem addr 0x7ffc4f77b698 val 7f7fe7a0cfe0, offset 80
unwind: access_mem addr 0x7ffc4f77b758 val 400469, offset 272
unwind: isprime:ip = 0x400536 (0x536)
unwind: main:ip = 0x4005ea (0x5ea)
unwind: __libc_start_main:ip = 0x7f7fe7a0cfe0 (0x1ffe0)
unwind: _start:ip = 0x400469 (0x469)
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 9 of event 'probe_isprime:isprime'
# Event count (approx.): 9
#
# Overhead Command Shared Object Symbol
# ........ ....... .................. ................................
#
100.00% isprime /home/acme/isprime 0x536 B [.] isprime
|
---isprime
main
__libc_start_main
_start
#
# (For a higher level overview, try: perf report --sort comm,dso)
#
prev parent reply other threads:[~2015-11-25 2:24 UTC|newest]
Thread overview: 16+ messages / expand[flat|nested] mbox.gz Atom feed top
2015-11-24 11:18 bogus values of variables in userspace probes Michael Petlan
2015-11-24 14:54 ` Arnaldo Carvalho de Melo
2015-11-24 16:13 ` Arnaldo Carvalho de Melo
2015-11-25 6:32 ` 平松雅巳 / HIRAMATU，MASAMI
2015-11-25 10:34 ` [BUGFIX PATCH perf/core ] perf probe: Fix to free temporal Dwarf_Frame correctly Masami Hiramatsu
2015-11-24 15:08 ` bogus values of variables in userspace probes Arnaldo Carvalho de Melo
2015-11-24 18:30 ` Michael Petlan
2015-11-24 19:16 ` Arnaldo Carvalho de Melo
2015-11-25 13:25 ` Michael Petlan
2015-11-25 13:33 ` Jiri Olsa
2015-11-25 14:43 ` perftool-testsuite was: " Arnaldo Carvalho de Melo
2015-11-25 15:58 ` Michael Petlan
2015-11-25 19:27 ` Arnaldo Carvalho de Melo
2015-11-25 15:07 ` 平松雅巳 / HIRAMATU，MASAMI
2015-11-25 1:03 ` 平松雅巳 / HIRAMATU，MASAMI
2015-11-25 2:24 ` Arnaldo Carvalho de Melo [this message]
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20151125022444.GN18140@kernel.org \
--to=acme@kernel.org \
--cc=dsahern@gmail.com \
--cc=jolsa@kernel.org \
--cc=linux-perf-users@vger.kernel.org \
--cc=masami.hiramatsu.pt@hitachi.com \
--cc=mingo@kernel.org \
--cc=mpetlan@redhat.com \
--cc=wangnan0@huawei.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.