JVM 分析工具 - NightPxy

top
jstack
jstat
- 语法
- -class
- -gc
- -gcutil
- -gccause
jmap
- 堆分析
- Dump
- MAT
- 分析思路
  - 内存泄露

https://www.cnblogs.com/duanxz/p/8510623.html

https://www.cnblogs.com/duanxz/p/6092911.html

https://www.cnblogs.com/duanxz/p/6046055.html

JVM参数之-XX:+HeapDumpOnOutOfMemoryError（导出内存溢出的堆信息(hprof文件)）

top

（1）load average：此值反映了任务队列的平均长度；如果此值超过了CPU数量，则表示当前CPU数量不足以处理任务，负载过高（2）%us：用户CPU时间百分比；如果此值过高，表示应用消耗了大量的CPU.这主要是线程可能一直处于可运行状态.这些线程大量执行无阻塞,循环或正则的纯计算任务.(可能是代码中存在死循环、或是频繁GC等)
（3）%sy：系统CPU时间百分比；如果此值过高,表示Linux话费了更多的时间在进行线程切换上. 可能是系统线程竞争激烈,上下文切换过多(线程处于不断阻塞(锁等待或IO等待)和执行状态变化过程中),应当减少线程数（4）%wa：等待输入、输出CPU时间百分比；如果此值过高，说明系统IO速度过慢，CPU大部分时间都在等待IO完成（5）%hi：硬件中断CPU百分比；当硬件中断发生时，CPU会优先去处理硬件中断；比如，网卡接收数据会产生硬件中断（6）swap used：被使用的swap；此值过高代表系统因为内存不足在进行频繁的换入、换出操作，这样会影响效率，应增大内存量（7）%CPU：进程使用CPU的百分比；此值高表示CPU在进行无阻塞运算等

jstack

概述

jstack是分析线程栈的工具
譬如CPU的高占用,一般是由于线程问题引起的.正常情况下,线程不断的切换执行的CPU占用也会很高,这是CPU利用充分的正常现象,但诸如死循环,大量阻塞甚至死锁问题也会引起CPU高占用,这里就需要使用jstack分析线程栈了,区分是正常情况还是程序本身出现了问题

语法

jstack [-l] <xxx-pid>

# jstack 19191 > t.log 

# -l 表示打印锁附加信息(比如是java.util.concurrent的ownable或是synchronizer)
# 打印附加信息会极大的加剧jstack造成的JVM停顿(正常停止几十毫秒,附加信息可能会秒记)
# 所以如非确实需要,否则一般情况下不需打印附加信息  

基本步骤

本地

top 定位高占进程(或jps定位要分析的目标进程)
top + h 或 ps -mp pid -o THREAD,tid,time | sort -rn 定位高占线程
记录线程号,并转换为16进制数字(因为在jstack的输出中线程号是不是10进制存储,需要转16进制方便查询过滤)
jstack *** | grep thread-id -A 100 jstack输出过滤线程号的后100行

远程

线程状态

首先应该明白的是jstack中的线程状态含义.jstack的线程是运行时线程,未启动(NEW)或销毁(TERMINATED)的线程不在运行时考虑中,所以状态如下

RUNNABLE
BLOCKED 受阻塞并等待监视器锁(synchronizer阻塞) 未获取到锁
WAITING 无限期等待某个Condition或monitor释放,一般停留在park,wait,sleep,join,是竞争到锁后的等待
TIMED_WATING wait(timeout),有期限的等待某个Condition或monitor释放

locked xx 锁xx的拥有者
waiting to lock xx 在锁xx的待进入区(锁队列)上等待
wait on xx 获的锁xx的线程调用wait而进入等待区等待
parking to wait for xx juc的锁park原语而已,意义一样,但体系不同

分析思路

长尾循环(死循环)

   java.lang.Thread.State: RUNNABLE
        at concurrency.EndlessLoop.main(EndlessLoop.java:6)

   Locked ownable synchronizers:
        - None

waiting for monitor entry

# 线程状态阻塞(BLOCKED),线程动作等待进入(waiting for monitor entry) 
# 具体是等待锁(waiting to lock <0x0000000602f38e90>)
# 这是一个标准的因为Sychronzieed竞争失败的阻塞  
# 如果是经常出现或大量出现,表示这里很可能有全局锁性能问题
#    1.检查下拥有者为什么长时间占有(数据库死锁、网络等待等长尾IO)
#    2.优化全局锁
"d&a-3588" daemon waiting for monitor entry [0x000000006e5d5000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.Thread.run(Thread.java:745)
- waiting to lock <0x0000000602f38e90> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:745)

waiting on condition

   # waiting for monitor entry没有竞争到锁,在进入(Entry)区中阻塞等待
   # waiting on condition 则是竞争到锁都wait,是在等待(wait)区中等待唤醒
   # WAITING其实不太好,TIMED_WAITING会更好  
   # java.lang.Thread.State: TIMED_WAITING (on object monitor)
   # 如果大量出现,需要检查下为什么唤醒条件迟迟没有达成
   java.lang.Thread.State: WAITING (on object monitor)
   at java.lang.Object.wait(Native Method)
   - waiting on <0x00000000d5e5bc70> (a java.lang.Object)
   at java.lang.Object.wait(Object.java:502)
   at concurrency.EndlessLoop.main(EndlessLoop.java:9)
   - locked <0x00000000d5e5bc70> (a java.lang.Object)

死锁

Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00000000572c9ab8 (object 0x00000000d5e5bab0, a java.
lang.Object),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00000000572cb0b8 (object 0x00000000d5e5bac0, a java.
lang.Object),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at concurrency.Thread2.run(EndlessLoop.java:39)
        - waiting to lock <0x00000000d5e5bab0> (a java.lang.Object)
        - locked <0x00000000d5e5bac0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:745)
"Thread-0":
        at concurrency.Thread1.run(EndlessLoop.java:24)
        - waiting to lock <0x00000000d5e5bac0> (a java.lang.Object)
        - locked <0x00000000d5e5bab0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:745)

Found 1 deadlock.

总结

如果相同的CallStack出现在同一个线程(Thread-ID)中,则可以80%确定这里有长循环,需要仔细检查确认是否死循环或者能否优化长循环
如果经常发现等待,则需要检查这里是否有全局锁或唤醒条件问题(因为锁性能问题,正常情况下锁是短时间和概率低的,有是正常的,有且经常被我们捕捉到说明概率很大,值得调优)
如果开发或测试环境经常发现同一块的业务代码,也可以看看.以开发或测试环境的低频度执行,应该很难捕捉到业务过程,如果有很多,值得看看是不是业务处理有长尾问题
如果怀疑有死锁问题,需要拉出lock-id和wait to xx,看看是否有循环等待
一般情况下 jstack都能检测出deadlock,但不是绝对的.比如静态代码块死锁,jstac无法检测
警惕wait
wait是无限等待,这是有一定危险性的,最好是使用TIMED_WATING wait(timeout)

jstat

语法

jstat pid [1000 每隔毫秒输出一次] [5 输出5次停止]

# -class 显示ClassLoad相关信息  
# -compiler 显示JIT编译相关信息
# -gc 显示GC相关堆信息  
# -gccapacity 显示各代的容量和使用情况  
# -gcmetacapacity 显示元空间大小
# -gcnew 显示新生代信息
# -gcnewcapacity 显示新生代大小和使用情况
# -gcold 显示老年代和永久代的信息
# -gcoldcapacity 显示老年代的大小
# -gcutil 显示垃圾收集信息  
# -gccause 显示垃圾收集信息(同gcutil),同时显示当前或最后一次GC诱因
# -printcompilation 输出JIT编译的方法信息  

-class

jstat -class 9496

Loaded  Bytes  Unloaded  Bytes     Time
   416   863.2        0     0.0       0.06

# Loaded : 已经装载的类的数量
# Bytes : 装载类所占用的字节数
# Unloaded：已经卸载类的数量
# Bytes：卸载类的字节数
# Time：装载和卸载类所花费的时间   

-gc

 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC
512.0  512.0   0.0    0.0    2048.0   969.9     7168.0     1257.8   4864.0 2654.9 512.0  285.4       2    0.003   1

-gcutil

jstat -gcutil 8984
S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
0.00   0.00  63.27   0.00  17.19  19.76      0    0.000     0    0.000    0.000

# s0 s0当前使用比例
# s1 s1当前使用比例
# E Eden当前使用比例
# O Old当前使用比例
# M MetaSpace当前使用比例
# CCS 压缩使用比例
# YGC 从应用程序启动到现在为止的YoungGC次数
# YGCT 从应用程序启动到现在为止的YoungGC平均耗时
# FGC 从应用程序启动到现在为止的FullGC次数  
# FGCT 从应用程序启动到现在为止的FullGC次数 

-gccause

 S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC
 0.00   0.00  85.88   0.00  17.19  19.76      0    0.000     0    0.000    0.000 No GC                No GC

# s0 s0当前使用比例
# s1 s1当前使用比例
# E Eden当前使用比例
# O Old当前使用比例
# M MetaSpace当前使用比例
# CCS 压缩使用比例
# YGC 从应用程序启动到现在为止的YoungGC次数
# YGCT 从应用程序启动到现在为止的YoungGC平均耗时
# FGC 从应用程序启动到现在为止的FullGC次数  
# FGCT 从应用程序启动到现在为止的FullGC次数
# LGCC 最后一次GC原因  
# GCC 当前GC原因  

# GC原因(部分,太多了) 
_java_lang_system_gc System.gc()调用产生的GC
_heap_inspection 因为jmap histo:live 导致的GC
_heap_dump 因为 jmap dump 导致的GC 
_g1_inc_collection_pause 设置为G1时分配失败GC
_g1_humongous_allocation 设置为G1时分配大对象失败导致GC
_metadata_GC_threshold 元空间分配失败时GC
_cms_initial_mark CMS初始化标识时GC
_cms_final_remark CMS最终标记时GC
_cms_concurrent_mark CMS并发标记时GC

jmap

堆分析

jmap -heap 27900

Attaching to process ID 27900, please wait...
Debugger attached successfully.
Client compiler detected.
JVM version is 20.45-b01
using thread-local object allocation.
Mark Sweep Compact GC
Heap Configuration: #堆内存初始化配置
   MinHeapFreeRatio = 40     #-XX:MinHeapFreeRatio设置JVM堆最小空闲比率  
   MaxHeapFreeRatio = 70   #-XX:MaxHeapFreeRatio设置JVM堆最大空闲比率  
   MaxHeapSize = 100663296 (96.0MB)   #-XX:MaxHeapSize=设置JVM堆的最大大小
   NewSize = 1048576 (1.0MB)     #-XX:NewSize=设置JVM堆的‘新生代’的默认大小
   MaxNewSize = 4294901760 (4095.9375MB) #-XX:MaxNewSize=设置JVM堆的‘新生代’的最大大小
   OldSize = 4194304 (4.0MB)  #-XX:OldSize=设置JVM堆的‘老生代’的大小
   NewRatio = 2    #-XX:NewRatio=:‘新生代’和‘老生代’的大小比率
   SurvivorRatio = 8  #-XX:SurvivorRatio=设置年轻代中Eden区与Survivor区的大小比值
   PermSize = 12582912 (12.0MB) #-XX:PermSize=<value>:设置JVM堆的‘持久代’的初始大小  
   MaxPermSize = 67108864 (64.0MB) #-XX:MaxPermSize=<value>:设置JVM堆的‘持久代’的最大大小  
Heap Usage:
New Generation (Eden + 1 Survivor Space): #新生代区内存分布，包含伊甸园区+1个Survivor区
   capacity = 30212096 (28.8125MB)
   used = 27103784 (25.848182678222656MB)
   free = 3108312 (2.9643173217773438MB)
   89.71169693092462% used
Eden Space: #Eden区内存分布
   capacity = 26869760 (25.625MB)
   used = 26869760 (25.625MB)
   free = 0 (0.0MB)
   100.0% used
From Space: #其中一个Survivor区的内存分布
   capacity = 3342336 (3.1875MB)
   used = 234024 (0.22318267822265625MB)
   free = 3108312 (2.9643173217773438MB)
   7.001809512867647% used
To Space: #另一个Survivor区的内存分布
   capacity = 3342336 (3.1875MB)
   used = 0 (0.0MB)
   free = 3342336 (3.1875MB)
   0.0% used
tenured generation:   #当前的Old区内存分布  
   capacity = 67108864 (64.0MB)
   used = 67108816 (63.99995422363281MB)
   free = 48 (4.57763671875E-5MB)
   99.99992847442627% used
Perm Generation:     #当前的 “持久代” 内存分布
   capacity = 14417920 (13.75MB)
   used = 14339216 (13.674942016601562MB)
   free = 78704 (0.0750579833984375MB)
   99.45412375710227% used

Dump

jmap -dump:live,format=b,file=E:\xx\dump.hprof 9804

MAT

MAT(MemoryAnalyzer) 下载 https://www.eclipse.org/mat/downloads.php

Histogram

类柱状图,站在类(或包)的角度的对象数量和可回收大小

Class Name 类名
Objects 该类的对象数量(该类创建了多少个对象)
Shallow Heap 对象自身内存大小(不包含它引用对象)
对非数组而言,它的大小等于对象与它所有成员变量大小的总和
对于数组而言,大小等于数组元素对象的大小总和
Retained Heap 当前对象大小+当前对象直接或间接引用到对象的大小总和
这种间接是链式的(A->B->C),理论上如果这个对象被清理后总归可以为此回收到多少内存

Dominator Tree

对象支配树,站在对象的角度的对象之间的引用关系

Thread

线程角度的内存占用

Top Consumers

对象内存消耗的统计分析

Biggest Objects 对象大小统计
Biggest Top-Level 按等级分布查询,实际就是按使用次数统计
Biggest Top-Level Dominator Class Loaders 按加载器统计,如果使用自定义加载器会比较有用
Biggest Top-Level Dominator Packages 按包统计,这个比较有用定位自己还是第三方Jar问题

Leak Suspects

自带的泄露报告分析,可以参考参考
它的原理是如果一个对象发生泄露,那么随着程序运行不断的分配回收后,泄漏点会占比越来越多
那么如果一个点占比很多,就有理由相信这里可能是泄露点
当然这种方法有误判,java.lang.String占比很高就有可能不是泄露造成的,可以参考

其它

List objects -> with incoming references 这个对象持有哪些外部对象引用
List objects -> with outcoming references 这个对象被哪些外部对象引用
Path To GC Roots -> exclude all phantim/weak/soft etc. references
这个对象的排除软,弱,虚的只剩强引用的链
Path To GC Roots -> exclude weak/soft references 这个对象的强,虚引用链
Merge Shortest path to GC root 从GC-Root角度的引用链
Java-Collection -> 容器(数组,Hash,Set)等的元素内展开,非常方便

分析思路

内存泄露

内存泄露分析是比对两次Dump的新增对象异常,正常需要两次间隔时间稍长,能体现出差异的最好(也可以只需一次Dump也行,依赖类柱状图和对象支付图,这需要分析者本身对系统较为了解或者经验丰富)

通过两次Dump的Histogram比对,通过排序了解两次Dump间隔中新增了哪些对象
其中大量出现某一类对象就是可疑重点(内存泄露绝大部分都是容器泄露)
通过可疑对象定位类后,查找这个类对象的GC-Root,定位出最终是哪个点在维持引用
定位引用点后,反向分析代码确定最终问题

NightPxy 个人技术博客

目录

top

jstack

概述

语法

基本步骤

本地

远程

线程状态

分析思路

长尾循环(死循环)

waiting for monitor entry

waiting on condition

死锁

总结

jstat

语法

-class

-gc

-gcutil

-gccause

jmap

堆分析

Dump

MAT

Histogram

Dominator Tree

Thread

Top Consumers

Leak Suspects

其它

分析思路

内存泄露