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.


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

RE: Re: bogus values of variables in userspace probes

[平松雅巳 / HIRAMATU，MASAMI]

From: Michael Petlan [mailto:mpet...@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

[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




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

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

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

RE: bogus values of variables in userspace probes

[平松雅巳 / HIRAMATU，MASAMI]

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 ?

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 +, 平松雅巳 / 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: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374488: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374561: isprime: (0x400536) a=32618
 isprime-21965 [001] d... 199755.374567: 
 =G> exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374568: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374577: isprime: (0x400536) a=3
 isprime-21965 [001] d... 199755.374583: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374583: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374591: isprime: (0x400536) a=4
 isprime-21965 [001] d... 199755.374597: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374597: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374604: isprime: (0x400536) a=5
 isprime-21965 [001] d... 199755.374610: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374610: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374618: isprime: (0x400536) a=6
 isprime-21965 [001] d... 199755.374624: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374624: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374631: isprime: (0x400536) a=7
 isprime-21965 [001] d... 199755.374637: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374637: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374644: isprime: (0x400536) a=13
 isprime-21965 [001] d... 199755.374650: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374650: 
 =>  <00400536>
 =>  <7f6a29883fe0>
 isprime-21965 [001] d... 199755.374657: isprime: (0x400536) a=17
 isprime-21965 [001] d... 199755.374663: 
 => exit_to_usermode_loop
 => prepare_exit_to_usermode
 => retint_user
 isprime-21965 [001] d... 199755.374664: 
 =>  <00400536>
 =>  <7f6a29883fe0>
[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 

RE: Re: bogus values of variables in userspace probes

[平松雅巳 / HIRAMATU，MASAMI]

>From: Arnaldo Carvalho de Melo [mailto:a...@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 
>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 
>Cc: Adrian Hunter 
>Cc: Jiri Olsa 
>Cc: Namhyung Kim 
>Cc: Peter Zijlstra 
>Link: 
> http://lkml.kernel.org/r/20151118064011.30709.65674.stgit@localhost.localdomain
>Signed-off-by: Arnaldo Carvalho de Melo 
>

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

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


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

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

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>: Abbrev Number: 1 (DW_TAG_compile_unit)
   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)

 <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 
   DW_AT_frame_base  : 1 byte block: 9c (DW_OP_call_frame_cfa)
   DW_AT_GNU_all_call_sites: 1  
   DW_AT_sibling : <0xc1>   
 <2>: Abbrev Number: 6 (DW_TAG_formal_parameter)
   DW_AT_name: a
   DW_AT_decl_file   : 1
   DW_AT_decl_line   : 4
   DW_AT_type: <0x34>   
   DW_AT_location: 2 byte block: 91 5c  (DW_OP_fbreg: -36)

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

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