bogus values of variables in userspace probes

Hi *,

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

But if you look into the source, you can see that the function isprime() is called with the following arguments:

int numbers[] = { 2, 3, 4, 5, 6, 7, 13, 17, 19 };

So the first and last ones are omitted, there are some bogus numbers instead of them and all that is shifted somehow.

Note that when I probe for %ax register it looks correct.

The version of kernel/perf is 4.3.0. The architecture is x86_64. Am I missing something or is it a bug?

Thank you!
Michael

#include <stdlib.h>
#include <stdio.h>

int isprime(int a)

{
	int i;
	if(a <= 1)
		return 0;
	for(i = 2; i <= a / 2; i++)
		if(!(a % i))
			return 0;
	return 1;
}

int main(int argc, char **argv)

{
	int numbers[] = { 2, 3, 4, 5, 6, 7, 13, 17, 19 };
	int i;

	for(i = 0; i < 9; i++)
	{
		printf("%i %s prime\n", numbers[i], (isprime(numbers[i]))? "is" : "is not");
	}

	return 0;
}

Em Tue, Nov 24, 2015 at 12:18:22PM +0100, Michael Petlan escreveu:

Checking this here, but as non root I get:

[acme@zoo ~]$ gcc -O0 -g -o isprime isprime.c
[acme@zoo ~]$ perf probe -x ./isprime --add 'isprime a' Mapping for the register number 4113 missing on this architecture. Sorry, we don't support this variable location yet.
Error: Failed to add events.
[acme@zoo ~]$

Masami, can you take a look at this?

More info:

[acme@zoo ~]$ cat /etc/fedora-release
Fedora release 21 (Twenty One)
[acme@zoo ~]$ uname -a
Linux zoo 4.3.0+ #1 SMP Thu Nov 12 11:29:01 BRT 2015 x86_64 x86_64 x86_64 GNU/Linux

From readelf -wi, the isprime.c is the same as the one in Michael's original report.

Contents of the .debug_info section:

Compilation Unit @ offset 0x0:
Length: 0x12a (32-bit)
Version: 4
Abbrev Offset: 0x0
Pointer Size: 8
<0><b>: Abbrev Number: 1 (DW_TAG_compile_unit)
<c> DW_AT_producer : (indirect string, offset: 0x7a): GNU C 4.9.2 20150212 (Red Hat 4.9.2-6) -mtune=generic -march=x86-64 -g -O0
<10> DW_AT_language : 1 (ANSI C)
<SNIP>
<1><87>: Abbrev Number: 5 (DW_TAG_subprogram)

    <88>   DW_AT_external    : 1        
    <88>   DW_AT_name        : (indirect string, offset: 0xe): isprime  
    <8c>   DW_AT_decl_file   : 1        
    <8d>   DW_AT_decl_line   : 4        
    <8e>   DW_AT_prototyped  : 1        
    <8e>   DW_AT_type        : <0x34>   
    <92>   DW_AT_low_pc      : 0x400536 
    <9a>   DW_AT_high_pc     : 0x4d     
    <a2>   DW_AT_frame_base  : 1 byte block: 9c         (DW_OP_call_frame_cfa)
    <a4>   DW_AT_GNU_all_call_sites: 1  
    <a4>   DW_AT_sibling     : <0xc1>   
 <2><a8>: Abbrev Number: 6 (DW_TAG_formal_parameter)
    <a9>   DW_AT_name        : a        
    <ab>   DW_AT_decl_file   : 1        
    <ac>   DW_AT_decl_line   : 4        
    <ad>   DW_AT_type        : <0x34>   
    <b1>   DW_AT_location    : 2 byte block: 91 5c      (DW_OP_fbreg: -36)

<SNIP>

Em Tue, Nov 24, 2015 at 11:54:24AM -0300, Arnaldo Carvalho de Melo escreveu:

Bisected it down to:

[acme@zoo linux]$ git bisect good 05c8d802fa52ef17dbcce21c38b72b4a313eb036 is the first bad commit commit 05c8d802fa52ef17dbcce21c38b72b4a313eb036

Author: Masami Hiramatsu <[email protected]>
Date:   Wed Nov 18 15:40:12 2015 +0900

perf probe: Fix to free temporal Dwarf_Frame

Since dwarf_cfi_addrframe returns malloc'd Dwarf_Frame object, it has to be freed after it is used.

:040000 040000 6438a0b3a7817ecbfc61eb00af9c62e54c405bcb 62ca7f05ff3ec7202d4c47f9cd2e2cb183060725 M tools
[acme@zoo linux]$

If I just do a:

[acme@zoo linux]$ git revert 05c8d802fa52ef17dbcce21c38b72b4a313eb036 [perf/core 15ef27d95f5c] Revert "perf probe: Fix to free temporal Dwarf_Frame"

 1 file changed, 3 insertions(+), 6 deletions(-)

[acme@zoo linux]$

It works again, i.e. it goes from:

[acme@zoo linux]$ perf probe -x ~/isprime --add 'isprime a' Mapping for the register number 4113 missing on this architecture. Sorry, we don't support this variable location yet.
Error: Failed to add events.
[acme@zoo linux]$

To, after the revert:

[acme@zoo linux]$ perf probe -x ~/isprime --add 'isprime a' Failed to open uprobe_events: Permission denied
Error: Failed to add events.

And, as root:

[root@zoo acme]# perf probe -x ./isprime --add 'isprime a' Added new event:
probe_isprime:isprime (on isprime in /home/acme/isprime with a)

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

perf record -e probe_isprime:isprime -aR sleep 1

[root@zoo acme]# perf record -e probe_isprime:isprime ./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.018 MB perf.data (9 samples) ] [root@zoo acme]#

[root@zoo acme]# perf script

         isprime 27687 [003] 184735.650141: probe_isprime:isprime: (400536) a=0
         isprime 27687 [003] 184735.650204: probe_isprime:isprime: (400536) a=32570
         isprime 27687 [003] 184735.650209: probe_isprime:isprime: (400536) a=3
         isprime 27687 [003] 184735.650212: probe_isprime:isprime: (400536) a=4
         isprime 27687 [003] 184735.650215: probe_isprime:isprime: (400536) a=5
         isprime 27687 [003] 184735.650218: probe_isprime:isprime: (400536) a=6
         isprime 27687 [003] 184735.650222: probe_isprime:isprime: (400536) a=7
         isprime 27687 [003] 184735.650225: probe_isprime:isprime: (400536) a=13
         isprime 27687 [003] 184735.650229: probe_isprime:isprime: (400536) a=17

[root@zoo acme]#

I.e. bogus values for some of the samples, as Michael reported.

Ah, using 'perf trace', or 'trace' to type less, we can combine 'record' + 'script', only to end at the same bogus values for some of the captured 'a' variable contents:

[root@zoo acme]# trace --no-sys --ev probe_isprime:isprime ./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

     0.264 probe_isprime:isprime:(400536) a=0)
     0.332 probe_isprime:isprime:(400536) a=32562)
     0.363 probe_isprime:isprime:(400536) a=3)
     0.395 probe_isprime:isprime:(400536) a=4)
     0.429 probe_isprime:isprime:(400536) a=5)
     0.463 probe_isprime:isprime:(400536) a=6)
     0.497 probe_isprime:isprime:(400536) a=7)
     0.532 probe_isprime:isprime:(400536) a=13)
     0.566 probe_isprime:isprime:(400536) a=17)

[root@zoo acme]#

- Arnaldo

Ah, OK. I miss understood. The dwarf_frame_cfa can return a part of Dwarf_Frame(afaics libdw source code), so it should be freed right after the Dwarf_Op (pf->fb_ops) is used.

OK, I'll fix that.

Thanks!

The commit 05c8d802fa52 ("perf probe: Fix to free temporal Dwarf_Frame") tried to fix the memory leak of Dwarf_Frame, but it released the frame at wrong point. Since the dwarf_frame_cfa(frame, &pf->fb_ops, &nops) can return an address inside the frame data structure to pf->fb_ops, we can not release the frame before using pf->fb_ops.

This reverts the commit and releases the frame afterwards (right before returning from call_probe_finder) correctly.

---
 tools/perf/util/probe-finder.c |   13 ++++++-------
 1 file changed, 6 insertions(+), 7 deletions(-)

index 1cab05a..2be10fb 100644
@@ -654,6 +654,7 @@ static int convert_to_trace_point(Dwarf_Die *sp_die, Dwfl_Module *mod,
 static int call_probe_finder(Dwarf_Die *sc_die, struct probe_finder *pf)
 {
 	Dwarf_Attribute fb_attr;
+	Dwarf_Frame *frame = NULL;
 	size_t nops;
 	int ret;
 

@@ -683,26 +684,24 @@ static int call_probe_finder(Dwarf_Die *sc_die, struct probe_finder *pf)
 	ret = dwarf_getlocation_addr(&fb_attr, pf->addr, &pf->fb_ops, &nops, 1);
 	if (ret <= 0 || nops == 0) {
 		pf->fb_ops = NULL;
-		ret = 0;
 #if _ELFUTILS_PREREQ(0, 142)
 	} else if (nops == 1 && pf->fb_ops[0].atom == DW_OP_call_frame_cfa &&
 		   pf->cfi != NULL) {
-		Dwarf_Frame *frame = NULL;
 		if (dwarf_cfi_addrframe(pf->cfi, pf->addr, &frame) != 0 ||
 		    dwarf_frame_cfa(frame, &pf->fb_ops, &nops) != 0) {
 			pr_warning("Failed to get call frame on 0x%jx\n",
 				   (uintmax_t)pf->addr);
-			ret = -ENOENT;
+			free(frame);
+			return -ENOENT;
 		}
-		free(frame);
 #endif
 	}
 
 	/* Call finder's callback handler */
-	if (ret >= 0)
-		ret = pf->callback(sc_die, pf);
+	ret = pf->callback(sc_die, pf);
 
-	/* *pf->fb_ops will be cached in libdw. Don't free it. */
+	/* Since *pf->fb_ops can be a part of frame. we should free it here. */
+	free(frame);
 	pf->fb_ops = NULL;
 
 	return ret;

Em Tue, Nov 24, 2015 at 12:18:22PM +0100, Michael Petlan escreveu:

I'm now trying to bisect that register error I found while trying to reproduce the problem reported above, but please consider writing a 'perf test' entry that does exactly what you did, i.e. have a simple program that you build with a known set of compile flags, then run it using perf probe to catch a specific function, its argument, and then check that the values it produces are the ones expected.

We would catch bugs in 'perf probe', the DWARF code, etc, much more quickly with something like that in place. :-)

- Arnaldo

Hi Arnaldo,

thanks for investigating the issue. I do not use fedora kernel, I use what I build from git, but of course I am some versions back. So I use 4.3.0 and 4.3.0-rc5 and both do the same thing.

I have met this when writing new tests for perf-probe into the testsuite I had been speaking about some time ago [1]. But if needed, I may add it as a perf-test entry as you wish.

Michael

Em Tue, Nov 24, 2015 at 07:30:39PM +0100, Michael Petlan escreveu:

I ended up having to investigate that other issue, and now I have to do something else, but hopefully Masami will fix both issues, the one I bisected and the one you reported.

Right, I also use custom kernels, but reboot with RHEL or fedora kernels from time to time to investigate issues like this.

Please :-)

- Arnaldo

Hi,

after a short discussion with Jiri Olsa I think that perf-test entry is not an ideal way to add a testcase such as this one. While perf-test aims on testing internal functions, here you need to use multiple tools in order to reproduce the issue:

1) build a custom C example
2) add a userspace probe in the example
3) record some perf.data of it
4) analyze the perf.data by perf script

So in order to have this testcase in perf.test we'd need to call all the mentioned functionality within a C function. That's why I think that better approach is to use the shell based tests that I am collecting in my suite for now:

# for running the particular testcase for this issue you just need to:
git clone https://github.com/rfmvh/perftool-testsuite.git
cd perftool-testsuite/base_probe
./setup.sh
./test_advanced.sh

The overall approach of that testsuite is to test the tool as it is. So both approaches are necessary; both testing of the internal functions by perf-test and testing the tool as such from the outside by the suite. I am not against extending perf-test set, but I don't think this is the right case for it.

Regards,
Michael

+1 ;-)

also I remember discussion about having your test suite ported somewhere over perf sources.. is this still a plan?

thanks,
jirka

Em Wed, Nov 25, 2015 at 02:33:43PM +0100, Jiri Olsa escreveu:

Looking at it, but how do you envision the workflow when/if this is merged into the kernel?

Nowadays, I have to do:

make -C tools/perf build-test

To do build-tests, and also have to run:

perf test

Would this be a 3td thing I'd have to do? Or would it be hooked into 'perf test' somehow? It doesn't have to be written in C, but if it could be called without us having to add a 3rd step to this process...

What I saw from a very quick walkthru starting from the 'base_probe' one:

[root@zoo base_probe]# ./test_advanced.sh
-- [ PASS ] -- perf_probe :: test_advanced :: function argument probing :: add
-- [ PASS ] -- perf_probe :: test_advanced :: function argument probing :: record Pattern not found in the proper order: a=2
-- [ FAIL ] -- perf_probe :: test_advanced :: function argument probing :: script (output regexp parsing) -- [ PASS ] -- perf_probe :: test_advanced :: function retval probing :: add
-- [ PASS ] -- perf_probe :: test_advanced :: function retval probing :: record
-- [ PASS ] -- perf_probe :: test_advanced :: function retval probing :: script
## [ FAIL ] ## perf_probe :: test_advanced SUMMARY :: 1 failures found
[root@zoo base_probe]#

With 'perf test'

[root@zoo ~]# perf test bpf llvm

35: Test LLVM searching and compiling                        :
35.1: Basic BPF llvm compiling test                          : Ok
35.2: Test kbuild searching                                  : Ok
35.3: Compile source for BPF prologue generation test        : Ok
37: Test BPF filter                                          :
37.1: Test basic BPF filtering                               : Ok
37.2: Test BPF prologue generation                           : Ok

[root@zoo ~]#

So just FAIL, Skip or Ok, and if I ask for -v, then it will emit more information.

I think that we should add your suite to be called from 'perf test', and it should follow the same style as 'perf test', see the BPF and LLVM test? they have subtests, perhaps this is the way for this test suite to be integrated.

How can I run all the tests in perftool-testsuite? Checking...

I think there's no need to have any 3rd thing to do... I would vote for calling from the perf's Makefile after building it.

Bus same as perf-test, the testsuite does not 100% pass. Some better skipping mechanism could be useful. But anyway, it is designed to be parametrized, so it can be run in some "quick/smoke testing" mode and in case of a need, in a more thoroughful mode. That depends on the configs in the common/parametrization.sh file.

Should the testsuite 100% pass in a basic mode?

Now it prints the PASS/FAIL/SKIP, and in case of FAIL some minimalistic footprint of the failure, so I can see whether it is just the old known thing or something different. The detailed logs are generated with that, but they are usually cleaned up in the cleanup.sh scripts.

I am still thinking about an ideal way to report failures, since I keep in mind another goal: I would like to have the path from "looking at the logs" and "reproducing the thing manually in shell" as short and straightforward as possible.

But using some -v is generally a good idea. I'll try to integrate that concept too.

Basically you need to run the ./test_driver.sh from the top directory. But nowadays all the subtests (base_SOMETHING) that are run are listed in the test_driver.sh per architecture. That concept could (and probably also should) be reworked a bit, but now it allows me hot-enabling and disabling groups of tests on various archs.

Em Wed, Nov 25, 2015 at 04:58:17PM +0100, Michael Petlan escreveu:

That doesn't work, sometimes patches are just cosmetic, sometimes they require root priviledges, sometimes it requires some preparation, like setting some tunable in /proc/sys/kernel/perf_event_paranoid or moving around the vmlinux file so that it uses kallsyms, or, or, or.

Also the granularity is more like before pushing upstream, or automating the tests using a script that runs the tests changeset by changeset in multiple distros before pushing, etc.

I.e. like 'make -C tools/perf build-test' and 'perf test' do now.

Well, it better pass 100% for things it _can_ test, if something is not available (root perms, vmlinux file, hardware capability (testing Intel PT on older CPUs), etc) that prevents the test from being performed, then it just prints Skip and doesn't consider that an error.

I think so. And by basic more I mean the mode that it is run when one calls:

perf test command-line

Picking "command-line" to mean what you have now in 'perftool-testsuite'.

Any other option will probably not be tested that frequently by anybody else than you, perhaps me and a few others.

I really think that the answer to 'Hey, how can I make sure the perf tools are working? How do I test it?" should be: "run 'perf test'".

Then it becomes muscle memory and one doesn't have to remember any other name or file to config, etc.

Re-reading the above, generally we try to remove redundant stuff, like all that "perf_probe" column, ditto for the "test_advanced", etc.

Reduces eyestrain and, to say something funny I saw on FB about mass surveilance, "removes hay so that we can find needles" :-)

I know, that is what I am saying, we have one tool to test the perf tools and it communicates using a set of messages and has a semantic for when to tell more than "Ok/FAIl/Skip", while your test suite does the same thing, but with slight formatting variations, what I am suggesting is to adopt the one in 'perf test' so that it becomes consistent and can be plugged directly into 'perf test'.

Of course one could run it as of today, directly, in a standalone fashion, be it by going to its source directory and running that test_drive.sh (or whatever other name it ends up having) or from 'perf test', by using something like:

[acme@zoo linux]$ perf test clock
20: Test software clock events have valid period values : Ok

See? Just one test was run.

If it is run by spanwing a shell from another shell or from 'perf test', that shouldn't matter, right?

Being able to just do 'perf test' and all tests, be it ones written in C and part of tools/perf/tests/ or one written in whatever script language, driven by your test suite, is the goal.

Thanks.

Thanks for the explanations, I had already found the README files and ran the whole suite using that test_driver.sh file (at first I thought, what driver is this testing? huh?) but then reading the README I figured it was the "driver" of tests :-)

- Arnaldo

From: Michael Petlan [mailto:[email protected]]

Yeah, I agreed, and perf-probe definitely needs it :) I hope that this is included into the kernel tree so that it can be synchronously evolving with perf itself.

Thanks!

From: Michael Petlan [mailto:[email protected]]

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 ?

Thank you,

Em Wed, Nov 25, 2015 at 01:03:47AM +0000, 平松雅巳 / HIRAMATU，MASAMI escreveu:

[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) #