java-1.8 jvm-diagnose

164 阅读4分钟

诊断工具

1. jps

JVM Process Status Tool,显示指定系统内所有的HotSpot虚拟机进程。option参数如下:

  • -l : 输出主类全名或jar路径
  • -q : 只输出LVMID
  • -m : 输出JVM启动时传递给main()的参数
  • -v : 输出JVM启动时显示指定的JVM参数 eg: jps -l -m

2. jstat

jstat(JVM statistics Monitoring)是用于监视虚拟机运行时状态信息的命令,它可以显示出虚拟机进程中的类装载、内存、垃圾收集、JIT编译等运行数据。 -class 监视类装载、卸载数量、总空间以及耗费的时间

# jstat -class 7064
Loaded  Bytes  Unloaded  Bytes     Time   
  9743 19960.8        0     0.0       6.11
* Loaded : 加载class的数量
* Bytes : class字节大小
* Unloaded : 未加载class的数量
* Bytes : 未加载class的字节大小
* Time : 加载时间
        -compiler 输出JIT编译过的方法数量耗时等
# jstat -compiler 7064
Compiled Failed Invalid   Time   FailedType FailedMethod
   16451      0       0   100.33          0   
* Compiled : 编译数量
* Failed : 编译失败数量
* Invalid : 无效数量
* Time : 编译耗时
* FailedType : 失败类型
* FailedMethod : 失败方法的全限定名
        -gc 垃圾回收堆的行为统计,常用命令
# jstat -gc 7064
S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
13056.0 13056.0 1007.6  0.0   104960.0 95505.2   917504.0   205679.5  66484.0 64848.5 7132.0 6717.6   3026   50.039   4      0.133   50.172
C即Capacity 总容量,U即Used 已使用的容量
* S0C : survivor0区的总容量
* S1C : survivor1区的总容量
* S0U : survivor0区已使用的容量
* S1C : survivor1区已使用的容量
* EC : Eden区的总容量
* EU : Eden区已使用的容量
* OC : Old区的总容量
* OU : Old区已使用的容量
* PC 当前perm的容量 (KB)
* PU perm的使用 (KB)
* YGC : 新生代垃圾回收次数
* YGCT : 新生代垃圾回收时间
* FGC : 老年代垃圾回收次数
* FGCT : 老年代垃圾回收时间
* GCT : 垃圾回收总消耗时间

# jstat -gc 7064 2000 20
这个命令意思就是每隔2000ms输出1262的gc情况,一共输出20次
-gccapacity  同-gc,不过还会输出Java堆各区域使用到的最大、最小空间
# jstat -gccapacity 7064 2000 20
NGCMN    NGCMX     NGC     S0C   S1C       EC      OGCMN      OGCMX       OGC         OC       MCMN     MCMX      MC     CCSMN    CCSMX     CCSC    YGC    FGC
131072.0 131072.0 131072.0 13056.0 13056.0 104960.0   917504.0   917504.0   917504.0   917504.0      0.0 1107968.0  66484.0      0.0 1048576.0   7132.0   3027     4
131072.0 131072.0 131072.0 13056.0 13056.0 104960.0   917504.0   917504.0   917504.0   917504.0      0.0 1107968.0  66484.0      0.0 1048576.0   7132.0   3027     4
* NGCMN : 新生代占用的最小空间
* NGCMX : 新生代占用的最大空间
* OGCMN : 老年代占用的最小空间
* OGCMX : 老年代占用的最大空间
* OGC:当前年老代的容量 (KB)
* OC:当前年老代的空间 (KB)
* PGCMN : perm占用的最小空间
* PGCMX : perm占用的最大空间
-gcutil  同-gc,不过输出的是已使用空间占总空间的百分比
# jstat -gcutil 7064 2000 20
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   7.76  27.58  22.42  97.54  94.19   3027   50.050     4    0.133   50.183
-gccause  垃圾收集统计概述(同-gcutil),附加最近两次垃圾回收事件的原因
# jstat -gccause 7064 2000 20
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC                 
  0.00   7.76  33.58  22.42  97.54  94.19   3027   50.050     4    0.133   50.183 Allocation Failure   No GC
* LGCC:最近垃圾回收的原因
* GCC:当前垃圾回收的原因
-gcnew  统计新生代的行为
-gcnewcapacity  新生代与其相应的内存空间的统计
-gcold  统计旧生代的行为
-gcoldcapacity  统计旧生代的大小和空间
-gcpermcapacity  永生代行为统计
-printcompilation   hotspot编译方法统计
#jstat -gcnew 7064 2000 20
S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT  
13056.0 13056.0    0.0 1012.9  6   6 6528.0 104960.0  57023.3   3027   50.050
* TT:Tenuring threshold(提升阈值)
* MTT:最大的tenuring threshold
* DSS:survivor区域大小 (KB)

# jstat -gcnewcapacity 7064 2000 20
  NGCMN      NGCMX       NGC      S0CMX     S0C     S1CMX     S1C       ECMX        EC      YGC   FGC
  131072.0   131072.0   131072.0  13056.0  13056.0  13056.0  13056.0   104960.0   104960.0  3027     4
* NGC:当前年轻代的容量 (KB)
* S0CMX:最大的S0空间 (KB)
* S0C:当前S0空间 (KB)
* ECMX:最大eden空间 (KB)
* EC:当前eden空间 (KB)

# jstat -printcompilation 7064 2000 20
Compiled  Size  Type Method
   16451     39    1 sun/nio/cs/US_ASCII$Decoder implReplaceWith
* Compiled:被执行的编译任务的数量
* Size:方法字节码的字节数
* Type:编译类型
* Method:编译方法的类名和方法名。类名使用"/" 代替 "." 作为空间分隔符. 方法名是给出类的方法名. 格式是一致于HotSpot - XX:+PrintComplation 选项

3. jmap

jmap(JVM Memory Map)命令用于生成heap dump文件,如果不使用这个命令,还阔以使用-XX:+HeapDumpOnOutOfMemoryError参数来让虚拟机出现OOM的时候·自动生成dump文件。 jmap不仅能生成dump文件,还阔以查询finalize执行队列、Java堆和永久代的详细信息,如当前使用率、当前使用的是哪种收集器等。 dump : 生成堆转储快照

# jmap -dump:live,format=b,file=dump.hprof 28920
        finalizerinfo : 显示在F-Queue队列等待Finalizer线程执行finalizer方法的对象

        heap : 显示Java堆详细信息。打印heap的概要信息,GC使用的算法,heap的配置及wise heap的使用情况,可以用此来判断内存目前的使用情况以及垃圾回收情况
# jmap -heap 2524
Attaching to process ID 2524, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.131-b11


using thread-local object allocation.
Parallel GC with 4 thread(s)  //GC 方式  


Heap Configuration://堆内存初始化配置
   MinHeapFreeRatio         = 0//对应jvm启动参数-XX:MinHeapFreeRatio设置JVM堆最小空闲比率(default 40)
   MaxHeapFreeRatio         = 100//对应jvm启动参数 -XX:MaxHeapFreeRatio设置JVM堆最大空闲比率(default 70)
   MaxHeapSize              = 734003200 (700.0MB)//对应jvm启动参数-XX:MaxHeapSize=设置JVM堆的最大大小
   NewSize                  = 44564480 (42.5MB)//对应jvm启动参数-XX:NewSize=设置JVM堆的‘新生代’的默认大小
   MaxNewSize               = 244318208 (233.0MB)//对应jvm启动参数-XX:MaxNewSize=设置JVM堆的‘新生代’的最大大小
   OldSize                  = 89653248 (85.5MB)//对应jvm启动参数-XX:OldSize=<value>:设置JVM堆的‘老生代’的大小
   NewRatio                 = 2//对应jvm启动参数-XX:NewRatio=:‘新生代’和‘老生代’的大小比率
   SurvivorRatio            = 8//对应jvm启动参数-XX:SurvivorRatio=设置年轻代中Eden区与Survivor区的大小比值
   MetaspaceSize            = 21807104 (20.796875MB)//对应jvm启动参数-XX:PermSize=<value>:设置JVM堆的‘永生代’的初始大小??
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)


Heap Usage://堆内存使用情况
PS Young Generation
Eden Space://Eden区内存分布
   capacity = 68157440 (65.0MB)//Eden区总容量
   used     = 2070304 (1.974395751953125MB)//Eden区已使用
   free     = 66087136 (63.025604248046875MB)//Eden区剩余容量
   3.037531926081731% used//Eden区使用比率
From Space://其中一个Survivor区的内存分布
   capacity = 5242880 (5.0MB)
   used     = 0 (0.0MB)
   free     = 5242880 (5.0MB)
   0.0% used
To Space://另一个Survivor区的内存分布
   capacity = 17825792 (17.0MB)
   used     = 0 (0.0MB)
   free     = 17825792 (17.0MB)
   0.0% used
PS Old Generation//当前的Old区内存分布
   capacity = 73400320 (70.0MB)
   used     = 22593392 (21.546737670898438MB)
   free     = 50806928 (48.45326232910156MB)
   30.781053815569198% used


6486 interned Strings occupying 550640 bytes.
histo : 显示堆中对象的统计信息

clstats: to print permanent generation statistics

F : 当-dump没有响应时,强制生成dump快照

4. jstack

用于生成java虚拟机当前时刻的线程快照。

线程快照是当前java虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待等。

线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做什么事情,或者等待什么资源。

如果java程序崩溃生成core文件,jstack工具可以用来获得core文件的java stack和native stack的信息,从而可以轻松地知道java程序是如何崩溃和在程序何处发生问题。另外,jstack工具还可以附属到正在运行的java程序中,看到当时运行的java程序的java stack和native stack的信息, 如果现在运行的java程序呈现hung的状态,jstack是非常有用的。

#jstack -l 2524|more
2019-04-29 16:51:29
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.131-b11 mixed mode):


"DestroyJavaVM" #16 prio=5 os_prio=0 tid=0x0000000005285800 nid=0x177c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE


* -F : 当正常输出请求不被响应时,强制输出线程堆栈
* -l : 除堆栈外,显示关于锁的附加信息
* -m : 如果调用到本地方法的话,可以显示C/C++的堆栈

5. jinfo

jinfo(JVM Configuration info)这个命令作用是实时查看和调整虚拟机运行参数。 之前的jps -v口令只能查看到显示指定的参数,如果想要查看未被显示指定的参数的值就要使用jinfo口令

VM Flags:
Non-default VM flags: -XX:CICompilerCount=3 -XX:InitialHeapSize=134217728 -XX:MaxHeapSize=734003200 -XX:MaxNewSize=244318208 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=44564480 -XX:OldSize=89653248 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
* -flag : 输出指定args参数的值
* -flags : 不需要args参数,输出所有JVM参数的值
* -sysprops : 输出系统属性,等同于System.getProperties()

6. top

Top命令取得cpu占有率最高的进程,然后取得该进程内的cpu占有率高的线程:

ps -mp pid-o THREAD,tid,time

实战

记一次线上full gc问题处理

问题现象

[root@-server-757799875b-2wkvx /]# jstat -gc 1 2000
S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796531.9  109388.0 104798.1 12364.0 11638.8    181    4.508 4129   914.951  919.459
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796536.4  109388.0 104798.1 12364.0 11638.8    181    4.508 4139   916.811  921.318
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796542.0  109388.0 104798.1 12364.0 11638.8    181    4.508 4150   918.822  923.330
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796541.4  109388.0 104798.1 12364.0 11638.8    181    4.508 4160   920.780  925.287
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796543.5  109388.0 104798.1 12364.0 11638.8    181    4.508 4171   922.759  927.267
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796544.0  109388.0 104798.1 12364.0 11638.8    181    4.508 4182   924.802  929.310
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796544.0  109388.0 104798.1 12364.0 11638.8    181    4.508 4193   926.755  931.263
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796544.0  109388.0 104798.1 12364.0 11638.8    181    4.508 4204   928.730  933.238
465408.0 465920.0  0.0    0.0   446464.0 446455.5 2796544.0  2796542.0  109388.0 104798.1 12364.0 11638.8    181    4.508 4215   930.797  935.304
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796544.0  109388.0 104798.1 12364.0 11638.8    181    4.508 4222   932.032  936.540
465408.0 465920.0  0.0    0.0   446464.0 446464.0 2796544.0  2796521.6  109388.0 104798.5 12364.0 11638.8    181    4.508 4230   934.761  939.269
* S0C:第一个幸存区的大小
* S1C:第二个幸存区的大小
* S0U:第一个幸存区的使用大小
* S1U:第二个幸存区的使用大小
* EC:伊甸园区的大小
* EU:伊甸园区的使用大小
* OC:老年代大小
* OU:老年代使用大小
* MC:方法区大小
* MU:方法区使用大小
* CCSC:压缩类空间大小
* CCSU:压缩类空间使用大小
* YGC:年轻代垃圾回收次数
* YGCT:年轻代垃圾回收消耗时间
* FGC:老年代垃圾回收次数
* FGCT:老年代垃圾回收消耗时间
* GCT:垃圾回收消耗总时间

[root@kuai-websocket-77b9dc5dbf-8z5mp /]# jinfo 1
VM Flags:
Non-default VM flags: -XX:CICompilerCount=15 -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=4294967296 -XX:MaxNewSize=1431306240 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=357564416 -XX:OldSize=716177408 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseParallelGC
Command line:  -Xms1024m -Xmx4096m

[root@kuai-server-757799875b-2wkvx /]# jmap -heap 1
Attaching to process ID 1, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.181-b13

using thread-local object allocation.
Parallel GC with 33 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 4294967296 (4096.0MB)
   NewSize                  = 357564416 (341.0MB)
   MaxNewSize               = 1431306240 (1365.0MB)
   OldSize                  = 716177408 (683.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 457179136 (436.0MB)
   used     = 457179136 (436.0MB)
   free     = 0 (0.0MB)
   100.0% used
From Space:
   capacity = 476577792 (454.5MB)
   used     = 0 (0.0MB)
   free     = 476577792 (454.5MB)
   0.0% used
To Space:
   capacity = 477102080 (455.0MB)
   used     = 0 (0.0MB)
   free     = 477102080 (455.0MB)
   0.0% used
PS Old Generation
   capacity = 2863661056 (2731.0MB)
   used     = 2861965360 (2729.382858276367MB)
   free     = 1695696 (1.6171417236328125MB)
   99.94078572963629% used

[root@-server-757799875b-slmzd /]#  jmap -histo:live 1|grep WsFrameServer
175:           202          22624  org.apache.tomcat.websocket.server.WsFrameServer
[root@-server-757799875b-slmzd /]#  jmap -dump:live,format=b,file=dump.hprof 1

问题分析

分析dump文件:

  1. Histogram里查看到WsFrameServer的引用对象总共有3.1G大小

Shallow Heap表示对象本身占用内存的大小,不包含对其他对象的引用,也就是对象头加成员变量(不是成员变量的值)的总和。

Retained Heap是该对象自己的Shallow Heap,并加上从该对象能直接或间接访问到对象的Shallow Heap之和。换句话说,Retained Heap是该对象GC之后所能回收到内存的总和。

image.png 2. 查找WsFrameServer的GCRoot未释放的外部引用

Paths to GC Roots -> exclude all phantom/weak/soft etc.reference (排除所有虚弱软引用) -查找GC Root线程 -> 查找未释放的内存占用最高的代码逻辑段(很可能是产生内存溢出代码)

image.png

  1. 过滤查看InstanceMonitorHandler的大小

image.png

  1. 查看WsFrameServer的内存占用情况,里面会有两个对象,一个messageBufferText和一个messageBufferBinary,一个10M和一个5M

image.png

  1. 代码诊断: a. spring-websocket.xml中配置bufferSize:
<bean class="org.springframework.web.socket.server.standard.ServletServerContainerFactoryBean">
    <property name="maxTextMessageBufferSize" value="5242800"/>
    <property name="maxBinaryMessageBufferSize" value="5242800"/>
</bean>

b. 页面关闭时,websocket连接未关闭,导致连接数一直增大

CPU过高

问题解决

首先我们通过top命令查看当前CPU消耗过高的进程是哪个,从而得到进程id;

# top
top - 08:31:10 up 30 min,  0 users,  load average: 0.73, 0.58, 0.34
KiB Mem:   2046460 total,  1923864 used,   122596 free,    14388 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192352 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
    9 root      20   0 2557160 288976  15812 S  98.0 14.1   0:42.60 java

然后通过top -Hp 来查看该进程中有哪些线程CPU过高,一般超过80%就是比较高的,80%左右是合理情况。这样我们就能得到CPU消耗比较高的线程id。

# top -Hp 9
top - 08:31:16 up 30 min,  0 users,  load average: 0.75, 0.59, 0.35
Threads:  11 total,   1 running,  10 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.5 us,  0.6 sy,  0.0 ni, 95.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   2046460 total,  1924856 used,   121604 free,    14396 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192532 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
   10 root      20   0 2557160 289824  15872 R 79.3 14.2   0:41.49 java
   11 root      20   0 2557160 289824  15872 S 13.2 14.2   0:06.78 java

接着通过该线程id的十六进制表示在jstack日志中查看当前线程具体的堆栈信息。

[bdpops@BJxxx ~]$ printf "%x\n" 44075
ac2b
[bdpops@BJxxx ~]$ jstack 43964| grep ac2b  -A 30

a  # 这里打印结果说明该线程在jstack中的展现形式为0xa
...
"main" #1 prio=5 os_prio=0 tid=0x00007f8718009800 nid=0xb runnable [0x00007f871fe41000]
   java.lang.Thread.State: RUNNABLE
	at com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)

"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable 

这里的VM Thread一行的最后显示nid=0xa,这里nid的意思就是操作系统线程id的意思。而VM Thread指的就是垃圾回收的线程。这里我们基本上可以确定,当前系统缓慢的原因主要是垃圾回收过于频繁,导致GC停顿时间较长。

debug gethostbyname: unknown host问题

问题描述

export HADOOP_CLIENT_OPTS=" -agentlib:jdwp=transport=dt_socket,server=y,address=*:8000,suspend=y"

报错

ERROR: transport error 202: gethostbyname: unknown host
ERROR: JDWP Transport dt_socket failed to initialize, TRANSPORT_INIT(510)
JDWP exit error AGENT_ERROR_TRANSPORT_INIT(197): No transports initialized [debugInit.c:750]

问题解决

# jdk1.8及以下
export HADOOP_CLIENT_OPTS=" -agentlib:jdwp=transport=dt_socket,server=y,address=8000,suspend=y"
# jdk1.8以上
export HADOOP_CLIENT_OPTS=" -agentlib:jdwp=transport=dt_socket,server=y,address=*:8000,suspend=y"