http://www.oracle.com/technetwork/java/javase/tooldescr-136044.html#gblvj Excellent also this article http://www.brendangregg.com/blog/2014-06-09/java-cpu-sampling-using-hprof.html
I am using this stupid class to test:
import java.util.HashMap; public class CUT { public static void main(String[] args) { try { for (int i = 0; i < 10000; i++) { Thread.sleep(1); HashMap<String, Object> m = new HashMap<String, Object>(); m.put("1", new Object()); } } catch (Exception e) { e.printStackTrace(); } } }then I run
javac -g CUT.java java -agentlib:hprof=cpu=samples CUT less java.hprof.txt
this is what I get:
THREAD START (obj=50000193, id = 200001, name="main", group="main") THREAD END (id = 200001) THREAD START (obj=50000193, id = 200004, name="DestroyJavaVM", group="main") THREAD END (id = 200004) THREAD END (id = 200002) TRACE 300050: java.lang.Thread.sleep(Thread.java:Unknown line) CUT.main(CUT.java:7) TRACE 300014: sun.usagetracker.UsageTrackerClient.getPropertyPrivileged(UsageTrackerClient.java:136) sun.usagetracker.UsageTrackerClient.getPropertyPrivileged(UsageTrackerClient.java:132) sun.usagetracker.UsageTrackerClient.(UsageTrackerClient.java:109) sun.misc.PostVMInitHook.trackJavaUsage(PostVMInitHook.java:28) TRACE 300026: java.lang.System.arraycopy(System.java:Unknown line) java.lang.String.getChars(String.java:826) java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:422) java.lang.StringBuffer.append(StringBuffer.java:272) TRACE 300042: java.io.FilePermissionCollection. (FilePermission.java:711) java.io.FilePermission.newPermissionCollection(FilePermission.java:642) java.security.Permissions.getPermissionCollection(Permissions.java:254) java.security.Permissions.add(Permissions.java:132) TRACE 300051: java.util.HashMap.putVal(HashMap.java:628) java.util.HashMap.put(HashMap.java:611) CUT.main(CUT.java:9) TRACE 300052: java.util.HashMap.put(HashMap.java:611) CUT.main(CUT.java:9) CPU SAMPLES BEGIN (total = 12) Wed Feb 3 06:07:50 2016 rank self accum count trace method 1 58.33% 58.33% 7 300050 java.lang.Thread.sleep 2 8.33% 66.67% 1 300014 sun.usagetracker.UsageTrackerClient.getPropertyPrivileged 3 8.33% 75.00% 1 300026 java.lang.System.arraycopy 4 8.33% 83.33% 1 300042 java.io.FilePermissionCollection. 5 8.33% 91.67% 1 300051 java.util.HashMap.putVal 6 8.33% 100.00% 1 300052 java.util.HashMap.put CPU SAMPLES END
Using the other option
java -agentlib:hprof=cpu=times CUT
gives me
THREAD START (obj=5000017d, id = 200002, name="HPROF gc_finish watcher", group="system") THREAD START (obj=5000017d, id = 200001, name="main", group="main") THREAD END (id = 200001) THREAD START (obj=5000017d, id = 200003, name="DestroyJavaVM", group="main") THREAD END (id = 200003) THREAD END (id = 200002) TRACE 301665: CUT.main(CUT.java:Unknown line) TRACE 301663: java.util.HashMap.putVal(HashMap.java:Unknown line) java.util.HashMap.put(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 301664: java.util.HashMap.put(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 301657: java.util.HashMap.(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 301659: java.util.HashMap.hash(HashMap.java:Unknown line) java.util.HashMap.put(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 301661: java.util.HashMap.newNode(HashMap.java:Unknown line) java.util.HashMap.putVal(HashMap.java:Unknown line) java.util.HashMap.put(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 301660: java.util.HashMap.resize(HashMap.java:Unknown line) java.util.HashMap.putVal(HashMap.java:Unknown line) java.util.HashMap.put(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 301662: java.util.HashMap.afterNodeInsertion(HashMap.java:Unknown line) java.util.HashMap.putVal(HashMap.java:Unknown line) java.util.HashMap.put(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 300952: java.util.HashMap$Node. (HashMap.java:Unknown line) java.util.HashMap.newNode(HashMap.java:Unknown line) java.util.HashMap.putVal(HashMap.java:Unknown line) java.util.HashMap.put(HashMap.java:Unknown line) TRACE 301656: java.util.AbstractMap. (AbstractMap.java:Unknown line) java.util.HashMap. (HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 301658: java.lang.String.hashCode(String.java:Unknown line) java.util.HashMap.hash(HashMap.java:Unknown line) java.util.HashMap.put(HashMap.java:Unknown line) CUT.main(CUT.java:Unknown line) TRACE 300163: java.lang.invoke.MethodHandle. (MethodHandle.java:Unknown line) TRACE 300094: java.lang.invoke.MethodHandleImpl. (MethodHandleImpl.java:Unknown line) java.lang.invoke.MethodHandle. (MethodHandle.java:Unknown line) TRACE 300252: java.lang.CharacterDataLatin1.getProperties(CharacterDataLatin1.java:Unknown line) java.lang.CharacterDataLatin1.toLowerCase(CharacterDataLatin1.java:Unknown line) java.lang.Character.toLowerCase(Character.java:Unknown line) java.lang.Character.toLowerCase(Character.java:Unknown line) TRACE 301251: sun.misc.PerfCounter. (PerfCounter.java:Unknown line) sun.misc.PerfCounter.newPerfCounter(PerfCounter.java:Unknown line) sun.misc.PerfCounter$CoreCounters. (PerfCounter.java:Unknown line) sun.misc.PerfCounter.getReadClassBytesTime(PerfCounter.java:Unknown line) CPU TIME (ms) BEGIN (total = 11886) Wed Feb 3 06:21:21 2016 rank self accum count trace method 1 94.75% 94.75% 1 301665 CUT.main 2 1.10% 95.85% 10000 301663 java.util.HashMap.putVal 3 0.83% 96.69% 10000 301664 java.util.HashMap.put 4 0.75% 97.43% 10000 301657 java.util.HashMap. 5 0.58% 98.01% 10000 301659 java.util.HashMap.hash 6 0.41% 98.43% 10000 301661 java.util.HashMap.newNode 7 0.27% 98.70% 10000 301660 java.util.HashMap.resize 8 0.24% 98.93% 10000 301662 java.util.HashMap.afterNodeInsertion 9 0.22% 99.15% 10016 300952 java.util.HashMap$Node. 10 0.21% 99.36% 10000 301656 java.util.AbstractMap. 11 0.15% 99.51% 10000 301658 java.lang.String.hashCode 12 0.04% 99.55% 1 300163 java.lang.invoke.MethodHandle. 13 0.02% 99.57% 1 300094 java.lang.invoke.MethodHandleImpl. 14 0.02% 99.59% 80 300252 java.lang.CharacterDataLatin1.getProperties 15 0.02% 99.60% 6 301251 sun.misc.PerfCounter. CPU TIME (ms) END
which SEEMS much more accurate.
Heap Profiling uses this:
java -agentlib:hprof=heap=sites CUTwhich gives (shortened form)
TRACE 300318: java.util.HashMap.resize(HashMap.java:703) java.util.HashMap.putVal(HashMap.java:628) java.util.HashMap.put(HashMap.java:611) CUT.main(CUT.java:9) TRACE 300316: java.util.AbstractMap.(AbstractMap.java:73) java.util.HashMap. (HashMap.java:474) CUT.main(CUT.java:8) TRACE 300186: java.util.HashMap$Node. (HashMap.java:284) java.util.HashMap.newNode(HashMap.java:1734) java.util.HashMap.putVal(HashMap.java:630) java.util.HashMap.put(HashMap.java:611) (etc etc) SITES BEGIN (ordered by live bytes) Wed Feb 3 06:28:22 2016 percent live alloc'ed stack class rank self accum bytes objs bytes objs trace name 1 39.18% 39.18% 800000 10000 800000 10000 300318 java.util.HashMap$Node[] 2 23.51% 62.69% 480000 10000 480000 10000 300316 java.util.HashMap 3 15.69% 78.38% 320384 10012 320384 10012 300186 java.util.HashMap$Node 4 7.84% 86.22% 160000 10000 160000 10000 300317 java.lang.Object 5 0.34% 86.56% 7000 53 7000 53 300011 char[] 6 0.07% 86.63% 1504 4 1504 4 300001 java.lang.Thread 7 0.06% 86.70% 1304 11 1304 11 300154 char[] 8 0.06% 86.76% 1296 3 1296 3 300000 java.lang.Thread 9 0.06% 86.82% 1248 11 1248 11 300172 char[] 10 0.06% 86.88% 1248 11 1248 11 300173 char[] 11 0.06% 86.94% 1240 10 1240 10 300176 char[] 12 0.05% 86.99% 1040 1 1040 1 300021 java.lang.invoke.MethodHandle[]
To get help do:
java -agentlib:hprof=help
HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code) hprof usage: java -agentlib:hprof=[help]|[
No comments:
Post a Comment