bogus values of variables in userspace probes

bogus values of variables in userspace probes

[Michael Petlan]

[-- Attachment #1: Type: text/plain, Size: 1419 bytes --]

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


[-- Attachment #2: dummy.c --]
[-- Type: text/x-csrc, Size: 381 bytes --]

#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;
}

Re: bogus values of variables in userspace probes

[Arnaldo Carvalho de Melo]

Em Tue, Nov 24, 2015 at 12:18:22PM +0100, Michael Petlan escreveu:
> 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

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>

Re: bogus values of variables in userspace probes

[Arnaldo Carvalho de Melo]

Em Tue, Nov 24, 2015 at 11:54:24AM -0300, Arnaldo Carvalho de Melo escreveu:
> 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
 
> 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 ~]$ 

Bisected it down to:

[acme@zoo linux]$ git bisect good 
05c8d802fa52ef17dbcce21c38b72b4a313eb036 is the first bad commit
commit 05c8d802fa52ef17dbcce21c38b72b4a313eb036
Author: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
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.
    
    Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
    Cc: Adrian Hunter <adrian.hunter@intel.com>
    Cc: Jiri Olsa <jolsa@redhat.com>
    Cc: Namhyung Kim <namhyung@kernel.org>
    Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
    Link: http://lkml.kernel.org/r/20151118064011.30709.65674.stgit@localhost.localdomain
    Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

: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

RE: Re: bogus values of variables in userspace probes

[平松雅巳 / HIRAMATU，MASAMI]

>From: Arnaldo Carvalho de Melo [mailto:acme@kernel.org]

>Em Tue, Nov 24, 2015 at 11:54:24AM -0300, Arnaldo Carvalho de Melo escreveu:
>> 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
>
>> 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 ~]$
>
>Bisected it down to:
>
>[acme@zoo linux]$ git bisect good
>05c8d802fa52ef17dbcce21c38b72b4a313eb036 is the first bad commit
>commit 05c8d802fa52ef17dbcce21c38b72b4a313eb036
>Author: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
>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.
>
>    Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
>    Cc: Adrian Hunter <adrian.hunter@intel.com>
>    Cc: Jiri Olsa <jolsa@redhat.com>
>    Cc: Namhyung Kim <namhyung@kernel.org>
>    Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
>    Link: http://lkml.kernel.org/r/20151118064011.30709.65674.stgit@localhost.localdomain
>    Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
>

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!

[BUGFIX PATCH perf/core ] perf probe: Fix to free temporal Dwarf_Frame correctly

[Masami Hiramatsu]

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.

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Reported-by: Arnaldo Carvalho de Melo <acme@kernel.org>
Reported-by: Michael Petlan <mpetlan@redhat.com>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: David Ahern <dsahern@gmail.com>
Cc: Wang Nan <wangnan0@huawei.com>
---
 tools/perf/util/probe-finder.c |   13 ++++++-------
 1 file changed, 6 insertions(+), 7 deletions(-)

diff --git a/tools/perf/util/probe-finder.c b/tools/perf/util/probe-finder.c
index 1cab05a..2be10fb 100644
--- a/tools/perf/util/probe-finder.c
+++ b/tools/perf/util/probe-finder.c
@@ -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;

Re: bogus values of variables in userspace probes

[Arnaldo Carvalho de Melo]

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
> 
> 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?

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

Re: bogus values of variables in userspace probes

[Michael Petlan]

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
> > 
> > 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?
> 
> 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. :-)

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

> 
> - Arnaldo

Re: bogus values of variables in userspace probes

[Arnaldo Carvalho de Melo]

Em Tue, Nov 24, 2015 at 07:30:39PM +0100, Michael Petlan escreveu:
> 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
> > > 
> > > 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?
> > 
> > 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. :-)
 
> Hi Arnaldo,
 
> thanks for investigating the issue. I do not use fedora kernel, I use

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.

> 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.

Right, I also use custom kernels, but reboot with RHEL or fedora kernels
from time to time to investigate issues like this.
 
> 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.

Please :-)

- Arnaldo

Re: bogus values of variables in userspace probes

[Michael Petlan]

On Tue, 2015-11-24 at 16:16 -0300, Arnaldo Carvalho de Melo wrote:
>  
> > 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.
> 
> Please :-)
> 

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.

> - Arnaldo

Regards,
Michael

Re: bogus values of variables in userspace probes

[Jiri Olsa]

On Wed, Nov 25, 2015 at 02:25:43PM +0100, Michael Petlan wrote:
> On Tue, 2015-11-24 at 16:16 -0300, Arnaldo Carvalho de Melo wrote:
> >  
> > > 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.
> > 
> > Please :-)
> > 
> 
> 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.

+1 ;-)

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

thanks,
jirka

perftool-testsuite was: Re: bogus values of variables in userspace probes

[Arnaldo Carvalho de Melo]

Em Wed, Nov 25, 2015 at 02:33:43PM +0100, Jiri Olsa escreveu:
> On Wed, Nov 25, 2015 at 02:25:43PM +0100, Michael Petlan wrote:
> > On Tue, 2015-11-24 at 16:16 -0300, Arnaldo Carvalho de Melo wrote:
> > >  
> > > > 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.
> > > 
> > > Please :-)
> > > 
> > 
> > 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

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...

> > 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.
> 
> +1 ;-)
> 
> also I remember discussion about having your test suite
> ported somewhere over perf sources.. is this still a plan?
> 
> thanks,
> jirka

Re: perftool-testsuite was: Re: bogus values of variables in userspace probes

[Michael Petlan]

On Wed, 2015-11-25 at 11:43 -0300, Arnaldo Carvalho de Melo wrote:
> 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...

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?

> 
> 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.

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.

> 
> 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...
> 

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.

Re: perftool-testsuite was: Re: bogus values of variables in userspace probes

[Arnaldo Carvalho de Melo]

Em Wed, Nov 25, 2015 at 04:58:17PM +0100, Michael Petlan escreveu:
> On Wed, 2015-11-25 at 11:43 -0300, Arnaldo Carvalho de Melo wrote:
> > 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...

> 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.

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.
 
> Bus same as perf-test, the testsuite does not 100% pass. Some better

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.

> 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?

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.

> > 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]#

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" :-)

> > 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.
> 
> 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 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.
 
> 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.

Thanks.
 
> > 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...
 
> 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.

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

RE: Re: bogus values of variables in userspace probes

[平松雅巳 / HIRAMATU，MASAMI]

From: Michael Petlan [mailto:mpetlan@redhat.com]
>
>On Tue, 2015-11-24 at 16:16 -0300, Arnaldo Carvalho de Melo wrote:
>>
>> > 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.
>>
>> Please :-)
>>
>
>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.

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!

>
>> - Arnaldo
>
>Regards,
>Michael
>
>
>

RE: bogus values of variables in userspace probes

[平松雅巳 / HIRAMATU，MASAMI]

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 ?

Thank you,

>> >
>> > 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?
>>
>> 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. :-)
>
>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
>
>>
>> - Arnaldo
>

Re: bogus values of variables in userspace probes

[Arnaldo Carvalho de Melo]

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