From: Suthikulpanit, S. <Sur...@am...> - 2009-05-28 06:52:01
|
Hi, I have run into a scenario when OProfile daemon fails to profile a Java application. 1. Start profile (opcontrol -start) 2. Start Java application with the JVMTI agent. 3. Stop Java application 4. Stop profile (opcontrol -shutdown) In the above scenario, if there is no sample dump (OProfile daemon does not process samples in the event buffer.) during the period that the Java process is running. The daemon will not be able to map the anonymous samples to the JIT functions. However, if we force a dump (opcontrol -dump) during the period that the Java process is running, this problem will not occur. Is this a known behavior? Suravee |
From: Daniel H. <dan...@li...> - 2009-05-28 12:42:51
|
Hi Suravee, can you send more details about your scenario? - Java version - user that you are using (root, non-root) - Oprofile version (release + version or development version) - detailed output of Oprofile (i.e. error messages) Kind regards, Daniel Suthikulpanit, Suravee wrote: > Hi, > > > > I have run into a scenario when OProfile daemon fails to profile a Java > application. > > > > 1. Start profile (opcontrol -start) > > 2. Start Java application with the JVMTI agent. > > 3. Stop Java application > > 4. Stop profile (opcontrol -shutdown) > > > > In the above scenario, if there is no sample dump (OProfile daemon does > not process samples in the event buffer.) during the period that the > Java process is running. The daemon will not be able to map the > anonymous samples to the JIT functions. However, if we force a dump > (opcontrol -dump) during the period that the Java process is running, > this problem will not occur. Is this a known behavior? > > > > Suravee > > > > > ------------------------------------------------------------------------ > > ------------------------------------------------------------------------------ > Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT > is a gathering of tech-side developers & brand creativity professionals. Meet > the minds behind Google Creative Lab, Visual Complexity, Processing, & > iPhoneDevCamp as they present alongside digital heavyweights like Barbarian > Group, R/GA, & Big Spaceship. http://p.sf.net/sfu/creativitycat-com > > > ------------------------------------------------------------------------ > > _______________________________________________ > oprofile-list mailing list > opr...@li... > https://lists.sourceforge.net/lists/listinfo/oprofile-list |
From: Suravee S. <sur...@am...> - 2009-05-28 14:49:15
|
Daniel Hansel wrote: > Hi Suravee, > > can you send more details about your scenario? > - Java version java -version java version "1.6.0_10" Java(TM) SE Runtime Environment (build 1.6.0_10-b33) Java HotSpot(TM) 64-Bit Server VM (build 11.0-b15, mixed mode) > - user that you are using (root, non-root) I was running as root > - Oprofile version (release + version or development version) OProfile 0.9.4 and Current trunk > - detailed output of Oprofile (i.e. error messages) I used the script below to reproduce the problem. I increased the size of the event buffer (4 times the default size). Here, I see that the daemon does not process the samples in the event buffer until after the scimark2 application finished (due to the fact that the number of samples in event buffer has not reached the watershed mark). You can experiment by: 1. Remove the file /var/lib/oprofile/complete_dump 2. Run "watch -n1 ls -l /var/lib/oprofile/complete_dump" on a separate windows. 3. Run the following script ------------------- BEGIN SCRIPT #!/bin/bash OPCONTROL=/usr/local/bin/opcontrol JAVA=/sandbox/tarballs/jdk1.6.0_10-64/bin/java rm -rf /root/.oprofile/daemonrc rm -rf /var/lib/oprofile/ $OPCONTROL --reset $OPCONTROL --no-vmlinux $OPCONTROL --event=CPU_CLK_UNHALTED:1000000:0:1:1 $OPCONTROL --separate=lib,cpu $OPCONTROL --buffer-size=524288 $OPCONTROL --buffer-watershed=32768 $OPCONTROL --cpu-buffer-size=8192 $OPCONTROL --start $OPCONTROL --status $JAVA -agentpath:/usr/local/lib/oprofile/libjvmti_oprofile.so.0.0.0 jnt.scimark2.commandline $OPCONTROL --shutdown ------------------- END SCRIPT ============= INVESTIGATION ============= I have looked into the function get_anon_maps(), file daemon/opd_anon.c, the code tries to acquire memory mapping of the Java process from "/proc/<pid>/maps. The problem with this approach is, if the Java process exits before the daemon get a chance to process samples, it will not have the memory maps of the Java process to map the anon samples to. --------------------------------------------------------- CASE1: linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all CPU: AMD64 family10, speed 1595.99 MHz (estimated) Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 1000000 CPU_CLK_UNHALT...| samples| %| ------------------ 2159 71.2776 no-vmlinux 483 15.9459 libjvm.so 133 4.3909 libc-2.9.so 63 2.0799 libpixman-1.so.0.12.0 36 1.1885 bash 33 1.0895 libcairo.so.2.10800.0 31 1.0234 ld-2.9.so 17 0.5612 Xorg 13 0.4292 oprofiled 12 0.3962 libpthread-2.9.so 8 0.2641 libzip.so 5 0.1651 libfb.so 5 0.1651 ophelp 4 0.1321 libgdk-x11-2.0.so.0.1400.4 4 0.1321 libglib-2.0.so.0.1800.2 3 0.0990 libverify.so 3 0.0990 libX11.so.6.2.0 2 0.0660 gawk 2 0.0660 libm-2.9.so 2 0.0660 libreadline.so.5.2 2 0.0660 libpango-1.0.so.0.2201.0 1 0.0330 grep 1 0.0330 librt-2.9.so 1 0.0330 libjava.so 1 0.0330 libORBit-2.so.0.1.0 1 0.0330 libgobject-2.0.so.0.1800.2 1 0.0330 libgtk-x11-2.0.so.0.1400.4 1 0.0330 libxaa.so 1 0.0330 libopagent.so.1.0.0 1 0.0330 [vdso] (tgid:4927 range:0x7fff9475f000-0x7fff94760000) linux-szdq:/sandbox/Scimark2_Java # cat var/lib/oprofile/samples/oprofiled.log oprofiled started Thu May 28 04:18:20 2009 kernel pointer size: 8 Thu May 28 04:18:51 2009 -- OProfile Statistics -- Nr. sample dumps: 2 Nr. non-backtrace samples: 48508 Nr. kernel samples: 2159 Nr. lost samples (no kernel/user): 0 Nr. lost kernel samples: 0 Nr. incomplete code structs: 0 Nr. samples lost due to sample file open failure: 0 Nr. samples lost due to no permanent mapping: 45908 <---- LOST JAVA SAMPLES --------------------------------------------------------- CASE 2: However, if I force dump using "opcontrol --dump" during the run of the application, I will get the following: linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all CPU: AMD64 family10, speed 1595.99 MHz (estimated) Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 1000000 CPU_CLK_UNHALT...| samples| %| ------------------ 45845 93.8351 10387.jo <--- THIS IS JAVA APPLICATION 2124 4.3474 no-vmlinux 469 0.9599 libjvm.so 147 0.3009 libc-2.9.so 72 0.1474 libpixman-1.so.0.12.0 46 0.0942 bash 36 0.0737 ld-2.9.so 30 0.0614 libcairo.so.2.10800.0 16 0.0327 Xorg 12 0.0246 libpthread-2.9.so 9 0.0184 ophelp 9 0.0184 oprofiled 6 0.0123 libzip.so 4 0.0082 libm-2.9.so 4 0.0082 libglib-2.0.so.0.1800.2 4 0.0082 libgobject-2.0.so.0.1800.2 3 0.0061 libselinux.so.1 3 0.0061 libverify.so 2 0.0041 gawk 2 0.0041 libclearlooks.so 1 0.0020 grep 1 0.0020 libdl-2.9.so 1 0.0020 librt-2.9.so 1 0.0020 libhpi.so 1 0.0020 libORBit-2.so.0.1.0 1 0.0020 libX11.so.6.2.0 1 0.0020 libcrypto.so.0.9.8 1 0.0020 libgdk-x11-2.0.so.0.1400.4 1 0.0020 libgtk-x11-2.0.so.0.1400.4 1 0.0020 libxcb.so.1.0.0 1 0.0020 libfb.so 1 0.0020 libxaa.so 1 0.0020 irqbalance 1 0.0020 [vdso] (tgid:10387 range:0x7ffff3dff000-0x7ffff3e00000) linux-szdq:/sandbox/Scimark2_Java # cat /var/lib/oprofile/samples/oprofiled.log oprofiled started Thu May 28 04:21:38 2009 kernel pointer size: 8 Thu May 28 04:22:09 2009 -- OProfile Statistics -- Nr. sample dumps: 3 Nr. non-backtrace samples: 2929 Nr. kernel samples: 2124 Nr. lost samples (no kernel/user): 0 Nr. lost kernel samples: 0 Nr. incomplete code structs: 0 Nr. samples lost due to sample file open failure: 0 Nr. samples lost due to no permanent mapping: 0 Nr. event lost due to buffer overflow: 0 Nr. samples lost due to no mapping: 1 Nr. backtraces skipped due to no file mapping: 0 Nr. samples lost due to no mm: 36 Suravee > > Kind regards, > Daniel > > Suthikulpanit, Suravee wrote: >> Hi, >> >> >> >> I have run into a scenario when OProfile daemon fails to profile a Java >> application. >> >> >> >> 1. Start profile (opcontrol -start) >> >> 2. Start Java application with the JVMTI agent. >> >> 3. Stop Java application >> >> 4. Stop profile (opcontrol -shutdown) >> >> >> >> In the above scenario, if there is no sample dump (OProfile daemon does >> not process samples in the event buffer.) during the period that the >> Java process is running. The daemon will not be able to map the >> anonymous samples to the JIT functions. However, if we force a dump >> (opcontrol -dump) during the period that the Java process is running, >> this problem will not occur. Is this a known behavior? >> >> >> >> Suravee >> >> >> >> >> ------------------------------------------------------------------------ >> >> ------------------------------------------------------------------------------ >> Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT >> is a gathering of tech-side developers & brand creativity professionals. Meet >> the minds behind Google Creative Lab, Visual Complexity, Processing, & >> iPhoneDevCamp as they present alongside digital heavyweights like Barbarian >> Group, R/GA, & Big Spaceship. http://p.sf.net/sfu/creativitycat-com >> >> >> ------------------------------------------------------------------------ >> >> _______________________________________________ >> oprofile-list mailing list >> opr...@li... >> https://lists.sourceforge.net/lists/listinfo/oprofile-list > > > ------------------------------------------------------------------------------ > Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT > is a gathering of tech-side developers & brand creativity professionals. Meet > the minds behind Google Creative Lab, Visual Complexity, Processing, & > iPhoneDevCamp as they present alongside digital heavyweights like Barbarian > Group, R/GA, & Big Spaceship. http://p.sf.net/sfu/creativitycat-com > _______________________________________________ > oprofile-list mailing list > opr...@li... > https://lists.sourceforge.net/lists/listinfo/oprofile-list > |
From: Daniel H. <dan...@li...> - 2009-07-27 19:01:23
|
Hi Suravee, OProfile's Java support uses an agent library to listen for "compiled method load" events from the JVM. This means that the methods you want to profile must be JITed. If you're using the Sun Java Hotspot, this won't happen the first time around, so be sure that you iterate over the methods you want to profile. So I would say that this is a known issue when you are profile such an application that do not iterate over the methods. You could try to test that using another JVM. Kind regards, Daniel p.s.: Sorry for that big delay. I was too busy in the last time due to an organizational change. Suravee Suthikulpanit wrote: > Daniel Hansel wrote: >> Hi Suravee, >> >> can you send more details about your scenario? >> - Java version > java -version > java version "1.6.0_10" > Java(TM) SE Runtime Environment (build 1.6.0_10-b33) > Java HotSpot(TM) 64-Bit Server VM (build 11.0-b15, mixed mode) > >> - user that you are using (root, non-root) > I was running as root > >> - Oprofile version (release + version or development version) > OProfile 0.9.4 and Current trunk >> - detailed output of Oprofile (i.e. error messages) > > I used the script below to reproduce the problem. I increased the size > of the event buffer (4 times the default size). Here, I see that the > daemon does not process the samples in the event buffer until after the > scimark2 application finished (due to the fact that the number of > samples in event buffer has not reached the watershed mark). You can > experiment by: > > 1. Remove the file /var/lib/oprofile/complete_dump > 2. Run "watch -n1 ls -l /var/lib/oprofile/complete_dump" on a separate > windows. > 3. Run the following script > > ------------------- BEGIN SCRIPT > #!/bin/bash > > OPCONTROL=/usr/local/bin/opcontrol > JAVA=/sandbox/tarballs/jdk1.6.0_10-64/bin/java > > rm -rf /root/.oprofile/daemonrc > rm -rf /var/lib/oprofile/ > > $OPCONTROL --reset > $OPCONTROL --no-vmlinux > $OPCONTROL --event=CPU_CLK_UNHALTED:1000000:0:1:1 > $OPCONTROL --separate=lib,cpu > $OPCONTROL --buffer-size=524288 > $OPCONTROL --buffer-watershed=32768 > $OPCONTROL --cpu-buffer-size=8192 > > $OPCONTROL --start > $OPCONTROL --status > > $JAVA -agentpath:/usr/local/lib/oprofile/libjvmti_oprofile.so.0.0.0 > jnt.scimark2.commandline > > $OPCONTROL --shutdown > ------------------- END SCRIPT > > ============= > INVESTIGATION > ============= > I have looked into the function get_anon_maps(), file daemon/opd_anon.c, > the code tries to acquire memory mapping of the Java process from > "/proc/<pid>/maps. The problem with this approach is, if the Java > process exits before the daemon get a chance to process samples, it will > not have the memory maps of the Java process to map the anon samples to. > > --------------------------------------------------------- > CASE1: > > linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all > CPU: AMD64 family10, speed 1595.99 MHz (estimated) > Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a > unit mask of 0x00 (No unit mask) count 1000000 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 2159 71.2776 no-vmlinux > 483 15.9459 libjvm.so > 133 4.3909 libc-2.9.so > 63 2.0799 libpixman-1.so.0.12.0 > 36 1.1885 bash > 33 1.0895 libcairo.so.2.10800.0 > 31 1.0234 ld-2.9.so > 17 0.5612 Xorg > 13 0.4292 oprofiled > 12 0.3962 libpthread-2.9.so > 8 0.2641 libzip.so > 5 0.1651 libfb.so > 5 0.1651 ophelp > 4 0.1321 libgdk-x11-2.0.so.0.1400.4 > 4 0.1321 libglib-2.0.so.0.1800.2 > 3 0.0990 libverify.so > 3 0.0990 libX11.so.6.2.0 > 2 0.0660 gawk > 2 0.0660 libm-2.9.so > 2 0.0660 libreadline.so.5.2 > 2 0.0660 libpango-1.0.so.0.2201.0 > 1 0.0330 grep > 1 0.0330 librt-2.9.so > 1 0.0330 libjava.so > 1 0.0330 libORBit-2.so.0.1.0 > 1 0.0330 libgobject-2.0.so.0.1800.2 > 1 0.0330 libgtk-x11-2.0.so.0.1400.4 > 1 0.0330 libxaa.so > 1 0.0330 libopagent.so.1.0.0 > 1 0.0330 [vdso] (tgid:4927 range:0x7fff9475f000-0x7fff94760000) > linux-szdq:/sandbox/Scimark2_Java # cat > var/lib/oprofile/samples/oprofiled.log > oprofiled started Thu May 28 04:18:20 2009 > kernel pointer size: 8 > > Thu May 28 04:18:51 2009 > > > -- OProfile Statistics -- > Nr. sample dumps: 2 > Nr. non-backtrace samples: 48508 > Nr. kernel samples: 2159 > Nr. lost samples (no kernel/user): 0 > Nr. lost kernel samples: 0 > Nr. incomplete code structs: 0 > Nr. samples lost due to sample file open failure: 0 > Nr. samples lost due to no permanent mapping: 45908 <---- LOST JAVA SAMPLES > > --------------------------------------------------------- > CASE 2: > > However, if I force dump using "opcontrol --dump" during the run of the > application, I will get the following: > > linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all > CPU: AMD64 family10, speed 1595.99 MHz (estimated) > Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a > unit mask of 0x00 (No unit mask) count 1000000 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 45845 93.8351 10387.jo <--- THIS IS JAVA APPLICATION > 2124 4.3474 no-vmlinux > 469 0.9599 libjvm.so > 147 0.3009 libc-2.9.so > 72 0.1474 libpixman-1.so.0.12.0 > 46 0.0942 bash > 36 0.0737 ld-2.9.so > 30 0.0614 libcairo.so.2.10800.0 > 16 0.0327 Xorg > 12 0.0246 libpthread-2.9.so > 9 0.0184 ophelp > 9 0.0184 oprofiled > 6 0.0123 libzip.so > 4 0.0082 libm-2.9.so > 4 0.0082 libglib-2.0.so.0.1800.2 > 4 0.0082 libgobject-2.0.so.0.1800.2 > 3 0.0061 libselinux.so.1 > 3 0.0061 libverify.so > 2 0.0041 gawk > 2 0.0041 libclearlooks.so > 1 0.0020 grep > 1 0.0020 libdl-2.9.so > 1 0.0020 librt-2.9.so > 1 0.0020 libhpi.so > 1 0.0020 libORBit-2.so.0.1.0 > 1 0.0020 libX11.so.6.2.0 > 1 0.0020 libcrypto.so.0.9.8 > 1 0.0020 libgdk-x11-2.0.so.0.1400.4 > 1 0.0020 libgtk-x11-2.0.so.0.1400.4 > 1 0.0020 libxcb.so.1.0.0 > 1 0.0020 libfb.so > 1 0.0020 libxaa.so > 1 0.0020 irqbalance > 1 0.0020 [vdso] (tgid:10387 range:0x7ffff3dff000-0x7ffff3e00000) > linux-szdq:/sandbox/Scimark2_Java # cat > /var/lib/oprofile/samples/oprofiled.log > oprofiled started Thu May 28 04:21:38 2009 > kernel pointer size: 8 > > Thu May 28 04:22:09 2009 > > > -- OProfile Statistics -- > Nr. sample dumps: 3 > Nr. non-backtrace samples: 2929 > Nr. kernel samples: 2124 > Nr. lost samples (no kernel/user): 0 > Nr. lost kernel samples: 0 > Nr. incomplete code structs: 0 > Nr. samples lost due to sample file open failure: 0 > Nr. samples lost due to no permanent mapping: 0 > Nr. event lost due to buffer overflow: 0 > Nr. samples lost due to no mapping: 1 > Nr. backtraces skipped due to no file mapping: 0 > Nr. samples lost due to no mm: 36 > > Suravee >> >> Kind regards, >> Daniel >> >> Suthikulpanit, Suravee wrote: >>> Hi, >>> >>> >>> >>> I have run into a scenario when OProfile daemon fails to profile a Java >>> application. >>> >>> >>> >>> 1. Start profile (opcontrol -start) >>> >>> 2. Start Java application with the JVMTI agent. >>> >>> 3. Stop Java application >>> >>> 4. Stop profile (opcontrol -shutdown) >>> >>> >>> >>> In the above scenario, if there is no sample dump (OProfile daemon does >>> not process samples in the event buffer.) during the period that the >>> Java process is running. The daemon will not be able to map the >>> anonymous samples to the JIT functions. However, if we force a dump >>> (opcontrol -dump) during the period that the Java process is running, >>> this problem will not occur. Is this a known behavior? >>> >>> >>> >>> Suravee >>> >>> >>> >>> >>> ------------------------------------------------------------------------ >>> >>> ------------------------------------------------------------------------------ >>> >>> Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT >>> is a gathering of tech-side developers & brand creativity >>> professionals. Meet >>> the minds behind Google Creative Lab, Visual Complexity, Processing, >>> & iPhoneDevCamp as they present alongside digital heavyweights like >>> Barbarian Group, R/GA, & Big Spaceship. >>> http://p.sf.net/sfu/creativitycat-com >>> >>> ------------------------------------------------------------------------ >>> >>> _______________________________________________ >>> oprofile-list mailing list >>> opr...@li... >>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >> >> >> ------------------------------------------------------------------------------ >> >> Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT >> is a gathering of tech-side developers & brand creativity >> professionals. Meet >> the minds behind Google Creative Lab, Visual Complexity, Processing, & >> iPhoneDevCamp as they present alongside digital heavyweights like >> Barbarian Group, R/GA, & Big Spaceship. >> http://p.sf.net/sfu/creativitycat-com >> _______________________________________________ >> oprofile-list mailing list >> opr...@li... >> https://lists.sourceforge.net/lists/listinfo/oprofile-list >> > > |
From: Suthikulpanit, S. <Sur...@am...> - 2009-07-27 23:21:54
|
Daniel, I don't think this is the issue with JDK. If so, how come it works fine when I force dump by "echo 1 > /dev/oprofile/dump". Suravee -----Original Message----- From: Daniel Hansel [mailto:dan...@li...] Sent: Monday, July 27, 2009 11:00 AM To: Suthikulpanit, Suravee Cc: opr...@li... Subject: Re: Oprofile fails to profile Java application in a scenario Hi Suravee, OProfile's Java support uses an agent library to listen for "compiled method load" events from the JVM. This means that the methods you want to profile must be JITed. If you're using the Sun Java Hotspot, this won't happen the first time around, so be sure that you iterate over the methods you want to profile. So I would say that this is a known issue when you are profile such an application that do not iterate over the methods. You could try to test that using another JVM. Kind regards, Daniel p.s.: Sorry for that big delay. I was too busy in the last time due to an organizational change. Suravee Suthikulpanit wrote: > Daniel Hansel wrote: >> Hi Suravee, >> >> can you send more details about your scenario? >> - Java version > java -version > java version "1.6.0_10" > Java(TM) SE Runtime Environment (build 1.6.0_10-b33) > Java HotSpot(TM) 64-Bit Server VM (build 11.0-b15, mixed mode) > >> - user that you are using (root, non-root) > I was running as root > >> - Oprofile version (release + version or development version) > OProfile 0.9.4 and Current trunk >> - detailed output of Oprofile (i.e. error messages) > > I used the script below to reproduce the problem. I increased the size > of the event buffer (4 times the default size). Here, I see that the > daemon does not process the samples in the event buffer until after the > scimark2 application finished (due to the fact that the number of > samples in event buffer has not reached the watershed mark). You can > experiment by: > > 1. Remove the file /var/lib/oprofile/complete_dump > 2. Run "watch -n1 ls -l /var/lib/oprofile/complete_dump" on a separate > windows. > 3. Run the following script > > ------------------- BEGIN SCRIPT > #!/bin/bash > > OPCONTROL=/usr/local/bin/opcontrol > JAVA=/sandbox/tarballs/jdk1.6.0_10-64/bin/java > > rm -rf /root/.oprofile/daemonrc > rm -rf /var/lib/oprofile/ > > $OPCONTROL --reset > $OPCONTROL --no-vmlinux > $OPCONTROL --event=CPU_CLK_UNHALTED:1000000:0:1:1 > $OPCONTROL --separate=lib,cpu > $OPCONTROL --buffer-size=524288 > $OPCONTROL --buffer-watershed=32768 > $OPCONTROL --cpu-buffer-size=8192 > > $OPCONTROL --start > $OPCONTROL --status > > $JAVA -agentpath:/usr/local/lib/oprofile/libjvmti_oprofile.so.0.0.0 > jnt.scimark2.commandline > > $OPCONTROL --shutdown > ------------------- END SCRIPT > > ============= > INVESTIGATION > ============= > I have looked into the function get_anon_maps(), file daemon/opd_anon.c, > the code tries to acquire memory mapping of the Java process from > "/proc/<pid>/maps. The problem with this approach is, if the Java > process exits before the daemon get a chance to process samples, it will > not have the memory maps of the Java process to map the anon samples to. > > --------------------------------------------------------- > CASE1: > > linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all > CPU: AMD64 family10, speed 1595.99 MHz (estimated) > Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a > unit mask of 0x00 (No unit mask) count 1000000 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 2159 71.2776 no-vmlinux > 483 15.9459 libjvm.so > 133 4.3909 libc-2.9.so > 63 2.0799 libpixman-1.so.0.12.0 > 36 1.1885 bash > 33 1.0895 libcairo.so.2.10800.0 > 31 1.0234 ld-2.9.so > 17 0.5612 Xorg > 13 0.4292 oprofiled > 12 0.3962 libpthread-2.9.so > 8 0.2641 libzip.so > 5 0.1651 libfb.so > 5 0.1651 ophelp > 4 0.1321 libgdk-x11-2.0.so.0.1400.4 > 4 0.1321 libglib-2.0.so.0.1800.2 > 3 0.0990 libverify.so > 3 0.0990 libX11.so.6.2.0 > 2 0.0660 gawk > 2 0.0660 libm-2.9.so > 2 0.0660 libreadline.so.5.2 > 2 0.0660 libpango-1.0.so.0.2201.0 > 1 0.0330 grep > 1 0.0330 librt-2.9.so > 1 0.0330 libjava.so > 1 0.0330 libORBit-2.so.0.1.0 > 1 0.0330 libgobject-2.0.so.0.1800.2 > 1 0.0330 libgtk-x11-2.0.so.0.1400.4 > 1 0.0330 libxaa.so > 1 0.0330 libopagent.so.1.0.0 > 1 0.0330 [vdso] (tgid:4927 range:0x7fff9475f000-0x7fff94760000) > linux-szdq:/sandbox/Scimark2_Java # cat > var/lib/oprofile/samples/oprofiled.log > oprofiled started Thu May 28 04:18:20 2009 > kernel pointer size: 8 > > Thu May 28 04:18:51 2009 > > > -- OProfile Statistics -- > Nr. sample dumps: 2 > Nr. non-backtrace samples: 48508 > Nr. kernel samples: 2159 > Nr. lost samples (no kernel/user): 0 > Nr. lost kernel samples: 0 > Nr. incomplete code structs: 0 > Nr. samples lost due to sample file open failure: 0 > Nr. samples lost due to no permanent mapping: 45908 <---- LOST JAVA SAMPLES > > --------------------------------------------------------- > CASE 2: > > However, if I force dump using "opcontrol --dump" during the run of the > application, I will get the following: > > linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all > CPU: AMD64 family10, speed 1595.99 MHz (estimated) > Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a > unit mask of 0x00 (No unit mask) count 1000000 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 45845 93.8351 10387.jo <--- THIS IS JAVA APPLICATION > 2124 4.3474 no-vmlinux > 469 0.9599 libjvm.so > 147 0.3009 libc-2.9.so > 72 0.1474 libpixman-1.so.0.12.0 > 46 0.0942 bash > 36 0.0737 ld-2.9.so > 30 0.0614 libcairo.so.2.10800.0 > 16 0.0327 Xorg > 12 0.0246 libpthread-2.9.so > 9 0.0184 ophelp > 9 0.0184 oprofiled > 6 0.0123 libzip.so > 4 0.0082 libm-2.9.so > 4 0.0082 libglib-2.0.so.0.1800.2 > 4 0.0082 libgobject-2.0.so.0.1800.2 > 3 0.0061 libselinux.so.1 > 3 0.0061 libverify.so > 2 0.0041 gawk > 2 0.0041 libclearlooks.so > 1 0.0020 grep > 1 0.0020 libdl-2.9.so > 1 0.0020 librt-2.9.so > 1 0.0020 libhpi.so > 1 0.0020 libORBit-2.so.0.1.0 > 1 0.0020 libX11.so.6.2.0 > 1 0.0020 libcrypto.so.0.9.8 > 1 0.0020 libgdk-x11-2.0.so.0.1400.4 > 1 0.0020 libgtk-x11-2.0.so.0.1400.4 > 1 0.0020 libxcb.so.1.0.0 > 1 0.0020 libfb.so > 1 0.0020 libxaa.so > 1 0.0020 irqbalance > 1 0.0020 [vdso] (tgid:10387 range:0x7ffff3dff000-0x7ffff3e00000) > linux-szdq:/sandbox/Scimark2_Java # cat > /var/lib/oprofile/samples/oprofiled.log > oprofiled started Thu May 28 04:21:38 2009 > kernel pointer size: 8 > > Thu May 28 04:22:09 2009 > > > -- OProfile Statistics -- > Nr. sample dumps: 3 > Nr. non-backtrace samples: 2929 > Nr. kernel samples: 2124 > Nr. lost samples (no kernel/user): 0 > Nr. lost kernel samples: 0 > Nr. incomplete code structs: 0 > Nr. samples lost due to sample file open failure: 0 > Nr. samples lost due to no permanent mapping: 0 > Nr. event lost due to buffer overflow: 0 > Nr. samples lost due to no mapping: 1 > Nr. backtraces skipped due to no file mapping: 0 > Nr. samples lost due to no mm: 36 > > Suravee >> >> Kind regards, >> Daniel >> >> Suthikulpanit, Suravee wrote: >>> Hi, >>> >>> >>> >>> I have run into a scenario when OProfile daemon fails to profile a Java >>> application. >>> >>> >>> >>> 1. Start profile (opcontrol -start) >>> >>> 2. Start Java application with the JVMTI agent. >>> >>> 3. Stop Java application >>> >>> 4. Stop profile (opcontrol -shutdown) >>> >>> >>> >>> In the above scenario, if there is no sample dump (OProfile daemon does >>> not process samples in the event buffer.) during the period that the >>> Java process is running. The daemon will not be able to map the >>> anonymous samples to the JIT functions. However, if we force a dump >>> (opcontrol -dump) during the period that the Java process is running, >>> this problem will not occur. Is this a known behavior? >>> >>> >>> >>> Suravee >>> >>> >>> >>> >>> ------------------------------------------------------------------------ >>> >>> ------------------------------------------------------------------------ ------ >>> >>> Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT >>> is a gathering of tech-side developers & brand creativity >>> professionals. Meet >>> the minds behind Google Creative Lab, Visual Complexity, Processing, >>> & iPhoneDevCamp as they present alongside digital heavyweights like >>> Barbarian Group, R/GA, & Big Spaceship. >>> http://p.sf.net/sfu/creativitycat-com >>> >>> ------------------------------------------------------------------------ >>> >>> _______________________________________________ >>> oprofile-list mailing list >>> opr...@li... >>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >> >> >> ------------------------------------------------------------------------ ------ >> >> Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT >> is a gathering of tech-side developers & brand creativity >> professionals. Meet >> the minds behind Google Creative Lab, Visual Complexity, Processing, & >> iPhoneDevCamp as they present alongside digital heavyweights like >> Barbarian Group, R/GA, & Big Spaceship. >> http://p.sf.net/sfu/creativitycat-com >> _______________________________________________ >> oprofile-list mailing list >> opr...@li... >> https://lists.sourceforge.net/lists/listinfo/oprofile-list >> > > |
From: Daniel H. <dan...@li...> - 2009-07-28 07:10:23
|
Hi Suravee, you are right. I remembered the thing with the HotSpot JVM Maynard has mentioned some time before. I forgot to look for the fact that dumping could be used to get the missing data. I will look for details of that problem. Thanks and kind regards, Daniel Suthikulpanit, Suravee wrote: > Daniel, > > I don't think this is the issue with JDK. If so, how come it works fine > when I force dump by "echo 1 > /dev/oprofile/dump". > > Suravee > > -----Original Message----- > From: Daniel Hansel [mailto:dan...@li...] > Sent: Monday, July 27, 2009 11:00 AM > To: Suthikulpanit, Suravee > Cc: opr...@li... > Subject: Re: Oprofile fails to profile Java application in a scenario > > Hi Suravee, > > OProfile's Java support uses an agent library to listen for "compiled > method load" events from the JVM. > This means that the methods you want to profile must be JITed. > If you're using the Sun Java Hotspot, this won't happen the first time > around, > so be sure that you iterate over the methods you want to profile. > > So I would say that this is a known issue when you are profile such an > application that do not iterate over the methods. > > You could try to test that using another JVM. > > Kind regards, > Daniel > > p.s.: Sorry for that big delay. I was too busy in the last time due to > an organizational change. > > Suravee Suthikulpanit wrote: >> Daniel Hansel wrote: >>> Hi Suravee, >>> >>> can you send more details about your scenario? >>> - Java version >> java -version >> java version "1.6.0_10" >> Java(TM) SE Runtime Environment (build 1.6.0_10-b33) >> Java HotSpot(TM) 64-Bit Server VM (build 11.0-b15, mixed mode) >> >>> - user that you are using (root, non-root) >> I was running as root >> >>> - Oprofile version (release + version or development version) >> OProfile 0.9.4 and Current trunk >>> - detailed output of Oprofile (i.e. error messages) >> I used the script below to reproduce the problem. I increased the > size >> of the event buffer (4 times the default size). Here, I see that the >> daemon does not process the samples in the event buffer until after > the >> scimark2 application finished (due to the fact that the number of >> samples in event buffer has not reached the watershed mark). You can >> experiment by: >> >> 1. Remove the file /var/lib/oprofile/complete_dump >> 2. Run "watch -n1 ls -l /var/lib/oprofile/complete_dump" on a separate > >> windows. >> 3. Run the following script >> >> ------------------- BEGIN SCRIPT >> #!/bin/bash >> >> OPCONTROL=/usr/local/bin/opcontrol >> JAVA=/sandbox/tarballs/jdk1.6.0_10-64/bin/java >> >> rm -rf /root/.oprofile/daemonrc >> rm -rf /var/lib/oprofile/ >> >> $OPCONTROL --reset >> $OPCONTROL --no-vmlinux >> $OPCONTROL --event=CPU_CLK_UNHALTED:1000000:0:1:1 >> $OPCONTROL --separate=lib,cpu >> $OPCONTROL --buffer-size=524288 >> $OPCONTROL --buffer-watershed=32768 >> $OPCONTROL --cpu-buffer-size=8192 >> >> $OPCONTROL --start >> $OPCONTROL --status >> >> $JAVA -agentpath:/usr/local/lib/oprofile/libjvmti_oprofile.so.0.0.0 >> jnt.scimark2.commandline >> >> $OPCONTROL --shutdown >> ------------------- END SCRIPT >> >> ============= >> INVESTIGATION >> ============= >> I have looked into the function get_anon_maps(), file > daemon/opd_anon.c, >> the code tries to acquire memory mapping of the Java process from >> "/proc/<pid>/maps. The problem with this approach is, if the Java >> process exits before the daemon get a chance to process samples, it > will >> not have the memory maps of the Java process to map the anon samples > to. >> --------------------------------------------------------- >> CASE1: >> >> linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all >> CPU: AMD64 family10, speed 1595.99 MHz (estimated) >> Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a >> unit mask of 0x00 (No unit mask) count 1000000 >> CPU_CLK_UNHALT...| >> samples| %| >> ------------------ >> 2159 71.2776 no-vmlinux >> 483 15.9459 libjvm.so >> 133 4.3909 libc-2.9.so >> 63 2.0799 libpixman-1.so.0.12.0 >> 36 1.1885 bash >> 33 1.0895 libcairo.so.2.10800.0 >> 31 1.0234 ld-2.9.so >> 17 0.5612 Xorg >> 13 0.4292 oprofiled >> 12 0.3962 libpthread-2.9.so >> 8 0.2641 libzip.so >> 5 0.1651 libfb.so >> 5 0.1651 ophelp >> 4 0.1321 libgdk-x11-2.0.so.0.1400.4 >> 4 0.1321 libglib-2.0.so.0.1800.2 >> 3 0.0990 libverify.so >> 3 0.0990 libX11.so.6.2.0 >> 2 0.0660 gawk >> 2 0.0660 libm-2.9.so >> 2 0.0660 libreadline.so.5.2 >> 2 0.0660 libpango-1.0.so.0.2201.0 >> 1 0.0330 grep >> 1 0.0330 librt-2.9.so >> 1 0.0330 libjava.so >> 1 0.0330 libORBit-2.so.0.1.0 >> 1 0.0330 libgobject-2.0.so.0.1800.2 >> 1 0.0330 libgtk-x11-2.0.so.0.1400.4 >> 1 0.0330 libxaa.so >> 1 0.0330 libopagent.so.1.0.0 >> 1 0.0330 [vdso] (tgid:4927 > range:0x7fff9475f000-0x7fff94760000) >> linux-szdq:/sandbox/Scimark2_Java # cat >> var/lib/oprofile/samples/oprofiled.log >> oprofiled started Thu May 28 04:18:20 2009 >> kernel pointer size: 8 >> >> Thu May 28 04:18:51 2009 >> >> >> -- OProfile Statistics -- >> Nr. sample dumps: 2 >> Nr. non-backtrace samples: 48508 >> Nr. kernel samples: 2159 >> Nr. lost samples (no kernel/user): 0 >> Nr. lost kernel samples: 0 >> Nr. incomplete code structs: 0 >> Nr. samples lost due to sample file open failure: 0 >> Nr. samples lost due to no permanent mapping: 45908 <---- LOST JAVA > SAMPLES >> --------------------------------------------------------- >> CASE 2: >> >> However, if I force dump using "opcontrol --dump" during the run of > the >> application, I will get the following: >> >> linux-szdq:/sandbox/Scimark2_Java # opreport --merge=all >> CPU: AMD64 family10, speed 1595.99 MHz (estimated) >> Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a >> unit mask of 0x00 (No unit mask) count 1000000 >> CPU_CLK_UNHALT...| >> samples| %| >> ------------------ >> 45845 93.8351 10387.jo <--- THIS IS JAVA APPLICATION >> 2124 4.3474 no-vmlinux >> 469 0.9599 libjvm.so >> 147 0.3009 libc-2.9.so >> 72 0.1474 libpixman-1.so.0.12.0 >> 46 0.0942 bash >> 36 0.0737 ld-2.9.so >> 30 0.0614 libcairo.so.2.10800.0 >> 16 0.0327 Xorg >> 12 0.0246 libpthread-2.9.so >> 9 0.0184 ophelp >> 9 0.0184 oprofiled >> 6 0.0123 libzip.so >> 4 0.0082 libm-2.9.so >> 4 0.0082 libglib-2.0.so.0.1800.2 >> 4 0.0082 libgobject-2.0.so.0.1800.2 >> 3 0.0061 libselinux.so.1 >> 3 0.0061 libverify.so >> 2 0.0041 gawk >> 2 0.0041 libclearlooks.so >> 1 0.0020 grep >> 1 0.0020 libdl-2.9.so >> 1 0.0020 librt-2.9.so >> 1 0.0020 libhpi.so >> 1 0.0020 libORBit-2.so.0.1.0 >> 1 0.0020 libX11.so.6.2.0 >> 1 0.0020 libcrypto.so.0.9.8 >> 1 0.0020 libgdk-x11-2.0.so.0.1400.4 >> 1 0.0020 libgtk-x11-2.0.so.0.1400.4 >> 1 0.0020 libxcb.so.1.0.0 >> 1 0.0020 libfb.so >> 1 0.0020 libxaa.so >> 1 0.0020 irqbalance >> 1 0.0020 [vdso] (tgid:10387 > range:0x7ffff3dff000-0x7ffff3e00000) >> linux-szdq:/sandbox/Scimark2_Java # cat >> /var/lib/oprofile/samples/oprofiled.log >> oprofiled started Thu May 28 04:21:38 2009 >> kernel pointer size: 8 >> >> Thu May 28 04:22:09 2009 >> >> >> -- OProfile Statistics -- >> Nr. sample dumps: 3 >> Nr. non-backtrace samples: 2929 >> Nr. kernel samples: 2124 >> Nr. lost samples (no kernel/user): 0 >> Nr. lost kernel samples: 0 >> Nr. incomplete code structs: 0 >> Nr. samples lost due to sample file open failure: 0 >> Nr. samples lost due to no permanent mapping: 0 >> Nr. event lost due to buffer overflow: 0 >> Nr. samples lost due to no mapping: 1 >> Nr. backtraces skipped due to no file mapping: 0 >> Nr. samples lost due to no mm: 36 >> >> Suravee >>> Kind regards, >>> Daniel >>> >>> Suthikulpanit, Suravee wrote: >>>> Hi, >>>> >>>> >>>> >>>> I have run into a scenario when OProfile daemon fails to profile a > Java >>>> application. >>>> >>>> >>>> >>>> 1. Start profile (opcontrol -start) >>>> >>>> 2. Start Java application with the JVMTI agent. >>>> >>>> 3. Stop Java application >>>> >>>> 4. Stop profile (opcontrol -shutdown) >>>> >>>> >>>> >>>> In the above scenario, if there is no sample dump (OProfile daemon > does >>>> not process samples in the event buffer.) during the period that the >>>> Java process is running. The daemon will not be able to map the >>>> anonymous samples to the JIT functions. However, if we force a dump >>>> (opcontrol -dump) during the period that the Java process is > running, >>>> this problem will not occur. Is this a known behavior? >>>> >>>> >>>> >>>> Suravee >>>> >>>> >>>> >>>> >>>> > ------------------------------------------------------------------------ >>>> > ------------------------------------------------------------------------ > ------ >>>> Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT > >>>> is a gathering of tech-side developers & brand creativity >>>> professionals. Meet >>>> the minds behind Google Creative Lab, Visual Complexity, Processing, > >>>> & iPhoneDevCamp as they present alongside digital heavyweights like >>>> Barbarian Group, R/GA, & Big Spaceship. >>>> http://p.sf.net/sfu/creativitycat-com >>>> >>>> > ------------------------------------------------------------------------ >>>> _______________________________________________ >>>> oprofile-list mailing list >>>> opr...@li... >>>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >>> >>> > ------------------------------------------------------------------------ > ------ >>> Register Now for Creativity and Technology (CaT), June 3rd, NYC. CaT >>> is a gathering of tech-side developers & brand creativity >>> professionals. Meet >>> the minds behind Google Creative Lab, Visual Complexity, Processing, > & >>> iPhoneDevCamp as they present alongside digital heavyweights like >>> Barbarian Group, R/GA, & Big Spaceship. >>> http://p.sf.net/sfu/creativitycat-com >>> _______________________________________________ >>> oprofile-list mailing list >>> opr...@li... >>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >>> >> > > > |