首先执行最简单的四步骤,再逐步检查
{PID} 为实际Java在服务器中的进程ID一般为服务器排名第一的那个Java进程
首先前提是:先获取占用最高的Java进程,然后再找出Java进程中CPU/内存占用最高的线程
详细可参考 快速成为Java故障排查高手
1.控制台执行 jstack {PID} > log.text 将生成的堆栈数据生成至日志中方便查看
2.转换线程ID控制台执行 printf "%x\n" {TID} 注意:TID为线程ID
3.定位cpu占用线程控制台执行 jstack {PID}|grep {tid} -A 30
4.将2步骤获得的tid去log.text中搜索,查看当前线程是否在异常堆栈日志中
/opt/java8/bin/jstack
Usage:
jstack [-l] <pid>
(to connect to running process) 连接活动线程
jstack -F [-m] [-l] <pid>
(to connect to a hung process) 连接阻塞线程
jstack [-m] [-l] <executable> <core>
(to connect to a core file) 连接dump的文件
jstack [-m] [-l] [server_id@]<remote server IP or hostname>
(to connect to a remote debug server) 连接远程服务器
Options:
-F to force a thread dump. Use when jstack <pid> does not respond (process is hung)
-m to print both java and native frames (mixed mode)
-l long listing. Prints additional information about locks
-h or -help to print this help message
详细各项指标排查如下:
CPU
是系统重要监控指标,能够分析系统的整体运行状况。监控一般包括运行队列、CPU 使用率和上下文切换等
top 命令显示了各个进程从高到低排序 CPU 使用情况 。
其中 Load Average 显示最近 1 分钟、5 分钟和 15 分钟的系统平均负载,上图各值为 0.0.4,0.09,0.13
我们一般会关注 CPU 使用率最高的进程,正常情况下就是我们的应用主进程。
PID : 进程 id
USER : 进程所有者
PR : 进程优先级
NI : nice 值。负值表示高优先级,正值表示低优先级
VIRT : 进程使用的虚拟内存总量,单位 kb。VIRT=SWAP+RES
RES : 进程使用的、未被换出的物理内存大小,单位 kb。RES=CODE+DATA
SHR : 共享内存大小,单位 kb
S : 进程状态。D= 不可中断的睡眠状态 R= 运行 S= 睡眠 T= 跟踪 / 停止 Z= 僵尸进程
%CPU : 上次更新到现在的 CPU 时间占用百分比
%MEM : 进程使用的物理内存百分比
TIME+ : 进程使用的 CPU 时间总计,单位 1/100 秒
COMMAND : 进程名称
内存
内存是排查线上问题的重要参考依据,内存问题很多时候是引起 CPU 使用率较高的见解因素。
系统内存:free 是显示的当前内存的使用 ,-m 的意思是 M 字节来显示内容。
free -m
total 内存总数: 3790M
used 已经使用的内存数: 1880M
free 空闲的内存数: 118M
shared 当前已经废弃不用 , 总是 0
buffers Buffer 缓存内存数: 1792M
磁盘
df -h
网络
dstat 命令可以集成了 vmstat、iostat、netstat 等等工具能完成的任务。
dstat -c cpu 情况
-d 磁盘读写
-n 网络状况
-l 显示系统负载
-m 显示形同内存状况
-p 显示系统进程信息
-r 显示系统 IO 情况
vmstat:
vmstat 2 10 -t
vmstat 是 Virtual Meomory Statistics(虚拟内存统计)的缩写 , 是实时系统监控工具。该命令通过使用 knlist 子程序和 /dev/kmen 伪设备驱动器访问这些数据,输出信息直接打印在屏幕。
使用 vmstat 2 10 -t 命令,查看 io 的情况 (第一个参数是采样的时间间隔数单位是秒,第二个参数是采样的次数)
定位排查问题时最为常用命令包括:jps(进程)、jmap(内存)、jstack(线程)、jinfo(参数) 等
jps: 查询当前机器所有 JAVA 进程信息
jmap: 输出某个 java 进程内存情况 (如:产生那些对象及数量等)
jstack: 打印某个 Java 线程的线程栈信息
jinfo: 用于查看 jvm 的配置参数
JAVA线上排查常用命令
jmap命令
jmap -heap pid 输出当前进程 JVM 堆新生代、老年代、持久代等请情况,GC 使用算法等信息
jmap -histo:live {pid} | head -n 10 输出当前进程内存中所有对象包含的大小
jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid} 以二进制输出档当前内存的堆情况,
然后可以导入 MAT 等工具进行
1、 jmap -heap pid
输出当前进程JVM堆新生代、老年代、持久代等情况,GC使用的算法等信息。
2、jmap -histo:live {pid} | head -n 10 输出当前进程内存中所有对象包含的大小
输出当前进程内存中所有对象实例数 (instances) 和大小 (bytes), 如果某个业务对象
实例数和大小存在异常情况,可能存在内存泄露或者业务设计方面存在不合理之处。
3.jmap -dump:
命令如下必选先创建文件夹,不会自动生成:
mkdir logs
jmap -dump:format=b,file=/tmp/logs/dump.hprof {pid}
-dump:formate=b,file={path}
以二进制输出当前内存的堆情况至相应的文件,然后使用 MAT 等内存分析工具深入分析当前内存情况
也可以通过JVM参数配置OOM时自动dump当前内存镜像文件。
-XX:+HeapDumpOnOutOfMemoryError 和-XX:HeapDumpPath
所代表的含义就是当程序出现OutofMemory时,将会在相应的目录下生成一份dump文件,
而如果不指定选项-XX:HeapDumpPath则在当前目录下生成dump文件
确保应用发生 OOM 时 JVM 能够保存并 dump 出当前的内存镜像。
当然,如果你决定手动 dump 内存时,dump 操作占据一定 CPU 时间片、内存资源、磁盘资源等,因此会带来一定的系统资源消耗影响
此外,dump 的文件可能比较大 , 一般我们可以考虑使用 zip 命令对文件进行压缩处理,这样在下载文件时能减少带宽的开销。
下载 dump 文件完成之后,由于 dump 文件较大可将 dump 文件备份至制定位置或者直接删除,以释放磁盘在这块的空间占用。
4.dump日志分析:
MAT(Memory Analyzer Tool),一个基于 Eclipse 的内存分析工具,是一个快速、功能丰富的 JAVA heap 分析工具,它可以帮助我们查找内存泄漏和减少内存消耗。
使用内存分析工具从众多的对象中进行分析,快速的计算出在内存中对象的占用大小,看看是谁阻止了垃圾收集器的回收工作,并可以通过报表直观的查看到可能造成这种结果的对象。
具体可以参考:Java内存分析工具MAT(Memory Analyzer Tool)安装使用实例 : https://blog.csdn.net/jin_kwok/article/details/80326088 和 基于Java内存dump文件分析解决内存泄漏问题 : https://www.jianshu.com/p/2cf7169ba1c4
5.jstack命令
printf '%x\n' tid --> 10 进制至 16 进制线程 ID(navtive 线程) %d 10 进制
jstack pid | grep tid -C 30 --color ps -mp 8278 -o THREAD,tid,time | head -n 40
某 Java 进程 CPU 占用率高,我们想要定位到其中 CPU 占用率最高的线程
(1) 先利用top命令找到CPU占用高的进程pid
也可以通过ps -ef | grep 应用名 来快速定位自己应用的pid
显示pid:25311
(2) 利用 top 命令可以查出占 CPU 最高的线程 pid (先找到该pid 29080下所有的线程数据)
假设第一个就是占用最高可以看到占用cpu资源最高的为25311
(3) 占用率最高的线程 ID 为25311,将其转换为 16 进制形式 (因为 java native 线程以 16 进制形式输出)
printf '%x\n' 25311
(4) 利用 jstack 打印出 java 线程调用栈信息
jstack 25311 | grep '62df' -A 50 --color
最后打印的信息就是实际的信息
更多内容也可以参考:
如何使用jstack分析线程状态 : https://www.jianshu.com/p/6690f7e92f27
通过jstack与jmap分析一次线上故障: https://www.cnblogs.com/kingszelda/p/9034191.html
6.jinfo命令
jinfo可以用来查看正在运行的java运用程序的扩展参数。
查看pid对应的JVM参数,可以到
http://login.perfma.com
校验参数的正确性
jinfo -flags pid
拿到Command line后面的配置参数到perfma中验证查询:这里使用默认
7.jstat命令
jstat显示GC执行的情况
jstat -gc 25311 2000
即会每2秒一次显示进程号为25311 的java进成的GC情况
说明:
S0C、S1C、S0U、S1U:Survivor 0/1区容量(Capacity)和使用量(Used)
EC、EU:Eden区容量和使用量
OC、OU:年老代容量和使用量
PC、PU:永久代容量和使用量
YGC、YGT:年轻代GC次数和GC耗时
FGC、FGCT:Full GC次数和Full GC耗时
GCT:GC总耗时
显示内容说明如下(部分结果是通过其他其他参数显示的,暂不说明):
S0C:年轻代中第一个survivor(幸存区)的容量 (字节)
S1C:年轻代中第二个survivor(幸存区)的容量 (字节)
S0U:年轻代中第一个survivor(幸存区)目前已使用空间 (字节)
S1U:年轻代中第二个survivor(幸存区)目前已使用空间 (字节)
EC:年轻代中Eden(伊甸园)的容量 (字节)
EU:年轻代中Eden(伊甸园)目前已使用空间 (字节)
OC:Old代的容量 (字节)
OU:Old代目前已使用空间 (字节)
PC:Perm(持久代)的容量 (字节)
PU:Perm(持久代)目前已使用空间 (字节)
YGC:从应用程序启动到采样时年轻代中gc次数
YGCT:从应用程序启动到采样时年轻代中gc所用时间(s)
FGC:从应用程序启动到采样时old代(全gc)gc次数
FGCT:从应用程序启动到采样时old代(全gc)gc所用时间(s)
GCT:从应用程序启动到采样时gc用的总时间(s)
8.案例分析:
CPU 使用率高问题定位
利用 top -Hp 6814 输出进程 ID 为 6814 的所有线程 CPU 使用率情况,发现某个线程使用率比较高,有些异常。
printf '%x\n' 2304 #输出线程 ID 的 16 进制
jstack pid | grep '0x900' -C 30 --color
输出的日志表明该线程一直处于与 mysql I/O 状态:
利用 jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid} 以二进制输出档当前内存的堆情况,然后可以导入 MAT 等工具进行分析。
如下图所示,点击 MAT 的支配树可以发现存在某个超大对象数组
经过分析发现数组中每一个对象都是核心业务对象,我们的业务系统有一个定时任务线程会访问数据库某张业务表的所有记录
然后加载至内存然后进行处理因此内存吃紧,导致 CPU 突然飙升。发现该问题后,已对该方案进行重新设计
jmap -dump:format=b,file=/usr/local/logs/dump.hprof {pid}
- GC 日志分析
GC 日志详细分析
Java 虚拟机 GC 日志是用于定位问题重要的日志信息,频繁的 GC 将导致应用吞吐量下降、响应时间增加,甚至导致服务不可用。
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/usr/local/gc/gc.log -XX:+UseConcMarkSweepGC
上图为线上某应用在平稳运行状态下的 GC 日志截图
例子假设情况讲解:
[2021-12-29T08:25:19.753+0800: 73143.256] : 自JVM启动73143.256秒时发生本次GC
[ParNew: 556782K->1200K(629120K), 0.0135760 secs] :
对新生代进行的GC,使用ParNew收集器,556782K是新生代回收前的大小,1200K是新生代回收后大小,
556782K是当前新生代分配的内存总大小, 0.0135760 secs表示本次新生代回收耗时 0.0135760秒
[825452K->266673K(2027264K), 0.0140300 secs]:825452K是回收堆内存大小,
266673K是回收堆之后内存大小,2027264K是当前堆内存总大小,0.0140300 secs表示本次回收共耗时0.0140300秒
[Times: user=0.02 sys=0.00, real=0.02 secs] : 用户态耗时0.02秒,系统态耗时0.00,实际耗时0.02秒
无论是 minor GC 或者是 Full GC, 我们主要关注 GC 回收实时耗时 , 如 real=0.02secs, 即 stop the world 时间,
如果该时间过长,则严重影响应用性能,说明系统存在问题,需要优化,同时动态调整新生代和老年代的配比
回首示例解读
以其中一行为例来解读下日志信息:
[GC (Allocation Failure) [ParNew: 367523K->1293K(410432K), 0.0023988 secs]
522739K->156516K(1322496K), 0.0025301 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
表明进行了一次垃圾回收,前面没有Full修饰,表明这是一次Minor GC ,注意它不表示只GC新生代
并且现有的不管是新生代还是老年代都会STW。
Allocation Failure:
表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。
ParNew:表明本次GC发生在年轻代并且使用的是ParNew垃圾收集器。ParNew是一个Serial收集器的多线程版本,会使用多个CPU和线程完成垃圾收集工作(默认使用的线程数和CPU数相同,可以使用-XX:ParallelGCThreads参数限制)。该收集器采用复制算法回收内存,期间会停止其他工作线程,即Stop The World。
367523K->1293K(410432K):单位是KB
三个参数分别为:
GC前该内存区域(这里是年轻代)使用容量,GC后该内存区域使用容量,该内存区域总容量。
0.0023988 secs:
该内存区域GC耗时,单位是秒
522739K->156516K(1322496K):
三个参数分别为:堆区垃圾回收前的大小,堆区垃圾回收后的大小,堆区总大小。
[Times: user=0.04 sys=0.00, real=0.01 secs]:
分别表示用户态耗时,内核态耗时和总耗时
分析下可以得出结论:
该次GC新生代减少了367523-1293=366239K
Heap区总共减少了522739-156516=366223K
366239 – 366223 =16K,说明该次共有16K内存从年轻代移到了老年代,可以看出来数量并不多,说明都是生命周期短的对象,只是这种对象有很多。
我们需要的是尽量避免Full GC的发生,让对象尽可能的在年轻代就回收掉,所以这里可以稍微增加一点年轻代的大小,让那17K的数据也保存在年轻代中。
GC时,用什么方法判断哪些对象是需要回收:
1.引用计数法(已经不用了)
2.可达性分析法
前一种简而言之就是给对象添加一个引用计数器,有其他地方引用时这个计数器+1,引用失效时-1,为0时就可以删除掉了。但是它不能解决循环引用的问题,所以一般使用的都是后一种算法。
可达性分析法的基本思路就是通过一系列名为GC Roots的对象作为起始点,从这些节点开始向下搜索,搜索所走过的路径称为引用链(Reference Chain),当一个对象到GC Roots没有任何引用链相连时,则证明此对象是不可用的,那就可以回收掉了。
GC Roots一般都是些堆外指向堆内的引用,例如:
1.JVM栈中引用的对象
2.方法区中静态属性引用的对象
3.方法区中常量引用的对象
4.本地方法栈中引用的对象
以CMS为例,补充一些知识点介绍:
复制算法介绍:
因为新生代对象生命周期一般很短,现在一般将该内存区域划分为三块部分,一块大的叫Eden,两块小的叫Survivor。他们之间的比例一般为8:1:1。
使用的时候只使用Eden + 一块Survivor。用Eden区用满时会进行一次minor gc,将存活下面的对象复制到另外一块Survivor上。如果另一块Survivor放不下(对应虚拟机参数为 XX:TargetSurvivorRatio,默认50,即50%),对象直接进入老年代。
(使用CMS时,默认的新生代收集器是ParNew)(有时新生代GC时,需要找到老年代中引用的新生代对象,这个时候会用到一种叫“卡表”的技术,避免老年代的全表扫描,具体怎么操作的暂时还不知道……)
Survivor区的意义:如果没有survivor,Eden每进行一次minor gc,存活的对象就会进入老年代,老年代很快被填满就会进入major gc。由于老年代空间一般很大,所以进行一次gc耗时要长的多!尤其是频繁进行full GC,对程序的响应有很大的影响,俗称STW Survivor存在就是减少被送到老年代的对象,进而减少Full gc的发生。默认设置是经历了15次minor gc还在新生代中存活的对象才会被送到老年代。
为什么要有两个Survivor:主要是为了解决内存碎片化和效率问题。如果只有一个Survivor时,每触发一次minor gc都会有数据从Eden放到Survivor,一直这样循环下去。注意的是,Survivor区也会进行垃圾回收,这样就会出现内存碎片化问题。碎片化会导致堆中可能没有足够大的连续空间存放一个大对象,影响程序性能。如果有两块Survivor就能将剩余对象集中到其中一块Survivor上,避免碎片问题
Minor GC和Full GC的区别以及触发条件:
Minor GC
对于复制算法来说,当年轻代Eden区域满的时候会触发一次Minor GC,将Eden和From Survivor的对象复制到另外一块To Survivor上。
注意:如果某个对象存活的时间超过一定Minor gc次数会直接进入老年代,不在分配到To Survivor上(默认15次,对应虚拟机参数 -XX:+MaxTenuringThreshold)。
Full GC
用于清理整个堆空间。它的触发条件主要有以下几种:
显式调用System.gc方法(建议JVM触发)。
方法区空间不足(JDK8及之后不会有这种情况了,详见下文)
老年代空间不足,引起Full GC。这种情况比较复杂,有以下几种:
1 大对象直接进入老年代引起,由-XX:PretenureSizeThreshold参数定义
2 Minor GC时,经历过多次Minor GC仍存在的对象进入老年代。上面提过,由-XX:MaxTenuringThreashold参数定义
3 Minor GC时,动态对象年龄判定机制会将对象提前转移老年代。年龄从小到大进行累加,当加入某个年龄段后,累加和超过survivor区域 * -XX:TargetSurvivorRatio的时候,从这个年龄段往上的年龄的对象进入老年代
4 Minor GC时,Eden和From Space区向To Space区复制时,大于To Space区可用内存,会直接把对象转移到老年代
JVM的空间分配担保机制可能会触发Full GC:
在进行Minor GC之前,JVM的空间担保分配机制可能会触发3.2、3.3和3.4发生,即触发一次Full GC。
空间担保分配是指在发生Minor GC之前,虚拟机会检查老年代最大可用的连续空间是否大于新生代所有对象的总空间。
如果大于,则此次Minor GC是安全的。
如果小于,则虚拟机会查看HandlePromotionFailure设置值是否允许担保失败。如果HandlePromotionFailure=true,那么会继续检查老年代最大可用连续空间是否大于历次晋升到老年代的对象的平均大小,如果大于,则尝试进行一次Minor GC,但这次Minor GC依然是有风险的,失败后会重新发起一次Full gc;如果小于或者HandlePromotionFailure=false,则改为直接进行一次Full GC。
所有才会说一次Full GC很有可能是由一次Minor GC触发的。
PS:JDK8中HotSpot为什么要取消永久代?
JDK8取消了永久代,新增了一个叫元空间(Metaspace)的区域,对应的还是JVM规范中的方法区(主要存放一些class和元数据的信息)。区别在于元空间使用的并不是JVM中的内存,而是使用本地内存。
而这么做的原因大致有以下几点:
1、字符串存在永久代中,容易出现性能问题和内存溢出。
2、类及方法的信息等比较难确定其大小,因此对于永久代的大小指定比较困难,太小容易出现永久代溢出,太大则容易导致老年代溢出。
3、永久代会为 GC 带来不必要的复杂度,并且回收效率偏低。