相关介绍
写这篇文章的起因
前一段时间我使用了OptimizedIt进行UniPortal系统的测试时，遇到过两次系统自动退出的问题，于是开始分析OptimizedIt及它实现时所使用的技术，发现它在命令行中使用了
-Xbootclasspath/p:"C:\Optimizeit\OptimizeitEntSuite60\lib\bootcp\oibcp_1.4.2_06.jar"
这一行成了我心中的第一个疑点。
接着，我在想，如果让我设计实现OptimizedIt，我会如何去做？我发现仅仅替换JDK的一个Jar包，是实现不了的。同时我想到了eclipse内部写了很多与系统剖析相关的代码，这使我想到，JDK应该有相类似的机制，于是我查找到google里查了一下” java virtual machine profile”,结果找到了JVMPI,我的答案也就找到了。
知道了OptimizedIt的实现原理，我产生了几点疑问：
JDK版本之间不可能100%的代码级兼容，那么使用-Xbootclasspath/p:来替换系统的部分类，会不会有问题？我觉得，肯定会有，只是Borland公司没有告诉我们罢了。
有问题，如何解决？不使用OptimzedIt，仅仅使用JDK提供的包可以不可以？如果可以话，可以最大限度避免第三方工具包引入的问题。
带着疑问，我找到了JDK自带的HProf工具。因为问题具有一定的共性，不敢独享，现在拿出来与大家共享。
本文中所使用命令行的解释
本文有点长，照顾到没有时间看此文档的人，特将文档中所用到的命令行参数列于此，以起到备找或简介之用。
使用java -Xrunhprof:help
会列出所有与Java Virutal Machine Profile相关的参数及解释说明。
Hprof usage: -Xrunhprof[: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 ascii or binary output a
file=<file> write data to file java.hprof(.txt for ascii)
net=<host>:<port> send data over a socket write to file
depth=<size> stack trace depth 4
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
gc_okay=y|n GC okay during sampling y
Example: java -Xrunhprof:cpu=samples,file=log.txt,depth=3 FooClass
java –verbose:gc或java –Xloggc:<log filename>
此参数的作用是显示JVM进行垃圾回收时的相关信息。
运行虚拟机剖析器代理的原理及HProf代理的使用
用户可以为虚拟机指定剖析器代理，并通过命令行指定相关参数选项，例如，假设用户指定如下参数：
java -Xrunmyprofiler:heapdump=on,file=log.txt ToBeProfiledClass
Java虚拟机就会试着从Java的库目录下装载名为myprofiler的动态库，
在Microsoft Windows下，这个动态库就是%JAVA_HOME%\bin\myprofiler.dll
在SPARC/Solaris下，这个动态库就是$JAVA_HOME/lib/sparc/libmyprofiler.so
如果动态库中Java的库目录下没有找到，Java虚拟机就会以给定操作系统下加载普通动态库的方式查找这个库文件：
在Microsoft Windows下，虚拟机会查找当前目录、Windows的系统目录及环境变量PATH中定义的路径来查找库文件。
在Solaris下，虚拟机会查找在环境变量LD_LIBRARY_PATH中定义的路径。
Java虚拟机在装载了剖析器代理的库文件后，会查找下面的入口点：
jint JNICALL JVM_OnLoad(JavaVM *jvm, char *options, void *reserved);
Java虚拟机在调用此函数时，会将虚拟机的实例指针做为第一个参数传递给此函数，将"heapdump=on,file=log.txt"以string的方式做为每二个参数传送给此函数，第三个参数做为保留参数，要设置为NULL。
这样Java虚拟机就、它的剖析器代理和用户的Java应用系统一起启动，开始了相关的统计工作。
具体Java虚拟机剖析器代理是如何使用JVMPI进行工作的，在此篇文章中不进行深入介绍，此文中关注点是如何利用Java虚拟机本身的机制来对Java应用系统的运行时状态进行跟踪分析。
HProf是JDK1.2以后版本中自己带的一个简单实现的剖析器代理，它与JVMPI进行交互，呈现给用户一些系统运行时的信息。我们可以通过下面的命令行来激活它：
java -Xrunhprof 其它参数 要运行的系统main函所在的类
根据我们要获取的系统信息的请求，HProf指示Java虚拟机将相关的剖析信息发送给它，HProf收集这些事件信息，在默认的情况下，会将这些事件信息写入到一个文件中。例如，运行下面的命令，HProf会将堆分配相关的剖析信息存放到前当目录下的java.hprof.txt文件中：
java -Xrunhprof:heap=sites ProgName
例如我使用如下命令行运行Tomcat-5.0.30：
"D:\java\j2sdk1.4.2_08\bin\java" -verbose:gc -Xrunhprof: cpu=samples,heap=sites -Djava.endorsed.dirs="D:\jakarta-tomcat-5.0.30\common\endorsed" -classpath "D:\java\j2sdk1.4.2_08\lib\tools.jar;D:\jakarta-tomcat-5.0.30\bin\bootstrap.jar" -Dcatalina.base="D:\jakarta-tomcat-5.0.30" -Dcatalina.home="D:\jakarta-tomcat-5.0.30" -Djava.io.tmpdir="D:\jakarta-tomcat-5.0.30\temp" org.apache.catalina.startup.Bootstrap start
信息分析
分配对象统计：
在产生的文件()中，有如下片断：
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 5.16% 5.16% 385000 69 6042096 1363 110 [B
2 4.59% 9.75% 342224 18 342224 18 8520 [B
3 3.35% 13.10% 249688 770 268624 808 1 [C
4 2.05% 15.15% 152824 2737 330512 5990 3678 [C
5 1.57% 16.71% 116736 13 1683912 453 11675 [B
6 1.54% 18.25% 114800 7 180400 11 5040 [C
7 1.41% 19.66% 105216 552 105216 552 484 [B
8 1.40% 21.06% 104096 4 242952 9 11851 [B
9 1.26% 22.32% 94272 524 12036552 73822 75 [C
10 1.21% 23.53% 90288 11 164160 20 5038 [B
11 1.19% 24.72% 88808 5 1238928 77 11671 [B
12 1.09% 25.81% 81368 1453 124152 2217 1309 java.lang.reflect.Method
13 1.01% 26.83% 75600 1575 331680 6910 6657 [C
14 1.01% 27.84% 75152 13 75152 13 9736 [B
15 0.95% 28.79% 70952 690 70952 690 5699 [C
16 0.93% 29.72% 69360 2890 110520 4605 5066
java.util.HashMap$Entry
……
在这里
B代表Ｂyte对象
Ｃ代表Ｃharacter对象
Ｌ代表Ｌong对象
其它的，都应该可以看出类名
各列分别外表什么含义呢？
| 列名 | 含义 |
| Rank | 根据已经分配内存多少进行排序所得名次 |
| Percent self | 特定方法为指定的类对象分配内存的大小与分配内存总数的比例 |
| Percent ccum | 截止最后一次采样，Percent self部分的累计值 |
| Live bytes | 当前使用的字节数(the number of bytes currently in use ("live")) |
| Live objs | 当前使用的对象数(the number of objects currently in use ("live"))) |
| alloc'ed bytes | 已经分配的字节数(the number of bytes originally allocated ("alloc'ed")) |
| alloc'ed objs | 已经分配的对象数(he number of bytes originally allocated ("alloc'ed")) |
| stack trace | 代表内存分配动态上下文中的TRACE id |
| Class name | 也就是类名 |
这时我们仅仅取出了其中的一部分信息放在这里，有兴趣的兄弟可以打开上面我所附的文件，以观其全貌。堆信息最主要的部分是在Tomcat启动过程中，不同部分所进行的大量的内存分配。上面的黑体信息告诉我们，5.16%被引用的对象是Byte类型的，注意，这里所讲到的被引用对象仅仅是指定点上全部生成对象的一部分，其它的生成的对象已经被垃圾回收器回收了。
内存分配态上下文：
我们看到了内存中所创建的对象及其比例了，但如何将内存分配点与源代码相关联起来呢？
一个很好的方法是记录所有会进行堆栈内存分配的动态上下文。那么HProf是如何表现内存上下文信息的呢？
先看下面的片断：
TRACE 17364:
java.util.HashMap.keySet(HashMap.java:857)
org.apache.catalina.core.ApplicationContext.getAttributeNames(ApplicationContext.java:190)
org.apache.catalina.core.ApplicationContextFacade.getAttributeNames(ApplicationContextFacade.java:328)
org.apache.struts.action.ActionServlet.destroyModules(ActionServlet.java:713)
TRACE 17307:
java.util.jar.JarFile.getBytes(JarFile.java:338)
java.util.jar.JarFile.getManifest(JarFile.java:157)
org.apache.catalina.loader.WebappClassLoader.findResourceInternal(WebappClassLoader.java:1790)
org.apache.catalina.loader.WebappClassLoader.findResource(WebappClassLoader.java:920)
TRACE 17036:
org.apache.jk.common.MsgAjp.<init>(MsgAjp.java:45)
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:658)
org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:866)
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
TRACE 16681:
org.apache.commons.modeler.BaseModelMBean.setManagedResource(BaseModelMBean.java:810)
org.apache.commons.modeler.ManagedBean.createMBean(ManagedBean.java:438)
org.apache.commons.modeler.Registry.registerComponent(Registry.java:862)
org.apache.commons.modeler.Registry.registerComponent(Registry.java:1088)
内存分配和动态上下文是如何关联起来的呢？
在上以上面信息为例
1 5.16% 5.16% 385000 69 6042096 1363 110 [B
这一行中说明有5.16%被引用的对象是Byte类型的,
那么这些对象是谁分配的呢？
我们看到倒数第二项是110,它又代表什么意思呢？
这里的110就是Trace ID,它会将分配的对象与动态上下文联系起来。我们在java.hprof.txt文件中查找110会在TRACE部分找到下面几行：
TRACE 110:
java.util.zip.InflaterInputStream.<init>(InflaterInputStream.java:71)
java.util.zip.ZipFile$1.<init>(ZipFile.java:241)
java.util.zip.ZipFile.getInputStream(ZipFile.java:213)
java.util.zip.ZipFile.getInputStream(ZipFile.java:184)
这就说明这些Byte对象都是由java.util.zip.InflaterInputStream.<init>(InflaterInputStream.java:71)产生的。
有了这些，我们定位内存泄漏时会更加容易。
同样，你可以找到下面一行的内存分配上下文
12 1.09% 25.81% 81368 1453 124152 2217 1309 java.lang.reflect.Method
它就是，
TRACE 1309:
java.lang.reflect.Method.copy(Method.java:90)
java.lang.reflect.ReflectAccess.copyMethod(ReflectAccess.java:88)
sun.reflect.ReflectionFactory.copyMethod(ReflectionFactory.java:270)
java.lang.Class.copyMethods(Class.java:1979)
动态上下文的每一帧都包含类名、方法名、源代码文件名和行号。用户可以为HProf设置动态上下文的最大帧数，默认为4帧。动态上下文中不仅指明了哪一些方法进行了堆栈内存分配，而且指明了哪些方法调用了这些方法进行了内存分配。
CPU资源使用情况
HPROF支持对CPU资源使用情况的统计功能，例如，
CPU SAMPLES BEGIN (total = 56505) Mon Nov 28 12:09:30 2005
rank self accum count trace method
1 94.66% 94.66% 53489 16793 java.net.PlainSocketImpl.socketAccept
2 0.86% 95.52% 485 12481 java.io.FileInputStream.readBytes
3 0.70% 96.22% 395 13176 java.io.FileInputStream.close0
4 0.58% 96.79% 325 8297 java.util.zip.ZipFile.open
5 0.26% 97.06% 148 15986 java.io.WinNTFileSystem.delete
6 0.23% 97.28% 128 8557 java.io.FileInputStream.readBytes
7 0.14% 97.42% 77 11890 java.io.FileOutputStream.open
8 0.13% 97.55% 73 15988 java.io.WinNTFileSystem.delete
HPROF代理定期的从当前所有运行线程中采样，记录最频繁的堆栈活动信息。上面片断的“count”一列，显示了特定方法在采样过程中处于“激活状态”中的次数。这些信息可以给出哪些点使用CPU最频繁。
内存和性能
识别内存泄漏
内存泄漏常见的一个特征就是应用系统经常抛出OutOfMemoryError，或者因为频繁的内存垃圾回收而表现出来比较差的性能。
如何找到内存泄漏的原因呢？
这里再介绍一下另外一个Java虚拟机的参数：
-verbose:gc: 使用此开关让Java虚拟机垃圾回收时将垃圾回收的信息打印到控制台上。如下面的信息：
……
[GC 1643K->1192K(1984K), 0.0012577 secs]
[GC 1703K->1226K(1984K), 0.0011907 secs]
[GC 1730K->1291K(1984K), 0.0013384 secs]
[GC 1803K->1361K(1984K), 0.0015767 secs]
[GC 1873K->1438K(1984K), 0.0017385 secs]
[GC 1950K->1402K(1984K), 0.0011247 secs]
[GC 1914K->1440K(1984K), 0.0015720 secs]
[GC 1952K->1486K(2112K), 0.0014097 secs]
[Full GC 1486K->1097K(2112K), 0.0399934 secs]
[GC 1607K->1134K(2408K), 0.0009208 secs]
[GC 1646K->1146K(2408K), 0.0009694 secs]
[GC 1638K->1208K(2408K), 0.0012376 secs]
[GC 1720K->1296K(2408K), 0.0025305 secs]
[GC 1808K->1339K(2408K), 0.0015829 secs]
[GC 1851K->1332K(2408K), 0.0008264 secs]
[GC 1844K->1434K(2408K), 0.0028990 secs]
2005-11-28 15:01:24 org.apache.coyote.http11.Http11Protocol init
信息: Initializing Coyote HTTP/1.1 on http-8080
[GC 1946K->1502K(2408K), 0.0027861 secs]
2005-11-28 15:01:24 org.apache.catalina.startup.Catalina load
信息: Initialization processed in 1110 ms
[GC 2014K->1529K(2408K), 0.0026643 secs]
[GC 2041K->1592K(2408K), 0.0024995 secs]
[GC 2104K->1622K(2408K), 0.0017812 secs]
……
在上面的信息中，包含了垃圾回收使用了多长时间、当前堆的使用情况（the current heap usage）、回收了多少内存（how much memory was recovered）等。打印这些垃圾回收的信息，并不会给你的系统带来很多困扰，所以当你需要进行内存相关问题分析或需要查看垃圾回收情况时，在你的产品中打开这一开关是很有必要的。
一旦你确认你的产品或系统中有内存泄漏问题，首先要找到是什么类型的对象引起了内存泄漏？这是要从上面我们讲到的java.hprof.txt文件中取出信息来进行分析的。
首先看一下，在分配对象统计表中占内存最大的对象
下一步，从内存分配上下文中，看一下哪一段代码分配了这些对象
下一步，结合控制台上打印出来的信息，看一下这些对象为什么没有被回收
通过这些有针对性的代码分析及Review，一般情况下的内存泄漏都会暴露出来。
查找性能瓶颈
造成性能瓶颈的原因有很多，最常见的包括内存缓慢泄漏、部分系统出现死循环或系统资源之间出现死锁等造成的。
分析此类问题，可以首先从占用CPU时间最多的类或方法开始分析，如下面的数据：
1 1.45% 1.45% 34544 4754 java.util.zip.ZipFile.getEntry
2 1.26% 2.71% 69815 4662 java.lang.StringBuffer.expandCapacity
3 1.04% 3.75% 221930 4654 org.apache.xerces.util.XMLChar.isInvalid
4 0.99% 4.75% 388332 10638 org.apache.xerces.util.XMLChar.isValid
5 0.97% 5.72% 37287 4661 java.lang.StringBuffer.toString
6 0.87% 6.59% 37287 4554 java.lang.StringBuffer.<init>
java.util.zip.ZipFile.getEntry占用CPU的时间是最长的，我们首先就要分析，
代码中能不能减少此方法的使用？
如果不能，那么能不能优化此方法？
调用此方法的逻辑块是不是出现了死循环？
当然这里java.util.zip.ZipFile.getEntry是JDK自带的类，不是我们产品自己的类，所在优化的方向应该放在如何减少使用此方法和检查是不是出现了死循环上。
353
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
