HPROF: 一个Heap/CPU Profiling工具
Sun JDK自带JVM内存使用分析工具HProf 使用Sun JDK自带JVM内存使用分析工具HProf可以分析JVM堆栈,从而找到占用内存较大的对象。这对应经常出现内存泄漏(OOM)的JAVA系统进行调优很有帮助。
HProf使用方法
· 在WeblogicServer启动脚本中增加-Xrunhprof:heap=sites,重新启动WeblogicServer。
· 使用kill -3 <pid> 或退出WeblogicServer均会生成java.hprof.txt文件,直接打开此文件便可分析JVM的具体运行情况。
从java.hprof.txt记录的JVM堆栈结果中可以发现JVM占用内存较大的对象:
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 4.57% 4.57% 2289696 47702 8392224 174838 4251 [C
2 3.99% 8.57% 2000016 1 2000016 1 12308 [C
3 3.65% 12.22% 1827552 9622 1852672 10082 43265 [C
4 2.58% 14.80% 1293912 53913 3929424 163726 4258 java.lang.String
5 2.05% 16.85% 1028664 7585 3207272 24923 4252 [C
6 2.03% 18.88% 1015816 159 1015816 159 18694 [B
7 1.88% 20.77% 942080 230 2740224 669 20416 [B
8 1.61% 22.37% 805752 2142 2150856 4635 45318 [B
9 1.60% 23.98% 802880 772 802880 772 24710 weblogic.servlet.utils.URLMatchMap$URLMatchNode
10 1.60% 25.57% 799400 19985 2781400 69535 45073 cnc.util.Field
11 1.36% 26.93% 679360 3805 679360 3805 494 [B
12 1.35% 28.28% 674856 28119 5181240 215885 2985 java.util.HashMap$Entry
……
……
96 0.19% 63.73% 94776 3112 94776 3112 9146 [C
97 0.19% 63.92% 93456 3894 123936 5164 23631 java.lang.String
98 0.19% 64.10% 93224 3884 123968 5165 23644 java.lang.String
99 0.19% 64.29% 93192 3883 123936 5164 23636 java.lang.String
100 0.18% 64.47% 89528 238 240264 520 33227 [B
101 0.17% 64.64% 86448 1901 103472 2255 18715 java.lang.Object
102 0.17% 64.81% 85464 676 85768 695 18715 [S
103 0.17% 64.98% 85184 1331 85184 1331 28266 weblogic.ejb20.internal.MethodDescriptor
104 0.17% 65.15% 84224 752 84224 752 24148 weblogic.servlet.internal.dd.ServletDescriptor
105 0.17% 65.32% 84136 528 50471136 348769 63 [C
106 0.16% 65.48% 79968 1428 388976 6946 5503 java.lang.reflect.Method
107 0.15% 65.63% 77520 1615 77520 1615 27967 weblogic.ejb20.deployer.mbimpl.MethodInfoImpl
108 0.15% 65.79% 77056 4816 469808 29363 20250 java.lang.Object
109 0.15% 65.94% 76960 74 76960 74 23695 [B
110 0.15% 66.09% 76104 3171 215040 8960 45071 cnc.util.FyCol
111 0.15% 66.24% 74688 3112 74688 3112 9152 java.util.Hashtable$Entry
112 0.15% 66.39% 74688 3112 74688 3112 9147 java.lang.String
113 0.15% 66.54% 74280 61 794328 788 45313 [C
114 0.14% 66.68% 72480 1510 436032 9084 45353 [C
115 0.14% 66.82% 70720 68 70720 68 25869 [B
116 0.14% 66.97% 70720 68 70720 68 27448 [B
117 0.14% 67.11% 70272 1279 142672 2439 5503 [C
118 0.14% 67.24% 69256 86 69256 86 6584 [S
119 0.13% 67.38% 67056 66 67056 66 28882 java.lang.Object
120 0.13% 67.51% 66176 752 66176 752 24170 weblogic.servlet.internal.dd.UIDescriptor
121 0.13% 67.64% 65688 715 65688 715 25389 [C
122 0.13% 67.77% 65600 4 885600 54 23939 [C
123 0.13% 67.90% 65600 4 623200 38 40639 [C
124 0.13% 68.03% 65576 367 65576 367 51686 [C
125 0.13% 68.17% 65568 2 65568 2 30610 java.util.HashMap$Entry
126 0.13% 68.30% 65568 2 130816 16 43271 java.util.HashMap$Entry
127 0.13% 68.43% 65552 1 65552 1 16617 [B
128 0.13% 68.56% 64600 1615 64600 1615 27969 java.util.HashMap
129 0.13% 68.68% 63888 2662 64032 2668 16951 java.util.HashMap$Entry
130 0.13% 68.81% 63888 2662 64032 2668 16997 java.util.HashMap$Entry
131 0.13% 68.94% 63888 2662 64032 2668 16996 weblogic.rmi.internal.ClientMethodDescriptor
132 0.13% 69.07% 63888 2662 99120 4130 16949 java.lang.String
133 0.13% 69.19% 63888 2662 64032 2668 16976 java.lang.String
134 0.13% 69.32% 63232 152 63232 152 9655 weblogic.utils.collections.ConcurrentHashMap$Entry
135 0.13% 69.45% 63232 152 63232 152 9704 weblogic.utils.collections.ConcurrentHashMap$Entry
136 0.12% 69.57% 62168 3885 82632 5164 23628 [B
137 0.12% 69.69% 61680 406 66904 468 1 [C
138 0.12% 69.82% 61504 4 246016 16 47372 [B
139 0.12% 69.94% 61144 36 91019160 23904 92 [B
140 0.12% 70.06% 61040 763 61040 763 24194 weblogic.servlet.internal.dd.ServletMappingDescriptor
141 0.12% 70.18% 60400 1510 363360 9084 45338 java.util.Hashtable
142 0.12% 70.30% 59544 827 59544 827 24746 weblogic.servlet.internal.ServletRuntimeMBeanImpl
143 0.12% 70.42% 59248 1058 484984 8664 33236 oracle.jdbc.ttc7.TTCItem
144 0.12% 70.53% 58152 232 187176 764 748 [C
145 0.12% 70.65% 57888 2412 161904 6746 16621 java.lang.String
146 0.11% 70.77% 57400 1435 57400 1435 16855 java.util.HashMap
……
……
根据以上的结果,在java.hprof.txt中定位到导致分配大内存的操作如下:
TRACE 63:
java.lang.StringBuffer.expandCapacity(StringBuffer.java:202)
java.lang.StringBuffer.append(StringBuffer.java:401)
java.util.zip.ZipFile.getEntry(ZipFile.java:148)
java.util.jar.JarFile.getEntry(JarFile.java:198)
TRACE 92:
java.util.zip.InflaterInputStream.<init>(InflaterInputStream.java:71)
java.util.zip.ZipFile$1.<init>(ZipFile.java:240)
java.util.zip.ZipFile.getInputStream(ZipFile.java:212)
java.util.zip.ZipFile.getInputStream(ZipFile.java:183)
再进一步分析则需要应用开发人员对应用代码做相应的分析定位。
注意:使用HProf非常消耗资源,切记不要在生产系统使用。
http://www.51testing.com/?uid-3354-action-viewspace-itemid-116628
J2SE中提供了一个简单的命令行工具来对java程序的cpu和heap进行 profiling,叫做HPROF。HPROF实际上是JVM中的一个native的库,它会在JVM启动的时候通过命令行参数来动态加载,并成为 JVM进程的一部分。若要在java进程启动的时候使用HPROF,用户可以通过各种命令行参数类型来使用HPROF对java进程的heap或者(和)cpu进行profiling的功能。HPROF产生的profiling数据可以是二进制的,也可以是文本格式的。这些日志可以用来跟踪和分析 java进程的性能问题和瓶颈,解决内存使用上不优的地方或者程序实现上的不优之处。二进制格式的日志还可以被JVM中的HAT工具来进行浏览和分析,用以观察java进程的heap中各种类型和数据的情况。
在J2SE 5.0以后的版本中,HPROF已经被并入到一个叫做Java Virtual Machine Tool Interface(JVM TI)中。
HPROF的启用
HPROF可以用来展示和跟踪cpu的使用情况,内存分配的统计数据等。不仅如此,它还支持对 java进程完整的内存dump,所有线程的monitor stats数据。HPROF被启用的方式可以如下:
java -agentlib:hprof[=options] ToBeProfiledClass
或者
java -Xrunhprof[:options] ToBeProfiledClass
HPROF如何构建java进程,并发送进程的jvm profiling信息,取决于HPROF在JVM启动时从命令行获取的参数指令。比如,以下指令将会获取java进程的heap allocation的profile:
java -agentlib:hprof=heap=sites ToBeProfiledClass
HPROF 可以被指定的参数非常的多,以下是完整的列表:
java -agentlib:hprof=help
HPROF: Heap and CPU Profiling Agent (JVM TI Demonstration Code)
hprof usage: java -agentlib:hprof=[help]|[<option>=<value>, ...]
Option Name and Value Description Default
--------------------- ----------- -------
heap=dump|sites|all heap profiling all
cpu=samples|times|old CPU usage off
monitor=y|n monitor contention n
format=a|b text(txt) or binary output a
file=<file> write data to file java.hprof[.txt]
net=<host>:<port> send data over a socket off
depth=<size> stack trace depth 4
interval=<ms> sample interval in ms 10
cutoff=<value> output cutoff point 0.0001
lineno=y|n line number in traces? y
thread=y|n thread in traces? n
doe=y|n dump on exit? y
msa=y|n Solaris micro state accounting n
force=y|n force output to <file> y
verbose=y|n print messages about dumps y
Obsolete Options
----------------
gc_okay=y|n
Examples
--------
- Get sample cpu information every 20 millisec, with a stack depth of 3:
java -agentlib:hprof=cpu=samples,interval=20,depth=3 classname
- Get heap usage information based on the allocation sites:
java -agentlib:hprof=heap=sites classname
默认情况下,java进程profiling的信息(sites和dump)都会被写入到一个叫做java.hprof.txt的文件中。大多数情况下,该文件中都会对每个trace,threads,objects包含一个ID,每一个ID代表一个不同的观察对象。通常,traces会从300000开始。
默认,force=y,会将所有的信息全部输出到output文件中,所以如果含有多个JVMs都采用的HRPOF enable的方式运行,最好将force=n,这样能够将单独的JVM的profiling信息输出到不同的指定文件。
interval选项只在 cpu=samples的情况下生效,表示每隔多少毫秒对java进程的cpu使用情况进行一次采集。
msa选项仅仅在Solaris系统下才有效,表示会使用Solaris下的Micro State Accounting功能
Examples
我们可以自己写一个java应用程序,但是例子里将使用一个J2SE中已有的java应用程序,javac。
Heap Allocation Profiles(heap=sites)
以下是对一个java代码文件运行java编译器javac的heap allocation profile日志的一部分:
Command used: javac -J-agentlib:hprof=heap=sites Hello.java
从日志中可以看到程序在运行的每一个部分都消耗了多少内存的heap profile数据。以上日志可以看出,整个程序的heap中有44.73%的被分配给了java.util.zip.ZipEntry对象。同时可以观察到,live data的数量跟所有allocated的总数是匹配atch的,这就说明GC可能在HPROF遍历整个heap搜集信息的很短的时间之前已经做过一次内存回收了。通常情况下,live data的数量是会稍微少于所有allocated的总数的。
Heap Dump (heap=dump)
该选项用来对java进程的heap进行进行完全的dump:
Command used: javac -J-agentlib:hprof=heap=dump Hello.java
这样会产生一个非常大的输出文件,但是可以用任何编辑器进行打开和搜索。但是,更好的观察和分析办法是通过HAT来进行分析和观察。所有用heap=sites选项中获取的信息这里也都可以获取到。另外还加上一些特别的细节数据。如对每个对象的内存分配以及其引用的其他所有的对象。
该选项会使用很多的内存,因为它会将所有对象的内存分配情况全部记录下来,同时也可能会影响到应用程序本身的性能,因为数据的产生会影响对象分配和资源回收。
CPU Usage Sampling Profiles (cpu=samples)
HPROF可以用来搜集java进程中各个threads的cpu使用情况:
HPROF会对java进程中所有的threads进行周期性的stack traces采集。以上count一列就表示在采集中有多少次的stack trace被HPROF发现,并且是active的(而不是指一个method被执行了多少次)。这些stack traces包括cpu的使用,哪些是cpu消耗热点。
那么以上日志中可以看出什么信息呢?第一,统计数据的样本数据是很少的,只有126次的采样,如果是比较大的程序编译,那么应该能够产生更有代表性的数据。第二,该数据跟以上对heap=sites的采集数据比较匹配,ZipFile耗费了比较多的 cpu时间和调用次数。在以上采集中,可以发现,跟ZipFile相关的的性能在javac中都会消耗的比较高,该ZipFile的stack trace如下:
CPU Usage Times Profile (cpu=times)
HPROF可以通过对java应用程序的各个方法中注入code的方式来搜集各个method的执行情况。对每个methods的执行情况进行跟踪,count以及时间消耗的搜集。这种技术叫做 Byte Code Injection。所以这种采集方式的运行比cpu=samples要慢很多,以下是采集数据日志:
这里的count代表着该方法被真正执行了多少次,并且方法thread消耗了多少精确的cpu 时间。
http://blog.csdn.net/ae86_fc/article/details/5960719
值得一提的是这哥们的博客写得不错,对重构hadoop有很牛的经验:http://blog.csdn.net/AE86_FC