Menu
▾
▴
Re: No anonymous mappings when profiling Java VM (i.e. can't see any compiled Java method)
|
From: Daniel H. <dan...@li...> - 2010-05-11 14:12:49
|
Hi Volker and Maynard, I also have seen that kernel change and I can add this requirement in the documentation. Kind regards, Daniel p.s.: Sorry for my late answer. I am very busy during this and the last weeks. On 05/11/2010 02:13 PM, Volker Simonis wrote: > Ok, I think I found the problem! > > It seems to be an issue with the old kernel. As I wrote I tested on > SLES9 which has a 2.6.5 kernel. Looking at the kernel sources at > http://www.kernel.org I found the change "[PATCH] oprofile: report > anonymous region samples" > (http://git.kernel.org/?p=linux/kernel/git/stable/linux-2.6.27.y.git;a=commit;h=0c0a400d1debb172c596b24ab82efab4975990a9) > which was added in 2.6.13 as far as I can see. > > Wouldn't it be a good idea to update the documentation with a sentence > like "At least kernel 2.6.13 is need for profiling JITed code". > > Thank you and best regards, > Volker > > On Mon, May 10, 2010 at 6:42 PM, Volker Simonis > <vol...@gm...> wrote: >> Hi and thank you for the answer. >> >> This is driving me really nuts! >> >> I've managed to get it running on a SLES 10 now, but still no success >> on SLES 9. I've tried with IBM and Sun JDK 5 and 6 on AMD and Intel >> CPUs without any difference (see example log below). I started >> debugging the oprofiled without any success. Perhaps this is a kernel >> issue? >> >> If I look at the results, I can see that the kernel has a lot of >> cycles, although my small java application (which computes 'e' to a >> given precision with the help of the BigDecimal API) shows up with 99% >> CPU and no sys-time at all in 'top', so there should be nearly no >> samples in kernel-land. >> >> Has anybody else observed this behaviour before? >> >> Regards, >> Volker >> >> >> SUSE LINUX Enterprise Server 9 (x86_64) >> --------------------------------------- >> VERSION = 9 >> PATCHLEVEL = 3 >> Linux hostname 2.6.5-7.276-smp #1 SMP Mon Jul 24 10:45:31 UTC 2006 >> x86_64 x86_64 x86_64 GNU/Linux >> >> hostname:/priv/username/oprofile-0.9.6 # opcontrol -v >> opcontrol: oprofile 0.9.6 compiled on May 10 2010 10:15:19 >> >> hostname:/priv/username/oprofile-0.9.6 # opcontrol --start >> Using default event: GLOBAL_POWER_EVENTS:100000:1:1:1 >> Using 2.6+ OProfile kernel interface. >> Reading module info. >> Using log file /var/lib/oprofile/samples/oprofiled.log >> Daemon started. >> Profiler running. >> >> hostname:/priv/username/oprofile-0.9.6 # java -showversion NumberE 10000 >> java version "1.5.0" >> Java(TM) 2 Runtime Environment, Standard Edition (build >> pxa64devifx-20100127 (SR11 FP1 )) >> IBM J9 VM (build 2.3, J2RE 1.5.0 IBM J9 2.3 Linux amd64-64 >> j9vmxa6423ifx-20100125 (JIT enabled) >> J9VM - 20100122_52103_LHdSMr >> JIT - 20091016_1845ifx1_r8 >> GC - 20091026_AA) >> JCL - 20100127 >> >> ... >> >> hostname:/priv/username/oprofile-0.9.6 # opcontrol --dump >> hostname:/priv/username/oprofile-0.9.6 # opcontrol --stop >> Stopping profiling. >> hostname:/priv/username/oprofile-0.9.6 # opreport >> >> Overflow stats not available >> CPU: P4 / Xeon with 2 hyper-threads, speed 3400.24 MHz (estimated) >> Counted GLOBAL_POWER_EVENTS events (time during which processor is not >> stopped) with a unit mask of 0x01 ( >> mandatory) count 100000 >> GLOBAL_POWER_E...| >> samples| %| >> ------------------ >> 283240 40.7237 libj9gc23.so >> 226134 32.5131 vmlinux-2.6.5-7.276-smp >> 85266 12.2594 libj9jit23.so >> 21400 3.0769 libj9thr23.so >> 21321 3.0655 oprofile >> 17283 2.4849 libpthread.so.0 >> 12576 1.8082 libj9vm23.so >> 7633 1.0975 libc.so.6 >> 6843 0.9839 oprofiled >> 2172 0.3123 libjvm.so >> 1796 0.2582 libj9dyn23.so >> ... >> >> >> hostname:/priv/username/oprofile-0.9.6 # opcontrol --reset >> Signalling daemon... done >> hostname:/priv/username/oprofile-0.9.6 # opcontrol --start >> Profiler running. >> >> hostname:/priv/username/oprofile-0.9.6 # java -showversion -cp >> ~username/Java NumberE 10000 >> java version "1.5.0_24" >> Java(TM) Platform, Standard Edition for Business (build 1.5.0_24-b02) >> Java HotSpot(TM) 64-Bit Server VM (build 1.5.0_24-b02, mixed mode) >> >> ... >> >> hostname:/priv/username/oprofile-0.9.6 # opcontrol --dump >> hostname:/priv/username/oprofile-0.9.6 # opcontrol --stop >> Stopping profiling. >> hostname:/priv/username/oprofile-0.9.6 # opreport >> >> Overflow stats not available >> CPU: P4 / Xeon with 2 hyper-threads, speed 3400.24 MHz (estimated) >> Counted GLOBAL_POWER_EVENTS events (time during which processor is not >> stopped) with a unit mask of 0x01 ( >> mandatory) count 100000 >> GLOBAL_POWER_E...| >> samples| %| >> ------------------ >> 189980 60.5719 vmlinux-2.6.5-7.276-smp >> 52528 16.7477 libjvm.so >> 19140 6.1025 libc.so.6 >> 16930 5.3978 reiserfs >> 14705 4.6884 oprofile >> 5575 1.7775 du >> 3682 1.1739 oprofiled >> >> >> username@hostname:/sapmnt/hs0131/a/sapjvm_dev/username/hg/oprofile-0.9.6_obj> >> top >> top - 12:00:08 up 1223 days, 25 min, 4 users, load average: 1.91, 1.37, 1.25 >> Tasks: 118 total, 2 running, 116 sleeping, 0 stopped, 0 zombie >> Cpu(s): 25.4% us, 0.8% sy, 0.0% ni, 73.7% id, 0.1% wa, 0.0% hi, 0.0% si >> Mem: 4040384k total, 3813984k used, 226400k free, 229600k buffers >> Swap: 12582872k total, 21464k used, 12561408k free, 2877224k cached >> >> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND >> 23908 root 25 0 1221m 41m 8620 R 99.9 1.1 2:00.45 java >> 5384 bin 16 0 4580 316 228 S 0.3 0.0 26:23.94 portmap >> 22321 jvmtests 16 0 40232 3064 2344 S 0.3 0.1 0:00.17 sshd >> 23938 username 16 0 8424 1360 976 R 0.3 0.0 0:00.07 top >> 1 root 16 0 640 80 48 S 0.0 0.0 1:31.37 init >> 2 root RT 0 0 0 0 S 0.0 0.0 0:04.12 migration/0 >> >> >> >> On Fri, May 7, 2010 at 11:11 PM, Maynard Johnson<may...@us...> wrote: >>> Volker Simonis wrote: >>>> And I forgot to say, the kernel is version 2.6.5-7.322-smp >>>> >>>> On Fri, May 7, 2010 at 6:52 PM, Volker Simonis<vol...@gm...> wrote: >>>>> Hi all, >>>>> >>>>> since some days I'm trying to use oprofile to profile JITed Java code >>>>> - unfortunately without success. >>>>> >>>>> I downloaded version 0.9.6 and compiled it on a Linux/x86_64 machine >>>>> (actually SLES 9 with gcc 3.3.3). Because I've read that there are >>>>> problems with older versions of libbfd I used a local version of >>>>> binutils (actually 2.19.51) and configured as follows: >>>>> >>>>> CFLAGS="-m64" CXXFLAGS="-m64" >>>>> CPPFLAGS="-I/share/software/binutils-2.19.51/bfd" >>>>> LDFLAGS="-L/share/software/binutils-2.19.51/bfd >>>>> -L/share/software/binutils-2.19.51/libiberty" ./configure >>>>> --with-kernel-support --with-java=/share/software/jdk1.6.0_11 >>> >>> You could simply use the --with-binutils configure optinon. >>> >>>>> >>>>> 'make' and 'make install' succeeded without error. I created the >>>>> oprofile user and group: >>>>> >>>>> grep oprofile /etc/passwd >>>>> oprofile:x:1036:1051::/home/oprofile:/bin/bash >>>>> grep oprofile /etc/shadow >>>>> oprofile:*:14735:0:99999:7::: >>>>> grep oprofile /etc/group >>>>> oprofile:*:1051:oprofile >>>>> >>>>> After that, as root, I do the following: >>>>> >>>>> opcontrol --init >>>>> opcontrol --no-vmlinux >>>>> opcontrol --start >>>>> >>>>> java -showversion >>>>> -agentpath:/usr/local/lib/oprofile/libjvmti_oprofile.so -cp ~user/Java >>>>> NumberE 10000 >>>>> >>>>> opcontrol --dump >>>>> opcontrol --stop >>>>> >>>>> Afterwards, I can see that a dump file was created in the jitdemo subdirectory: >>>>> >>>>> la /var/lib/oprofile/jitdump/25936.dump >>>>> -rw------- 1 root root 125856 May 7 18:24 /var/lib/oprofile/jitdump/25936.dump >>>>> >>>>> But unfortunately, no *.jo files have been created as described in the >>>>> documentation. >>>>> >>>>> The log file /var/lib/oprofile/samples/oprofiled.log contains line >>>>> like the following: >>>>> >>>>> JIT dump processing exited abnormally: 0 >>>>> >>>>> If I run opjitconv manually, I get the follwing output: >>>>> >>>>> opjitconv -d /var/lib/oprofile/ 1273250000 1273250554 >>>>> start time/end time is 1273250000/1273250554 >>>>> opjitconv: Ending with rc = 2. This code is usually OK, but can be >>>>> useful for debugging purposes. >>>>> >>>>> Looking into opjitconv.h I can see the the exit code '2' means >>>>> OP_JIT_CONV_NO_ANON_SAMPLES, and indeed, there are no anonymous >>>>> mapping in the samples dir: >>>>> >>>>> find /var/lib/oprofile/ -name "*ano*" >>>>> >>>>> returns no results! This is strange, because my Java application for >>>>> sure compiled and executed a lot of methods. E.g. : >>>>> >>>>> strings /var/lib/oprofile/jitdump/25936.dump >>>>> ... >>>>> MutableBigInteger.java >>>>> Ljava/math/MutableBigInteger;unsignedLongCompare(JJ)Z >>>>> BigInteger.java >>>>> Ljava/math/BigInteger;destructiveMulAdd([III)V >>>>> ... >>>>> >>>>> opreport works fine and shows me the expected results, but only for >>>>> concrete executables: >>>>> >>>>> opreport -l >>>>> CPU: AMD64 processors, speed 1800.16 MHz (estimated) >>>>> Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a >>>>> unit mask of 0x00 (No unit mask) count 100000 >>>>> samples % app name symbol name >>>>> 2664480 27.6543 no-vmlinux /no-vmlinux >>>>> 851788 8.8406 libjvm.so >>>>> PhaseAggressiveCoalesce::insert_copies(Matcher&) >>>>> 438239 4.5484 libjvm.so PhaseChaitin::Split(unsigned int) >>>>> 209340 2.1727 libjvm.so Node_Backward_Iterator::next() >>>>> 155579 1.6147 libjvm.so >>>>> SpaceMangler::mangle_region(MemRegion) >>>>> 123938 1.2863 libc.so.6 memcpy >>>>> ... >>>>> >>>>> What am I missing? What am I doing wrong? Why are there no anonymous >>>>> mappings in the samples directory as described in the tutorial? >>> >>> Your description of the setup and running of oprofile was nicely detailed, and AFAICS, you're doing everything right. The unexpected part is that you're not getting any samples from an anonymously mapped memory region. Even if you weren't setting up oprofile's JIT support correctly, your profile data should (I think) still show some anonymous samples. Every Java VM I've tested oprofile with will show samples similar to the following (without using the libjvmti_oprofile.so): >>> >>> -------------- >>> samples % image name app name symbol name >>> 177638 47.1843 anon (tgid:24951 range:<blah>) java anon (tgid:24951 range:<blah>) >>> 75247 19.9871 libj9jit24.so java L.tableDispatch >>> 15474 4.1102 libj9jit24.so java L.28copy >>> -------------- >>> >>> Note the "anon" image name associated with the "java" executable. This means that those 177638 samples were taken in the range of memory of that anonymous mapping. In your opreport output, not only do I not see any "anon" samples, I don't see any sames for the java executable. I suppose it's certainly possible that a given JVM might farm out most of its work to libraries versus the executable. But if the library is running the JITed code from somewhere other than anonymous memory, oprofile won't know how to find it. Can you try another JVM? >>> >>> I've cc'ed Daniel to see if he has any ideas. >>> >>> -Maynard >>> >>>>> >>>>> I would be very graceful for any help. >>>>> >>>>> Regards, >>>>> Volker >>>>> >>>> >>>> ------------------------------------------------------------------------------ >>>> >>>> _______________________________________________ >>>> oprofile-list mailing list >>>> opr...@li... >>>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >>> >>> >> > > ------------------------------------------------------------------------------ > > _______________________________________________ > oprofile-list mailing list > opr...@li... > https://lists.sourceforge.net/lists/listinfo/oprofile-list |