给一个系统定位问题的时候,知识、经验是关键基础,数据是依据,工具是运用知识处理数据的手段。这里说的数据包括:运行日志、异常堆栈、GC日志、线程快照(threaddump/javacore文件)、堆转储快照(heapdump/hprof文件)等。经常使用适当的虚拟机监控和分析的工具可以加快我们分析数据、定位解决问题的速度。
JDK的bin目录下有很多用于监视虚拟机和故障处理的工具,这些工具都非常稳定而且功能强大,能在处理应用程序性能问题、定位故障是发挥很大的作用。比较细心的读者可能会注意到这些工具的程序体积都异常小巧。并非JDK开发团队刻意把它们制作得如此精炼来炫耀编程水平,而是因为这些命令行工具大多是jdk/lib/tools.jar类库的一层薄包装而已,它们主要的功能代码是在tools类库中实现的。
接下来介绍常用的一些工具。
JVM Process Status Tool,显示指定系统内所有的HotSpot虚拟机进程。 命令格式:
jps [ options ] [ hostid ]
jps可以通过RMI协议查询开启了RMI服务的远程虚拟机进程状态,hostid为RMI注册表中注册的主机名。
jps工具主要选项: 其中[ options ]、[ hostid ]参数也可以不写。
示例:
$ ./jps -l -m 21332 org.tanukisoftware.wrapper.WrapperSimpleApp org.cellphone.gateway.WarehouseGateway 7516 kafka.Kafka config/server.properties 18140 sun.tools.jps.Jps -l -mjstat(JVM statistics Monitoring)是用于监视虚拟机运行时状态信息的命令,它可以显示出虚拟机进程中的类装载、内存、垃圾收集、JIT编译等运行数据。
命令格式:
jstat [ option vmid [interval[s|ms] [count]] ]
对于命令格式中的VMID与LVMID需要特别说明一下:如果是本地虚拟机进程,VMID与LVMID是一致的,如果是远程虚拟机进程,那VMID的格式应当是:
[protocol:][//]lvmid[@hostname[:port]/servername]
参数interval和count代表查询间隔和次数,如果省略这两个参数,说明只查询一次。假设需要每250毫秒查询一次进程2764垃圾收集状况,一共查询20次,那命令应当是:
jstat -gc 2764 250 20
选项option代表着用户希望查询的虚拟机信息,主要分为3类:类装载、垃圾收集、运行期编译状况。
jstat工具主要选项:
option参数详解
-class 监视类装载、卸载数量、总空间以及耗费的时间。
$ ./jstat -class 21332 Loaded Bytes Unloaded Bytes Time 9263 16938.8 0 0.0 5.28 Loaded : 加载class的数量Bytes : class字节大小Unloaded : 未加载class的数量Bytes : 未加载class的字节大小Time : 加载时间输出JIT编译过的方法数量耗时等。
$ ./jstat -compiler 21332 Compiled Failed Invalid Time FailedType FailedMethod 10998 2 0 84.47 1 org/jboss/netty/channel/socket/nio/NioClientSocketPipelineSink$Boss run Compiled : 编译数量Failed : 编译失败数量Invalid : 无效数量Time : 编译耗时FailedType : 失败类型FailedMethod : 失败方法的全限定名垃圾回收堆的行为统计,常用命令。
$ ./jstat -gc 21332 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 26176.0 26176.0 0.0 3352.3 209792.0 29733.0 262144.0 31656.1 53632.0 51814.7 6528.0 6124.3 417 3.690 0 0.000 3.690$ ./jstat -gc 21332 2000 20
这个命令意思就是每隔2000ms输出1262的gc情况,一共输出20次。
同-gc,不过还会输出Java堆各区域使用到的最大、最小空间。
$ ./jstat -gccapacity 21332 NGCMN NGCMX NGC S0C S1C EC OGCMN OGCMX OGC OC MCMN MCMX MC CCSMN CCSMX CCSC YGC FGC 262144.0 262144.0 262144.0 26176.0 26176.0 209792.0 262144.0 262144.0 262144.0 262144.0 0.0 1095680.0 53632.0 0.0 1048576.0 6528.0 417 0 NGCMN : 新生代占用的最小空间NGCMX : 新生代占用的最大空间OGCMN : 老年代占用的最小空间OGCMX : 老年代占用的最大空间OGC:当前年老代的容量 (KB)OC:当前年老代的空间 (KB)PGCMN : perm占用的最小空间PGCMX : perm占用的最大空间同-gc,不过输出的是已使用空间占总空间的百分比。
$ ./jstat -gcutil 21332 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 12.81 14.17 12.08 96.61 93.82 417 3.690 0 0.000 3.690垃圾收集统计概述(同-gcutil),附加最近两次垃圾回收事件的原因。
$ ./jstat -gccause 21332 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC 0.00 12.81 14.22 12.08 96.61 93.82 417 3.690 0 0.000 3.690 Allocation Failure No GC LGCC:最近垃圾回收的原因GCC:当前垃圾回收的原因统计新生代的行为。
$ ./jstat -gcnew 21332 S0C S1C S0U S1U TT MTT DSS EC EU YGC YGCT 26176.0 26176.0 0.0 3352.3 6 6 13088.0 209792.0 30207.4 417 3.690 TT:Tenuring threshold(提升阈值)MTT:最大的tenuring thresholdDSS:survivor区域大小 (KB)新生代与其相应的内存空间的统计。
$ ./jstat -gcnewcapacity 21332 NGCMN NGCMX NGC S0CMX S0C S1CMX S1C ECMX EC YGC FGC 262144.0 262144.0 262144.0 26176.0 26176.0 26176.0 26176.0 209792.0 209792.0 417 0 NGC:当前年轻代的容量 (KB)S0CMX:最大的S0空间 (KB)S0C:当前S0空间 (KB)ECMX:最大eden空间 (KB)EC:当前eden空间 (KB)统计旧生代的行为。
$ ./jstat -gcold 21332 MC MU CCSC CCSU OC OU YGC FGC FGCT GCT 53632.0 51814.7 6528.0 6124.3 262144.0 31656.1 417 0 0.000 3.690统计旧生代的大小和空间。
$ ./jstat -gcoldcapacity 21332 OGCMN OGCMX OGC OC YGC FGC FGCT GCT 262144.0 262144.0 262144.0 262144.0 417 0 0.000 3.690hotspot编译方法统计。
$ ./jstat -printcompilation 21332 Compiled Size Type Method 10998 2602 1 org/springframework/web/util/UrlPathHelper getPathWithinApplication Compiled:被执行的编译任务的数量Size:方法字节码的字节数Type:编译类型Method:编译方法的类名和方法名。类名使用"/" 代替 “.” 作为空间分隔符. 方法名是给出类的方法名. 格式是一致于HotSpot - XX:+PrintComplation 选项jmap(JVM Memory Map)命令用于生成heap dump文件,如果不使用这个命令,还阔以使用-XX:+HeapDumpOnOutOfMemoryError参数来让虚拟机出现OOM的时候·自动生成dump文件。 jmap不仅能生成dump文件,还阔以查询finalize执行队列、Java堆和永久代的详细信息,如当前使用率、当前使用的是哪种收集器等。 命令格式:
jmap [ option ] vmid
jmap工具主要选项:
常用格式:
-dump::live,format=b,file= pid
dump堆到文件,format指定输出格式,live指明是活着的对象,file指定文件名。
$ ./jmap -dump:live,format=b,file=dump.hprof 21332 Dumping heap to /home/ubuntu/app/jdk/bin/dump.hprof ... Heap dump file createddump.hprof这个后缀是为了后续可以直接用MAT(Memory Anlysis Tool)打开。
打印等待回收对象的信息。
$ sudo ./jmap -finalizerinfo 21332 Attaching to process ID 21332, please wait... Debugger attached successfully. Server compiler detected. JVM version is 25.161-b12 Number of objects pending for finalization: 0可以看到当前F-QUEUE队列中并没有等待Finalizer线程执行finalizer方法的对象。
打印heap的概要信息,GC使用的算法,heap的配置及wise heap的使用情况,可以用此来判断内存目前的使用情况以及垃圾回收情况。
$ sudo ./jmap -heap 21332 Attaching to process ID 21332, please wait... Debugger attached successfully. Server compiler detected. JVM version is 25.161-b12 using parallel threads in the new generation. using thread-local object allocation. Concurrent Mark-Sweep GC Heap Configuration: MinHeapFreeRatio = 40 MaxHeapFreeRatio = 70 MaxHeapSize = 536870912 (512.0MB) NewSize = 268435456 (256.0MB) MaxNewSize = 268435456 (256.0MB) OldSize = 268435456 (256.0MB) NewRatio = 2 SurvivorRatio = 8 MetaspaceSize = 134217728 (128.0MB) CompressedClassSpaceSize = 1073741824 (1024.0MB) MaxMetaspaceSize = 268435456 (256.0MB) G1HeapRegionSize = 0 (0.0MB) Heap Usage: New Generation (Eden + 1 Survivor Space): capacity = 241631232 (230.4375MB) used = 4158608 (3.9659576416015625MB) free = 237472624 (226.47154235839844MB) 1.721055662208435% used Eden Space: capacity = 214827008 (204.875MB) used = 4158608 (3.9659576416015625MB) free = 210668400 (200.90904235839844MB) 1.9357938458091823% used From Space: capacity = 26804224 (25.5625MB) used = 0 (0.0MB) free = 26804224 (25.5625MB) 0.0% used To Space: capacity = 26804224 (25.5625MB) used = 0 (0.0MB) free = 26804224 (25.5625MB) 0.0% used concurrent mark-sweep generation: capacity = 268435456 (256.0MB) used = 26038384 (24.832138061523438MB) free = 242397072 (231.16786193847656MB) 9.700053930282593% used 20159 interned Strings occupying 2604800 bytes.可以很清楚的看到Java堆中各个区域目前的情况。 -histo 打印堆的对象统计,包括对象数、内存大小等等 (因为在dump:live前会进行full gc,如果带上live则只统计活对象,因此不加live的堆大小要大于加live堆的大小 )。
$ ./jmap -histo:live 21332 | more num #instances #bytes class name ---------------------------------------------- 1: 55397 8014576 [C 2: 2561 7430632 [B 3: 54263 1302312 java.lang.String 4: 9892 1102904 java.lang.Class 5: 20234 647488 java.util.concurrent.ConcurrentHashMap$Node 6: 9364 526024 [Ljava.lang.Object; 7: 5179 455752 java.lang.reflect.Method 8: 11743 375776 java.util.HashMap$Node 9: 3925 328232 [Ljava.util.HashMap$Node; 10: 7953 318120 java.util.LinkedHashMap$Entry 11: 228 260424 [Ljava.util.concurrent.ConcurrentHashMap$Node; 12: 14883 238128 java.lang.Object 13: 4078 228368 java.util.LinkedHashMap 14: 3464 148784 [I 15: 2192 109768 [Ljava.lang.String;xml class name是对象类型,说明如下:
B byteC charD doubleF floatI intJ longZ boolean[ 数组,如[I表示int[][L+类名 其他对象印Java堆内存的永久保存区域的类加载器的智能统计信息。对于每个类加载器而言,它的名称、活跃度、地址、父类加载器、它所加载的类的数量和大小都会被打印。此外,包含的字符串数量和大小也会被打印。
强制模式。如果指定的pid没有响应,请使用jmap -dump或jmap -histo选项。此模式下,不支持live子选项。
jhat(JVM Heap Analysis Tool)命令是与jmap搭配使用,用来分析jmap生成的dump,jhat内置了一个微型的HTTP/HTML服务器,生成dump的分析结果后,可以在浏览器中查看。在此要注意,一般不会直接在服务器上进行分析,因为jhat是一个耗时并且耗费硬件资源的过程,一般把服务器生成的dump文件复制到本地或其他机器上进行分析。
命令格式:
jhat [dumpfile]
jstat工具主要选项: 示例:
$ ./jhat -J-Xmx512m dump.hprof Reading from dump.hprof... Dump file created Wed Aug 15 23:41:00 CST 2018 Snapshot read, resolving... Resolving 330324 objects... Chasing references, expect 66 dots.................................................................. Eliminating duplicate references.................................................................. Snapshot resolved. Started HTTP server on port 7000 Server is ready.中间的-J-Xmx512m是在dump快照很大的情况下分配512M内存去启动HTTP服务器,运行完之后就可在浏览器打开Http://localhost:7000进行快照分析 堆快照分析主要在最后面的Heap Histogram里,里面根据class列出了dump的时候所有存活对象。 分析同样一个dump快照,MAT需要的额外内存比jhat要小的多的多,所以建议使用MAT来进行分析,当然也看个人偏好。 分析 打开浏览器Http://localhost:7000,该页面提供了几个查询功能可供使用:
All classes including platform Show all members of the rootset Show instance counts for all classes (including platform) Show instance counts for all classes (excluding platform) Show heap histogram Show finalizer summary Execute Object Query Language (OQL) query一般查看堆异常情况主要看这个两个部分: Show instance counts for all classes (excluding platform),平台外的所有对象信息。如下图: Show heap histogram 以树状图形式展示堆情况。如下图: 具体排查时需要结合代码,观察是否大量应该被回收的对象在一直被引用或者是否有占用内存特别大的对象无法被回收。 一般情况,会down到客户端用工具来分析。
jstack用于生成java虚拟机当前时刻的线程快照。线程快照是当前java虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待等。 线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做什么事情,或者等待什么资源。 如果java程序崩溃生成core文件,jstack工具可以用来获得core文件的java stack和native stack的信息,从而可以轻松地知道java程序是如何崩溃和在程序何处发生问题。另外,jstack工具还可以附属到正在运行的java程序中,看到当时运行的java程序的java stack和native stack的信息, 如果现在运行的java程序呈现hung的状态,jstack是非常有用的。
jstack命令格式:
jstack [ option ] vmid
jstack工具主要选项:
示例:
$ ./jstack -l 21332 | more 2018-08-16 00:15:47 Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.161-b12 mixed mode): "Attach Listener" #134 daemon prio=9 os_prio=0 tid=0x00007f57e415f000 nid=0x513a waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "DubboResponseTimeoutScanTimer" #69 daemon prio=5 os_prio=0 tid=0x00007f57f800b800 nid=0x54c2 sleeping[0x00007f57d230d000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture$RemotingInvocationTimeoutScan.run(DefaultFuture.java:296) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - None "dubbo-remoting-client-heartbeat-thread-2" #68 daemon prio=5 os_prio=0 tid=0x00007f57f8008800 nid=0x53eb waiting on condition [0x00007f57d0ef5000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000f037a018> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)jinfo(JVM Configuration info)这个命令作用是实时查看和调整虚拟机运行参数。 之前的jps -v口令只能查看到显示指定的参数,如果想要查看未被显示指定的参数的值就要使用jinfo口令。 jinfo命令格式:
jinfo [ option ] pid
示例:
$ sudo ./jinfo -flags 21332 Attaching to process ID 21332, please wait... Debugger attached successfully. Server compiler detected. JVM version is 25.161-b12 Non-default VM flags: -XX:CICompilerCount=2 -XX:CMSInitiatingOccupancyFraction=75 -XX:+DisableExplicitGC -XX:GCLogFileSize=10485760 -XX:HeapDumpPath=null -XX:InitialHeapSize=536870912 -XX:+ManagementServer -XX:MaxHeapSize=536870912 -XX:MaxMetaspaceSize=268435456 -XX:MaxNewSize=268435456 -XX:MaxTenuringThreshold=6 -XX:MetaspaceSize=134217728 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=268435456 -XX:NumberOfGCLogFiles=30 -XX:OldPLABSize=16 -XX:OldSize=268435456 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ThreadStackSize=512 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation -XX:+UseParNewGC Command line: -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1980 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Xms512M -Xmx512M -Xss512K -XX:NewSize=256M -XX:MetaspaceSize=128M -XX:MaxMetaspaceSize=256M -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+DisableExplicitGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:logs/warehouse_gateway_gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=30 -XX:GCLogFileSize=10M -XX:HeapDumpPath=logs/warehouse_gateway_dump.hprof -Djava.library.path=lib -Dwrapper.key=kQiO5p_Fz3KA0uhJ -Dwrapper.port=32001 -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 -Dwrapper.pid=21330 -Dwrapper.version=3.2.3 -Dwrapper.native_library=wrapper -Dwrapper.service=TRUE -Dwrapper.cpu.timeout=10 -Dwrapper.jvmid=1