JAVA线上常见问题排查CPU飙高内存打满排查

首先执行最简单的四步骤,再逐步检查

{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 命令是 Linux 下常用的 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}

  1. GC 日志分析
    GC 日志详细分析
    Java 虚拟机 GC 日志是用于定位问题重要的日志信息,频繁的 GC 将导致应用吞吐量下降、响应时间增加,甚至导致服务不可用。
    -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/usr/local/gc/gc.log -XX:+UseConcMarkSweepGC

我们可以在 java 应用的启动参数中增加 -XX:+PrintGCDetails 可以输出 GC 的详细日志,例外还可以增加其他的辅助参数,如-Xloggc 制定 GC 日志文件地址。如果你的应用还没有开启该参数 , 下次重启时请加入该参数。

上图为线上某应用在平稳运行状态下的 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 带来不必要的复杂度,并且回收效率偏低。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 202,802评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,109评论 2 379
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 149,683评论 0 335
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,458评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,452评论 5 364
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,505评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,901评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,550评论 0 256
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,763评论 1 296
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,556评论 2 319
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,629评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,330评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,898评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,897评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,140评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,807评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,339评论 2 342

推荐阅读更多精彩内容