Java 故障与诊断指南.doc

Java 故障与诊断指南（根据Java 5.0的文档，参考JDK1.6的特性做一些修改和补充）1 诊断工具与选项1.1 介绍这节介绍JDK5中的各种诊断和监视工具，包括命令行工具，命令行选项和日志文件。所介绍的命令行工具包括JDK5的工具，还有操作系统的工具。尽管JDK5的工具是包含在JDK的下载包中，但是它们也一样能用来诊断和监视仅与JRE5发布的应用程序。通常，这里描述的诊断工具和选项使用各种机制来获取所报告的信息。在多数情况下，这些机制针对特定的虚拟机实现、操作系统和各自的版本。因而，一些工具所报告的信息有重叠的部分。1.1.1 附加说明一些工具是实验性的，如jstack, jinfo, jmap。将来可能会有改变，可能不会包含在建立的JDK发行中。日志的格式和其他命令行工具的输出也是版本特定的。例如，如果一个脚本依赖于致命错误日志文件hs_err_pid.log，那么这个脚本对将来的JDK版本可能就没法工作。以 XX 开头的命令行选项是Java HotSpot VM特定的选项。通常，大部分 XX 选项都是不被支持、没有文档的，它们仅仅是作为VM开发测试的目的而存在的。然而，大部分的 XX 选项对于性能调优和诊断是非常重要的，在这节将做介绍。这里描述的有些工具并不一定存在所有操作系统的JDK版本，如，jstack、jinfo和jmap仅对Solaris和Linux操作系统的JDK版本。除了操作系统的特定工具外，这里还介绍了一些专门针对Solaris10的诊断特征和工具。Solaris10有很多生成环境的高级诊断特征，还有许多本地工具能针对Java运行环境提供特定的信息。1.1.2 事后诊断（post-mortem diagnostics）这里描述的很多工具和选项都是设计为事后诊断的。如果一个应用程序因为JRE的bug崩溃了，有很多选项和工具来获取额外的信息。工具或选项描述和使用致命错误日志致命错误日志hs_err_.log包含许多发生致命错误时的信息。在许多情况下它是检查崩溃什么时候发生的第一手资料。-XX:OnError用来指定一个用户脚本或命令行序列, 让它在致命错误（崩溃）发生时执行。-XX:+ShowMessageBoxOnError可以在致命错误发生时挂接进程。它能启动本地调试器（dbx，gdb，msdev）连接到VM。开发中，这个选项用来在崩溃发生时连接本地调试器非常有用。Jinfo能从java进程或崩溃时的核心文件中获取配置信息。Jmap能从java进程或崩溃时的核心文件中获取内存信息，包括堆直方图。Jstack用来从java进程或崩溃时的核心文件中获取java或本地的栈信息。JdbJDK支持的调试器，包括一个连接器，允许jdb和其他java调试器连接到核心文件。可以用来查看崩溃时发生了什么。本地工具操作系统提供的本地工具。后面有做介绍。1.1.3 挂起的进程有些工具对挂起或死锁的进程也有所帮助。下面列表的工具也不要求应用程序以特定的参数启动。工具或选项描述和使用Ctrl-Break获取线程的转贮信息。同时也执行一个死锁侦查算法，报告同步代码中的死锁。Jstack获取运行时进程中的java和本地的栈信息，甚至包括ctrl-break没有响应的情况。JdbDK支持的调试器，包括一个连接器，允许jdb和其他java调试器连接到一个挂住的进程。可以用来查看挂起或死锁时每个线程在做什么。本地工具操作系统提供的本地工具。后面有做介绍。1.1.4 监视工具下面列表中的工具是用来监视运行中的应用程序的。工具描述和使用jconsoleJDK包含了一个基于JMX的监视工具jconsole。这个工具使用JVM内建的JMX机能来提供应用程序运行的性能和资源消耗信息。JstatJstat使用JVM内建的机能来提供应用程序运行的性能和资源消耗信息。可能使用这个工具来诊断性能问题，尤其是和堆大小和垃圾回收有关的性能问题。这个工具不要求应用程序以任何的特定参数启动。本地工具如Solaris10的dtrace就是一个高级工具。1.1.5 其他工具和选项除了上面列出的工具外，还有很多其他有用的诊断工具和选项。工具或选项描述和使用HPROF Profiler这是包含在JDK中的简单的profiler工具。它能展示CPU的使用、堆的分配情况和监视竞争情况。除外，它还能报告虚拟机中所有监视和线程的全部堆转贮和状态。根据诊断的问题，HPROF在分析性能、锁竞争、内存泄漏和其他问题。Heap Analysis Tool(HAT)HAT没有包含在JDK5中，但是能从中下载。它在诊断不需要的对象滞留（内存泄漏）上非常有用。它能用来浏览对象堆，查看堆中所有能访问的对象，可以了解活动对象有那些引用。JhatJDK6开始提供jhat，它比HAT有更好的改进。-XX:+HeapDumpOnOutOfMemoryError当VM出现OutOfMemoryError时，产生一个堆转贮。-XX:+HeapDumpOnCtrlBreakCtrl-break时，产生一个堆转贮。（在测试linux 5.4,JDK6是没有这个选项）-Xcheck:jni用来诊断使用JNI的应用程序非常有用。1.2 JinfoJinfo 可以从一个运行的java程序中获取应用程序的相关配置信息：环境变量、启动参数等。如roothpserver116 .vnc# jinfo 5058Attaching to process ID 5058, please wait.Debugger attached successfully.Server compiler detected.JVM version is 16.0-b13Java System Properties: = Java(TM) SE Runtime Environmentsun.boot.library.path = /usr/java/jdk1.6.0_18/jre/lib/amd64java.vm.version = 16.0-b13java.vm.vendor = Sun Microsystems Inc.java.vendor.url = /path.separator = : = Java HotSpot(TM) 64-Bit Server VMfile.encoding.pkg = sun.iosun.java.launcher = SUN_STANDARDuser.country = USsun.os.patch.level = = Java Virtual Machine Specificationuser.dir = /home/bmcs/bmi_home/tools/memdbjava.runtime.version = 1.6.0_18-b07java.awt.graphicsenv = sun.awt.X11GraphicsEnvironmentjava.endorsed.dirs = /usr/java/jdk1.6.0_18/jre/lib/endorsedos.arch = amd64java.io.tmpdir = /tmpline.separator = java.vm.specification.vendor = Sun Microsystems I = Linuxsun.jnu.encoding = UTF-8java.library.path = /usr/java/jdk1.6.0_18/jre/lib/amd64/server:/usr/java/jdk1.6.0_18/jre/lib/amd64:/usr/java/jdk1.6.0_18/jre/./lib/amd64:/u02/app/oracle/product/10.2.0/db_1/jdk/jre/lib/i386/server:/u02/app/oracle/product/10.2.0/db_1/jdk/jre/lib/i386:/u02/app/oracle/product/10.2.0/db_1/lib:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/ = Java Platform API Specificationjava.class.version = 50.0piler = HotSpot 64-Bit Server Compileros.version = 2.6.18-164.el5user.home = /home/bmcsuser.timezone = Asia/Shanghaijava.awt.printerjob = sun.print.PSPrinterJobfile.encoding = UTF-8java.specification.version = 1.6java.class.path = /home/bmcs/bmi_home/tools/memdb/lib/ = bmcsjava.vm.specification.version = 1.0java.home = /usr/java/jdk1.6.0_18/jresun.arch.data.model = 64user.language = enjava.specification.vendor = Sun Microsystems I = mixed modejava.version = 1.6.0_18java.ext.dirs = /usr/java/jdk1.6.0_18/jre/lib/ext:/usr/java/packages/lib/extsun.boot.class.path = /usr/java/jdk1.6.0_18/jre/lib/resources.jar:/usr/java/jdk1.6.0_18/jre/lib/rt.jar:/usr/java/jdk1.6.0_18/jre/lib/sunrsasign.jar:/usr/java/jdk1.6.0_18/jre/lib/jsse.jar:/usr/java/jdk1.6.0_18/jre/lib/jce.jar:/usr/java/jdk1.6.0_18/jre/lib/charsets.jar:/usr/java/jdk1.6.0_18/jre/classesjava.vendor = Sun Microsystems Inc.file.separator = /java.vendor.url.bug = /cgi-bin/bugreport.cgisun.io.unicode.encoding = UnicodeLittlesun.cpu.endian = littlesun.cpu.isalist = VM Flags:-XX:+UseParNewGC -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -Xms128m -Xmx512m -Xss128k -XX:NewSize=64m -XX:MaxNewSize=256mJinfo还可以把core文件做为输入参数。例如先运行命令：gcore 5058产生一个core文件在当前目录，名字是core.5058然后运行：jinfo /usr/java/default/bin/java core.5058，也同样可以得出上面的输出。注意：这里的java命令可能得用全路径。Jinfo还有一个特殊的功能，可以给运行中的应用程序加参数。 jinfo -flag +|- to enable or disable the named VM flag jinfo -flag = to set the named VM flag to the given value例如： jinfo flag +HeapDumpOnOutOfMemoryError 1.3 JmapJmap用来输出运行VM或core文件的内存相关数据信息。1.3.1 堆的配置和使用选项-heap用来获取堆的信息，包括：1、 GC算法的特定信息：包括算法名称和算法的特定信息2、 堆的配置：堆的配置可能是一些命令行参数3、 堆的内存使用情况：对每个世代，都打印总的容量、在使用和可用的内存情况。下面就是一个输出例子：roothpserver116 .vnc# jmap -heap 16172Attaching to process ID 16172, please wait.Debugger attached successfully.Server compiler detected.JVM version is 16.0-b13using thread-local object allocation.Parallel GC with 13 thread(s)Heap Configuration: MinHeapFreeRatio = 40 MaxHeapFreeRatio = 70 MaxHeapSize = 536870912 (512.0MB) NewSize = 5439488 (5.1875MB) MaxNewSize = 17592186044415 MB OldSize = 5439488 (5.1875MB) NewRatio = 2 SurvivorRatio = 8 PermSize = 21757952 (20.75MB) MaxPermSize = 88080384 (84.0MB)Heap Usage:PS Young GenerationEden Space: capacity = 86966272 (82.9375MB) used = 5218624 (4.97686767578125MB) free = 81747648 (77.96063232421875MB) 6.000744748492841% usedFrom Space: capacity = 1245184 (1.1875MB) used = 1081344 (1.03125MB) free = 163840 (0.15625MB) 86.84210526315789% usedTo Space: capacity = 1245184 (1.1875MB) used = 0 (0.0MB) free = 1245184 (1.1875MB) 0.0% usedPS Old Generation capacity = 178978816 (170.6875MB) used = 130870200 (124.80754852294922MB) free = 48108616 (45.87995147705078MB) 73.12049712073187% usedPS Perm Generation capacity = 21757952 (20.75MB) used = 16783920 (16.006393432617188MB) free = 4974032 (4.7436065673828125MB) 77.13924545839609% used1.3.2 堆直方图选项-histo能被用来获取类的堆直方图。对每个类，它打印对象的数量、内存的大小和类的名字。需要注意的是VM的内部类是以*为前缀的。1.3.3 获取永久代的信息永久代是虚拟机用来保存所有的反射数据的堆区域，例如类和方法都是保存在这个区域。配置永久代的大小对于需要动态生成和导入大量类的应用程序非常重要。如果永久代不够，应用程序可能会中止并产生这样的错误信息：“Exception in thread XXXX java.lang.OutOfMemoryError: PermGen space“。为了获取永久代的信息，可以使用选项-permstat。它可以打印永久代的对象情况。例如roothpserver116 .vnc# jmap -permstat 16172Attaching to process ID 16172, please wait.Debugger attached successfully.Server compiler detected.JVM version is 16.0-b135561 intern Strings occupying 621128 bytes.finding class loader instances .Finding object size using Printezis bits and skipping over.Finding object size using Printezis bits and skipping over.Finding object size using Printezis bits and skipping over.Finding object size using Printezis bits and skipping over.Finding object size using Printezis bits and skipping over.Finding object size using Printezis bits and skipping over.Finding object size using Printezis bits and skipping over.Finding object size using Printezis bits and skipping puting per loader stat .done.please wait. computing liveness.liveness analysis may be inaccurate .class_loader classes bytes parent_loader alive? type 858 5053472 null live 0x00002aaab4c1aba0 1 3144 0x00002aaab4762140 dead sun/reflect/DelegatingClassLoader0x00002aaaae2766700x00002aaab48c35f0 1 3096 0x00002aaab4762140 dead sun/reflect/DelegatingClassLoader0x00002aaaae2766700x00002aaab4c1b118 1 3096 null dead sun/reflect/DelegatingClassLoader0x00002aaaae2766700x00002aaab4c1b690 1 3144 0x00002aaab4762140 dead sun/reflect/DelegatingClassLoader0x00002aaaae2766700x00002aaab47621c8 0 0 null dead sun/misc/Launcher$ExtClassLoader0x00002aaaae3d89b00x00002aaab4762140 1540 9906096 0x00002aaab47621c8 dead sun/misc/Launcher$AppClassLoader0x00002aaaae4475300x00002aaab5185940 1 3144 0x00002aaab4762140 dead sun/reflect/DelegatingClassLoader0x00002aaaae2766700x00002aaab4938a48 0 0 0x00002aaab4762140 dead java/util/ResourceBundle$RBClassLoader0x00002aaaae7b13e00x00002aaab48c3520 1 3120 0x00002aaab4762140 dead sun/reflect/DelegatingClassLoader0x00002aaaae2766700x00002aaab48c34b8 1 3120 0x00002aaab4762140 dead sun/reflect/DelegatingClassLoader0x00002aaaae276670total = 11 2405 14981432 N/A alive=1, dead=10 N/A 对于每个导入器类，都打印以下信息：1、 导入器类的地址2、 类导入的个数3、 所有导入类元数据的字节数4、 父导入器的地址5、 活或死亡的指示导入器是否要被回收6、 导入器类的名称1.3.4 堆转贮选项-dump能转贮hprof格式的堆。例如： Jmap dump:live, format=b, file=java.dump 上面的命令把堆的活动对象以二进制的格式转贮到文件java.dump中，这个转贮文件可以供hat工具作为输入进行分析。1.4 JstackJstack命令行工具可以依附到指定的进程（或core文件），并打印所有线程的栈的跟踪信息。对于诊断死锁或挂起这样的问题，线程栈的跟踪信息是很有用的。线程的转贮可以这样获取：1、 在应用程序控制台按Ctrl-2、 给进程发QUIT信号(kill QUIT )3、 在程序中使用Threa.getAllStackTraces方法4、 使用调试（如在jdb中使用where命令）下面是jstack的一个输出例子：roothpserver116 # su -l bmcs -c jstack 50582011-02-22 11:40:06Full thread dump Java HotSpot(TM) 64-Bit Server VM (16.0-b13 mixed mode):Attach Listener daemon prio=10 tid=0x0000000046c2b800 nid=0x507b waiting on condition 0x0000000000000000 java.lang.Thread.State: RUNNABLEDestroyJavaVM prio=10 tid=0x00002aaad80c9000 nid=0x13c4 waiting on condition 0x0000000000000000 java.lang.Thread.State: RUNNABLEHSQLDB Server 4506411 prio=10 tid=0x00002aaad804f000 nid=0x13d9 runnable 0x00000000404b7000 java.lang.Thread.State: RUNNABLE at .PlainSocketImpl.socketAccept(Native Method) at .PlainSocketImpl.accept(PlainSocketImpl.java:390) - locked (a .SocksSocketImpl) at .ServerSocket.implAccept(ServerSocket.java:453) at .ServerSocket.accept(ServerSocket.java:421) at org.hsqldb.Server.run(Unknown Source) at org.hsqldb.Server.access$000(Unknown Source) at org.hsqldb.Server$ServerThread.run(Unknown Source)Low Memory Detector daemon prio=10 tid=0x00002aaad8029000 nid=0x13d7 runnable 0x0000000000000000 java.lang.Thread.State: RUNNABLECompilerThread1 daemon prio=10 tid=0x00002aaad8026800 nid=0x13d6 waiting on condition 0x0000000000000000 java.lang.Thread.State: RUNNABLECompilerThread0 daemon prio=10 tid=0x00002aaad8024000 nid=0x13d5 waiting on condition 0x0000000000000000 java.lang.Thread.State: RUNNABLESignal Dispatcher daemon prio=10 tid=0x00002aaad8022000 nid=0x13d4 runnable 0x0000000000000000 java.lang.Thread.State: RUNNABLESurrogate Locker Thread (CMS) daemon prio=10 tid=0x00002aaad8020000 nid=0x13d3 waiting on condition 0x0000000000000000 java.lang.Thread.State: RUNNABLEFinalizer daemon prio=10 tid=0x00002aaad8001000 nid=0x13d2 in Object.wait() 0x0000000040496000 java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)Reference Handler daemon prio=10 tid=0x0000000046a5d000 nid=0x13d1 in Object.wait() 0x0000000040475000 java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked (a java.lang.ref.Reference$Lock)VM Thread prio=10 tid=0x0000000046a58800 nid=0x13d0 runnable Gang worker#0 (Parallel GC Threads) prio=10 tid=0x000000004684e800 nid=0x13c5 runnable Gang worker#1 (Parallel GC Threads) prio=10 tid=0x0000000046850800 nid=0x13c6 runnable Gang worker#2 (Parallel GC Threads) prio=10 tid=0x0000000046852000 nid=0x13c7 runnable Gang worker#3 (Parallel GC Threads) prio=10 tid=0x0000000046854000 nid=0x13c8 runnable Gang worker#4 (Parallel GC Threads) prio=10 tid=0x0000000046856000 nid=0x13c9 runnable Gang worker#5 (Parallel GC Threads) prio=10 tid=0x0000000046857800 nid=0x13ca runnable Gang worker#6 (Parallel GC Threads) prio=10 tid=0x0000000046859800 nid=0x13cb runnable Gang worker#7 (Parallel GC Threads) prio=10 tid=0x000000004685b800 nid=0x13cc runnable Concurrent Mark-Sweep GC Thread prio=10 tid=0x000000004692b800 nid=0x13cf runnable Gang worker#0 (Parallel CMS Threads) prio=10 tid=0x0000000046927800 nid=0x13cd runnable Gang worker#1 (Parallel CMS Threads) prio=10 tid=0x0000000046929800 nid=0x13ce runnable VM Periodic Task Thread prio=10 tid=0x00002aaad8034800 nid=0x13d8 waiting on condition JNI global references: 802同样，也可以使用core文件作为输入，这时可能看到不一样的输出结果。rootdongsongtest2 # jstack /usr/java/default/bin/java core.7439 Attaching to core core.7439 from executable /usr/java/default/bin/java, please wait.Debugger attached successfully.Server compiler detected.JVM version is 14.2-b01Deadlock Detection:No deadlocks found.Thread 7504: (state = BLOCKED) - java.lang.Object.wait(long) bci=0 (Interpreted frame) - java.lang.Object.wait() bci=2, line=485 (Interpreted frame) - java.util.TimerThread.mainLoop() bci=28, line=483 (Interpreted frame) - java.util.TimerThread.run() bci=1, line=462 (Interpreted frame)Thread 7503: (state = BLOCKED) - java.lang.Object.wait(long) bci=0 (Interpreted frame) - org.jboss.resource.connectionmanager.IdleRemover$IdleRemoverRunnable.run() bci=31, line=161 (Interpreted frame) - java.lang.Thread.run() bci=11, line=619 (Interpreted frame)Thread 7487: (state = IN_NATIVE) - .PlainSocketImpl.socketAccept(.SocketImpl) bci=0 (Interpreted frame) - .PlainSocketImpl.accept(.SocketImpl) bci=7, line=390 (Interpreted frame) - .ServerSocket.implAccept(.Socket) bci=60, line=453 (Interpreted frame) - .ServerSocket.accept() bci=48, line=421 (Interpreted frame) - org.jboss.invocation.pooled.server.PooledInvoker.run() bci=11, line=261 (Interpreted frame) - java.lang.Thread.run() bci=11, line=619 (Interpreted frame)Thread 7457: (state = BLOCKED)Thread 7456: (state = BLOCKED)Thread 7455: (state = BLOCKED) - java.lang.Object.wait(long) bci=0 (Interpreted frame) - java.lang.ref.ReferenceQueue.remove(long) bci=44, line=118 (Interpreted frame) - java.lang.ref.ReferenceQueue.remove() bci=2, line=134 (Interpreted frame) - java.lang.ref.Finalizer$FinalizerThread.run() bci=3, line=159 (Interpreted frame)Thread 7454: (state = BLOCKED) - java.lang.Object.wait(long) bci=0 (Interpreted frame) - java.lang.Object.wait() bci=2, line=485 (Interpreted frame) - java.lang.ref.Reference$ReferenceHandler.run() bci=46, line=116 (Interpreted frame)在输出的开头，会给出当前有没有死锁的情况。下面来解析一下其他输出的内容，以下面的输出为例。Thread 7454: (state = BLOCKED) - java.lang.Object.wait(long) bci=0 (Interpreted frame) - java.lang.Object.wait() bci=2, line=485 (Interpreted frame) - java.lang.ref.Reference$ReferenceHandler.run() bci=46, line=116 (Interpreted frame)数值 7454是进程的PID号，通过top H能看见这个pid值。BLOCKED是线程的状态，线程的状态有：UNINTIALIZED线程还没有创建。这个状态正常情况下不会发生，除非有严重的bug，如内存问题。NEW线程已经被创建，但是还没有启动运行。IN_NATIVE线程在运行本地代码。IN_VM线程运行VM代码。IN_JAVA线程在运行java代码。BLOCKED线程被阻塞_TRANS线程正改变到其他状态。bci指的是字节码的索引。line是代码的行号。Interpreted frame指方法是被解释的，还有可能是被编译的。注：对于本地代码，bci和line都不会被打印。1.5 JconsoleJconsole是遵从JMX的监视工具。通过使用VM的JMX内建机制能提供应用程序的性能和资源消耗的信息。这个工具包含在JDK的下载包中，但也可以发布到JRE的应用中。Jconsole可以依附到以JMX代理启动的任何程序。Jconsole可以显示线程使用、内存消耗、详细的类导入信息、运行时编译和操作系统等信息。Jconsole能显示的信息，包括：Summary Uptime:：JVM运行多长时间 Total compile time:：运行时编译花费的总时间 Process CPU time：JVM消耗的总的CPU时间Memory Current heap size：当然堆占用的字节数（Kbyte） Committed memory：堆分配使用的总内存 Maximum heap size：堆可占用的最大字节数(Kbyte) Objects pending for finalization：等待中止的对象数 Garbage collector information：GC信息，包括回收器的名称、回收执行次数和GC花的时间Threads Live threads：当前活动线程数，包括daemon线程和非daemon线程 Peak：JVM启动以来，达到的最大活动线程数 Daemon threads：当前活动的daemon线程数 Total started：JVM启动以来，总共启动的线程数（包括daemon线程，非daemon线程和中止的线程）Classes Current classes loaded：当前导入内存的类总数 Total classes loaded：JVM启动以来，导入到内存的类总数，包括已经被卸载的类 Total classes unloaded：JVM启动以来