Em Wed, Nov 25, 2015 at 01:03:47AM +0000, 平松雅巳 / HIRAMATU，MASAMI escreveu:
> From: Michael Petlan [mailto:mpet...@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)
#
--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
