Re: operf jit problem. No anon samples?
Maynard Johnson <[email protected]>
| Newsgroups | gmane.linux.oprofile |
|---|---|
| Message-ID | <[email protected]> |
On 10/16/2014 02:09 PM, Maurice Marks wrote:
> Thanks Maynard. I really appreciate your help with this.
>
> I made two versions of lli (the llvm interpreter that Jits code, then runs it). One is linked with an llvm that has oprofile support (/usr/local/bin/lii), one linked with llvm that has no such support built in. (/usr/bin/lli)
>
> The runs below (on AMD) show that there are no "anon" samples reported even with no llvm support for oprofile.
> However - there is a clue. This time I ran opreport with Verbose debug and it reports a discrepancy between the number
> of samples counted and how many were attributed to DSOs. Plus there are 4 lines of "start_offset is now 0" which I don't understand but you might.
Regarding the message about the discrepancy, see the opreport man page, under the "--symbols" option, for an explanation. But if the LLVM JITed code is really being loaded into the heap, then I'm at a loss to explain why the majority of your sample addresses seem to be in the range of memory where /lib/x86_64-linux-gnu/ld-2.19.so was loaded. A deep dive debugging session would be needed to compare the process's memory mappings (/proc/<pid>/maps) with the sample addresses being collected by operf (which can be see using "-V convert" option.
As for the "start_offset is now 0", it's just informational goop for debugging purposes, and these are not unusual.
>
> Looking at your response I have a question about "anonymous memory mappings". When you say that the JVM's jit puts code in anonymous memory mappings, is there something it does specifically to advise oprofile of the range of addresses for jit'd code?
See http://oprofile.sourceforge.net/doc/devel/developing.html, "Chapter 1. Developing a new JIT agent". It states the following:
Ensure your virtual machine provides an API that, at minimum, can provide the following information about dynamically compiled code:
- Notification when compilation occurs
- Name of the symbol (i.e., function or class/method, etc.)
- *Address in anonymous memory where the compiled code was loaded*
- Length of the compiled code segment
So as implemented now, oprofile's JIT support does not support JITed code loaded anywhere but in anonymous memory -- JITed code in the heap is not supported.
Now, this is the third time I've asked this question, and I would really appreciate an answer. Have you (or anyone else you know) used oprofile successfully in the past to profile LLVM JITed code? From google searches, I see that the feature seems to have been around since early 2013 (see http://lists.cs.uiuc.edu/pipermail/llvmdev/2013-March/060111.html), but maybe that was some experimental branch (my ignorance of LLVM is showing). But if it's never worked, it's odd no one has ever asked about it on the oprofile-list before.
-Maynard
>
> The llvm jit (and probably others) just grab memory from the heap, generate code into it, mark the region executable and execute the code.
>
> I should add that I've done some experiments with perf, which has a facility (also a file in /tmp) to let perf know about the name, address and length of jit'd code at run time. Using that scheme perf is able to attribute samples in jit'd code to a particular name and range.
> Personally I found that it was unreliable, that is, it did identify jit'd code ranges, but I didn't believe the relative counts. They didn't make sense, especially with perf top, in real time. And I'd really prefer to use oprofile if I can figure out the problem.
>
>
>
> dad@piled:/media/dad/work$ /usr/local/bin/operf -Vdebug -e CPU_CLK_UNHALTED:1000000 /usr/bin/lli 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 loopy.ll
> telling child to start app
> app 17499 is running
> Forking read pid
> parent says start app /usr/bin/lli
> going into waitpid on profiled app 17499
> operf: Profiler started
> 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: 620120
> operf-record process returned OK
> operf_read: Total bytes received from operf_record process: 619888
> Calling _do_jitdump_convert
> start time/end time is 1413484783/1413484788
> JIT dump processing complete.
> operf-read process returned OK
>
> Profiling done.
> dad@piled:/media/dad/work$ /usr/local/bin/opreport -V debug,stats -l /usr/bin/lli
> 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
> start_offset is now 0
> INFO: Sample counts differ: Module summary count: 19294; total symbols count: 2
> image name: /lib/x86_64-linux-gnu/ld-2.19.so <http://ld-2.19.so>
> start_offset is now 0
> start_offset is now 0
> start_offset is now 0
> samples % image name symbol name
> 24 58.5366 no-vmlinux /no-vmlinux
> 12 29.2683 lli /usr/bin/lli
> 1 2.4390 ld-2.19.so <http://ld-2.19.so> check_match.9458
> 1 2.4390 ld-2.19.so <http://ld-2.19.so> do_lookup_x
> 1 2.4390 libc-2.19.so <http://libc-2.19.so> __GI___strcmp_ssse3
> 1 2.4390 libc-2.19.so <http://libc-2.19.so> _int_free
> 1 2.4390 libc-2.19.so <http://libc-2.19.so> malloc_consolidate
> dad@piled:/media/dad/work$
>
>
> On Thu, Oct 16, 2014 at 12:59 PM, Maynard Johnson <[email protected] <mailto:[email protected]>> wrote:
>
> On 10/16/2014 11:31 AM, Maurice Marks wrote:
> > 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.
> >
> [snip]
> > 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 <http://ld-2.19.so> <http://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 <http://libc-2.19.so> <http://libc-2.19.so>
> > 5 0.0256 libpthread-2.19.so <http://libpthread-2.19.so> <http://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
> > ...
> >
> [snip]
> > Other possibilities?
> >
> > Is there an oprofile test for the jit functionality I can try?
> Maurice,
> Please try profiling the LLVM app without the oprofile JIT support. Not sure how you do that, but I presume you know. The results you get should look similar to what I get when I profile a java app without passing the -agentlib or -agentpath to the JVM; i.e.,
>
> -------------------------------------------------------
> [mpjohn@oc1757000783 myJavaStuff]$ opreport
> Using /home/mpjohn/myJavaStuff/oprofile_data/samples/ for samples directory.
> CPU: Intel Sandy Bridge microarchitecture, speed 2401 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| %|
> ------------------
> 140438 100.000 java
> CPU_CLK_UNHALT...|
> samples| %|
> ------------------
> 133294 94.9131 anon (tgid:11436 range:0x7fc4ed000000-0x7fc4ed26ffff)
> 4387 3.1238 libjvm.so
> 2301 1.6384 no-vmlinux
> 211 0.1502 libc-2.12.so <http://libc-2.12.so>
> 90 0.0641 libpthread-2.12.so <http://libpthread-2.12.so>
> 66 0.0470 libzip.so
> 43 0.0306 ld-2.12.so <http://ld-2.12.so>
> 20 0.0142 [vdso] (tgid:11436 range:0x7fffae4ea000-0x7fffae4eafff)
> 18 0.0128 [vsyscall] (tgid:11436 range:0xffffffffff600000-0xffffffffff600fff)
> 5 0.0036 libjava.so
> 1 7.1e-04 libnss_files-2.12.so <http://libnss_files-2.12.so>
> 1 7.1e-04 libjli.so
> 1 7.1e-04 libverify.so
>
> -------------------------------------------------------
>
> Note the "anon" samples. The JVM's JIT compiler puts JITed code into anonymous memory mappings. The oprofile JIT support works on the assumption that samples from JITed code will be associated with those anonymous memory mappings. So, if after profiling LLVM without the oprofile JIT agent support, you are not seeing any "anon" samples, that tells me that LLVM is not putting JITed code in anonymous memory mappings, and oprofile's JIT support won't work for it.
>
> I have verified that oprofile's support for Java JITed code works fine on Ubuntu. Does oprofile's support for LLVM JITed code work on any other platform?
>
> -Maynard
> >
> > 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] <mailto:[email protected]> <mailto:[email protected] <mailto:[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> <http://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> <http://libc-2.19.so> <http://libc-2.19.so>
> > > 1 0.0048 libpthread-2.19.so <http://libpthread-2.19.so> <http://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> <http://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] <mailto:[email protected]> <mailto:[email protected] <mailto:[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] <mailto:[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