Re: operf jit problem. No anon samples?

I don't think that was the problem. Just in case it was involved I tried
changing the event count to 5000000. That reduced the sample count but the
problem of missing anon samples was just the same. There was one other
thing that worried me. Most of my testing was on a VM (VMware Player 6.0.3)
which, although it makes the performance counters available, isn't perfect.
However operf works just fine on it with  non Jit applications.

To eliminate the VM  complication I built llvm and oprofile on an AMD
piledriver, running Ubuntu 14.04 on bare metal. Changed the count to
1000000.
Same problem:
dad@piled:/media/dad/work$ /usr/local/bin/operf -Vdebug -e
CPU_CLK_UNHALTED:1000000 lli -debug-only="oprofile-jit-event-listener"
loopy.ll
Using samples dir /media/dad/work/oprofile_data/samples
Kernel profiling is not possible with current system config.
Set /proc/sys/kernel/kptr_restrict to 0 to collect kernel samples.
Exec args are: lli -debug-only=oprofile-jit-event-listener loopy.ll
telling child to start app
app 17038 is running
parent says start app /usr/local/bin/lli
Forking read pid
going into waitpid on profiled app 17038
operf: Profiler started
Successfully read header info for sample data
Converting operf data to oprofile sample data format
sample type is 43
Connected to OProfile agent.
Mapping 0x7f02be7ef014 to loopy.c:13
Mapping 0x7f02be7ef01f to loopy.c:13
Mapping 0x7f02be7ef032 to loopy.c:13
Mapping 0x7f02be7ef054 to loopy.c:14
Mapping 0x7f02be7ef079 to loopy.c:9
Mapping 0x7f02be7ef082 to loopy.c:9
Mapping 0x7f02be7ef08e to loopy.c:10
Mapping 0x7f02be7ef0a1 to loopy.c:10
Mapping 0x7f02be7ef0b8 to loopy.c:10
Mapping 0x7f02be7ef0d9 to loopy.c:5
Mapping 0x7f02be7ef0e2 to loopy.c:5
Mapping 0x7f02be7ef0ee to loopy.c:6
Mapping 0x7f02be7ef101 to loopy.c:6
Mapping 0x7f02be7ef118 to loopy.c:6
Mapping 0x7f02be7ef139 to loopy.c:7
Mapping 0x7f02be7ef142 to loopy.c:7
Mapping 0x7f02be7ef14e to loopy.c:8
Mapping 0x7f02be7ef161 to loopy.c:8
Mapping 0x7f02be7ef178 to loopy.c:8
fib(43) == 701408733
profiled app ended normally.
operf recording finished.
Total bytes recorded from perf events: 628968
operf-record process returned OK
operf_read: Total bytes received from operf_record process: 628736
Calling _do_jitdump_convert
start time/end time is 1413476116/1413476120
opjitconv: Ending with rc = 2. This code is usually OK, but can be useful
for debugging purposes.
JIT dump processing complete.
operf-read process returned OK

Profiling done.
dad@piled:/media/dad/work$ opreport
Using /media/dad/work/oprofile_data/samples/ for samples directory.
CPU: AMD64 family15h, speed 4000 MHz (estimated)
Counted CPU_CLK_UNHALTED events (CPU Clocks not Halted) with a unit mask of
0x00 (No unit mask) count 1000000
CPU_CLK_UNHALT...|
  samples|      %|
------------------
    19536 100.000 lli
    CPU_CLK_UNHALT...|
      samples|      %|
    ------------------
        19339 98.9916 ld-2.19.so
           60  0.3071 no-vmlinux
           48  0.2457 libLLVMCore.so
           37  0.1894 libLLVMCodeGen.so
           15  0.0768 libLLVMSelectionDAG.so
           10  0.0512 libLLVMSupport.so
            6  0.0307 libLLVMX86CodeGen.so
            5  0.0256 libc-2.19.so
            5  0.0256 libpthread-2.19.so
            3  0.0154 libstdc++.so.6.0.20
            2  0.0102 lli
            2  0.0102 libLLVMAsmParser.so
            1  0.0051 libLLVMAnalysis.so
            ...

Here's the oprofile results for the non Jit version of the very same
program - its a little bit faster as there was no jit compilation, but
otherwise unremakable:

dad@piled:/media/dad/work$ /usr/local/bin/operf -Vdebug -e
CPU_CLK_UNHALTED:1000000 ./loopy
Using samples dir /media/dad/work/oprofile_data/samples
Kernel profiling is not possible with current system config.
Set /proc/sys/kernel/kptr_restrict to 0 to collect kernel samples.
operf: Profiler startedExec args are: loopy

telling child to start app
parent says start app /media/dad/work/loopy
app 17065 is running
Forking read pid
going into waitpid on profiled app 17065
Successfully read header info for sample data
Converting operf data to oprofile sample data format
sample type is 43
fib(43) == 701408733
profiled app ended normally.
operf recording finished.
Total bytes recorded from perf events: 567072
operf-record process returned OK
operf_read: Total bytes received from operf_record process: 566840
Calling _do_jitdump_convert
start time/end time is 1413476432/1413476437
JIT dump processing complete.
operf-read process returned OK

Profiling done.

dad@piled:/media/dad/work$ opreport -l ./loopy
Using /media/dad/work/oprofile_data/samples/ for samples directory.
CPU: AMD64 family15h, speed 4000 MHz (estimated)
Counted CPU_CLK_UNHALTED events (CPU Clocks not Halted) with a unit mask of
0x00 (No unit mask) count 1000000
samples  %        image name               symbol name
11448    64.6780  loopy                    fib_left
6240     35.2542  loopy                    fib_right
12        0.0678  no-vmlinux               /no-vmlinux

So it looks like oprofile is working fine in non Jit mode.

Other possibilities?

Is there an oprofile test for the jit functionality I can try?

Oprofile seems to be getting the events OK, and counting them, but just not
saving them as anon samples when they are outside the DSOs.

Has anyone else on the list been  using oprofile with a non-Java jit
configuration?




On Wed, Oct 15, 2014 at 6:53 PM, Maynard Johnson <[email protected]>
wrote:

> On 10/15/2014 04:25 PM, Maurice Marks wrote:
> > I'm trying to profile  non Java Jit code  (using llvm's built in
> oprofile interface) on Ubuntu 14.04 using operf.
> > I built the latest git version of oprofile just to be sure I'm up to
> date.
> >
> > What I see is that there are lots of jit samples counted, but rather
> than being attributed to anon or to (hopefully) <pid>.jo they are
> > counted against one of the .so files.
> >
> > Like this:
> > CPU: Intel Haswell microarchitecture, speed 3498 MHz (estimated)
> > Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a
> unit mask of 0x00 (No unit mask) count 100000
> > CPU_CLK_UNHALT...|
> >   samples|      %|
> > ------------------
> >     20792 100.000 lli
> >     CPU_CLK_UNHALT...|
> >       samples|      %|
> >     ------------------
> >         20634 99.2401 ld-2.19.so <http://ld-2.19.so>
> >            86  0.4136 no-vmlinux
> >            27  0.1299 libLLVMCore.so
> >            16  0.0770 libLLVMCodeGen.so
> >            10  0.0481 libLLVMSelectionDAG.so
> >             4  0.0192 libLLVMSupport.so
> >             3  0.0144 libLLVMJIT.so
> >             3  0.0144 libLLVMX86Desc.so
> >             2  0.0096 libLLVMScalarOpts.so
> >             2  0.0096 libLLVMX86CodeGen.so
> >             1  0.0048 lli
> >             1  0.0048 libc-2.19.so <http://libc-2.19.so>
> >             1  0.0048 libpthread-2.19.so <http://libpthread-2.19.so>
> >             1  0.0048 libLLVMAnalysis.so
> >             1  0.0048 libLLVMAsmParser.so
> >
> > ~99% of the samples are actually in the Jit'd code, not in ld-2.19.so <
> http://ld-2.19.so>.
> >
> > Debugging I see that the opjitagent calls are being made correctly for
> the jit'd routines, and jitdump files are being generated.
> > And opjitconv runs and deletes the jitdump files at the end. But because
> there are no "anon" samples
> > nothing is reported.
> >
> > With-Vdebug in operf I see:
> > ....
> > profiled app ended normally.
> > operf recording finished.
> > Total bytes recorded from perf events: 841464
> > operf-record process returned OK
> > * * * * WARNING: Profiling rate was throttled back by the kernel * * * *
> > The number of samples actually recorded is less than expected, but is
> > probably still statistically valid.  Decreasing the sampling rate is the
> > best option if you want to avoid throttling.
> > operf_read: Total bytes received from operf_record process: 841280
> > Calling _do_jitdump_convert
> > start time/end time is 1413408126/1413408137
> > opjitconv: Ending with rc = 2. This code is usually OK, but can be
> useful for debugging purposes.
> > JIT dump processing complete.
> > operf-read process returned OK
> >
> >
> > I'm probably doing something wrong. But I'm not sure what.
> > Any ideas?
> Hi, Maurice.  Cool, I didn't know that LLVM had an interface to oprofile's
> JIT support. Googling, I see that this have been around for a while.  So,
> the first question is have you ever gotten this to work (yourself) in the
> past?  If so, then please provide details (distro, oprofile version,
> processor type, etc.).
>
> What really jumps out at me is that according to the opjitconv start
> time/end time debug message above, your profile run was 11 seconds, but you
> only got a total of 20792, while sampling at a rate of one sample per
> 100,000 CPU_CLK_UNHALTED events! I've never seen the kernel do throttling
> like that. There may be a kernel issue there, but the first thing I would
> try is back off on the sampling rate ... try something like one sample
> every 500,000 CPU_CLK_UNHALTED events.
>
> -Maynard
> >
> >
> >
> >
> >
> >
> ------------------------------------------------------------------------------
> > Comprehensive Server Monitoring with Site24x7.
> > Monitor 10 servers for $9/Month.
> > Get alerted through email, SMS, voice calls or mobile push notifications.
> > Take corrective actions from your mobile device.
> > http://p.sf.net/sfu/Zoho
> >
> >
> >
> > _______________________________________________
> > oprofile-list mailing list
> > [email protected]
> > https://lists.sourceforge.net/lists/listinfo/oprofile-list
> >
>
>


-- 
Not sent from my Blackberry, Raspberry or Gooseberry!

------------------------------------------------------------------------------
Comprehensive Server Monitoring with Site24x7.
Monitor 10 servers for $9/Month.
Get alerted through email, SMS, voice calls or mobile push notifications.
Take corrective actions from your mobile device.
http://p.sf.net/sfu/Zoho

_______________________________________________
oprofile-list mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/oprofile-list