性能文章>JAVA应用生产问题排查步骤>

JAVA应用生产问题排查步骤原创

https://a.perfma.net/img/2382850
1年前
629404

JAVA应用生产问题排查步骤

学会这篇文章里面的命令并熟练使用,出去面试就可以说自己有5年工作经验并且精通JVM了。本篇文章中介绍的命令绝对是JAVA程序员平时工作中经常使用的并且必须会的命令,如果你不会你就是没有工作经验的人。如果你不会,那么在别人眼中你肯定就是菜鸟一个,所以本篇文章中的命令,你必须学会并且熟练使用。

注意:本篇文章内容基于JDK版本:
java version “1.6.0_113”
Java™ SE Runtime Environment (build 1.6.0_113-b01)
Java HotSpot™ 64-Bit Server VM (build 20.111-b01, mixed mode)

1 JAVA自带命令JPS

jps这个命令在JDK的安装目录bin/下面

jps命令所在目录

使用jps这个命令可以找到运行在服务器(电脑)上面的所有JVM进程。jps最常用、最有用的命令有以下俩个。

  • jps -vl

    jps -vl这个命令中的-v是输出启动JVM进程时传递给JVM的参数,-l是输出main方法所在类的完整路径或者JAR包的完成路径,命令结果如下截图:

    jps -vl命令结果

  • jps -ml

    jps -ml这个命令中的-m是输出传给main方法的参数,-l是输出main方法所在类的完整路径或者JAR包的完成路径,命令结果如下截图:

    jps -ml命令结果

    在Liunx服务器上面执行jps -ml结果如下截图:

    Linux服务器上面执行jps -ml命令结果

    工作中最常用的命令是jps -vl。jps -ml这个命令结果比较鸡肋并且不常用。你可以自己写一个main方法,在main方法里面写一个死循环,并且传递给main方法几个参数,然后再执行一下jps -vl和jps -ml这俩个命令感受一下。
    你如果光看我的文章,自己不手敲这些命令,你就是瞎看,没一点用。

如果你们公司是通过weblogic部署的应用,那么weblogic启动的时候会给JVM进程传一个参数-Dweblogic.Name=yourwebname,这个yourwebname就是你部署应用的应用名称,然后你可以通过jps -vl |grep yourwebname这个命令找到你javaweb项目的jvm进程id。

但是,如果你的应用是通过tomcat部署,那么jps -vl |grep yourwenname 这个命令就不太管用了。不过jps -vl 这个命令肯定还是管用的,因为jps是java自带的命令,跟tomcat或者weblogic没有任何关系。

如果你的应用部署在tomcat上面,那么你就用jps -vl 找tomcat这个JVM进程就可以了。原理如下:
一个tomcat就只能启动一个JVM进程,如果你的tomcat里面部署了多个Java Web应用, 那么你的多个Java Web应用共享这个一个JVM,每个JavaWeb应用都有自己的ClassLoader,也就是说一个JVM中可以有多个Class Loader。

如果其中一个JavaWeb应用发生了内存泄漏或者别的原因把JVM搞垮了,那么这个tomcat下面的所有JavaWeb应用就全挂了,所以生产环境没有人会用一个tomcat去部署多个JavaWeb应用的。生产环境,都是启动多个tomcat,每个tomcat只部署一个JavaWeb应用。

我感觉一个tomcat只能启动一个JVM进程这个设计非常弱智,假如我一个tomcat下面部署了多个JavaWeb应用,我想给每个JavaWeb应用设置不同的JVM参数都不行。现在的SpringBoot应用都是直接通过java -jar app.jar启动的,并且SpringBoot直接就内置了一个tomcat,所以你通过java -jar app.jar启动的时候就是一个tomcat只部署一个We应用。

关于tomcat的知识我是参考CSDN网站上面的大神greencacti的文章:Tomcat中会启动一个jvm还是多个jvm?

还有CSDN网站上面的大神tyyh08的文章
一个tomcat部署多个应用,有几个JVM?

2 Liunx上面top命令

使用jps命令找到我们的jvm进程ID之后赶紧使用top命令看一下服务器上面的大致情况,top命令默认好像是3秒钟刷新一次。
top 命令结果如下截图:

top 命令结果

top命令结果显示之后按小写字母c,可以显示完整的命令行,这个非常有用,一定要用。如截图

按小写字母c

然后按大写母P,以CPU使用率排序(按进程负载排序,排在最上面的就是CPU使用率最高的)

以CPU使用率排序

按大写字母M,以内存使用率排序

以内存使用率排序

高亮显示: 可以这样搞,先按大写字母P,再按小写字母b,再按小写字母x。效果如下截图:

高亮显示我想关注的列和行,bx

按键b打开或关闭 运行中进程的高亮效果

按键x打开或关闭 排序列的高亮效果

按数字 1 键,可以显示多个CPU的使用情况

显示多个CPU的使用情况

top显示的是服务器上面所有的进程概况,top类似于Windows电脑上面的的任务管理器。

Windows电脑上面的的任务管理器

但是,如果我只关心我自己的JVM进程呢?可以使用这个命令
top -p jvm进程ID,这个命令可以指定进程,只显示指定进程的概况,按空格键可以立即刷新。

top -p jvm进程ID

top -d 2 -p jvm进程ID,这个命令可以指定进程,只显示指定进程的概况,-d 2的意思是俩秒钟刷新一次。

top -d 2 -p jvm进程ID

top -Hp 进程ID,这个命令可以显示指定进程下面的线程信息,这个超级有用,必须要会。 而且这个命令搭配JAVA的自带命令jstack可以非常快速并且有效的定位代码问题。

top -Hp

然后使用Linux的自带命令,printf将线程ID转换成16进制,printf “0x%x\n” 19235

printf "0x%x\n" 19235 转换为16进制

然后使用JAVA的自带命令jstack去找到这个线程ID都在干什么就行了。这几个命令非常非常重要。

使用top命令,其实主要关注top命令里面的RES列的值,%CPU列的值,%MEM列的值,这三列的值就行了。然后
拿RES列的值跟后面jmap命令显示的jvm堆的值做比较。如果RES的值,比你的Xmx的值还大,注意是比你设置的Xmx的值还大,说明你的java程序引用的有非堆(堆外地址)内存,比如NIO,DirectByteBuffer这些类会使用堆外的内存。所以要注意堆外内存泄露情况(就是你代码里面虽然已经不用这块堆外地址了,但是你的引用没释放,导致你的程序浪费了很多用不到的堆外地址)。 堆外内存泄漏可以使用Google出品的perf工具来排查。perf工具使用参见,大神的文章 feininan的文章《使用google perf工具来排查堆外内存占用》。

这块知识点摘自网络上面MartinDai大神的文章记一次堆外内存泄漏排查过程。 执行top命令,再按c,看到对应的进程所占用的RES有8个多G(这里当时忘记截图了),但是实际上我们配置的Xmx只有3G,而且程序还是正常运行的,所以不会是堆占用了这么多,于是就把问题方向指向了非堆的内存。

RES列和%MEM列的关系为:RES/总内存=%MEM,我们来算一下:

top -p 32924

从上图可以看到,这台服务器的物理内存(运存)为:132024628k = 126G.

32924这个进程的RES列的值为:5.3G

32924这个进程的%MEM列的值为:4.2%

我们来算一下:RES:5.3G / total Mem:126G = 0.042 = 4.2%
这下你明白了吧RES列和%MEM列,表达的其实是一个意思。

RES的意思是:Resident Memory Size 常驻内存大小。使用man top命令看下top命令的官方帮助文档怎么说:

man top 查看top命令的帮助文档

%MEM列的含义

RES列的含义

TIPS:按小写字母q可以退出top命令

JVM进程的RES列的值和JVM的heap(堆)的关系也很有意思,RES列的值代表JVM进程在运行过程中曾经使用过的最大内存,注意是曾经使用过的最大内存,并不代表此时此刻JVM堆使用的内存大小。举个例子,假如JVM在业务高峰期有大量请求进来,此时堆内存使用量肯定会上升,假如此时堆内存的使用量为5G,然后触发了JVM的垃圾回收,垃圾回收之后JVM堆内存使用量下降到了1G,此时你用top命令去看这个JVM进程的RES列的值有很大可能还是5G,原因就是这5G内存目前还归属JVM进程管理并使用,JVM可能不会立即把回收掉的堆空间还给操作系统。

只要RES列的值不大于我们给JVM设置Xmx的值,就没有关系。Xmx这个参数的意思就是告诉操作系统,JVM本大爷我有可能要使用Xmx这么大的内存,你操作系统提前做好心理准备。JVM进程刚运行的时候并不会直接找操作系统要Xmx这么大的内存,JVM在运行的过程中根据自己的情况一点一点问操作系统申请的。一旦JVM进程从操作系统申请到内存之后,JVM在运行的过程中就可能就不会还给操作系统了。因为JVM跟操作系统之间如果总是借呀还呀的就会很浪费性能,没有什么必要。JVM进程退出之后占用的这些内存肯定会释放给操作系统的。关于JVM是否把空闲的堆(heap)内存还给操作系统这件事,JVM提供了一些参数:
-XX:MinHeapFreeRatio、
-XX:MaxHeapFreeRatio、
-XX:-ShrinkHeapInSteps
这几个参数你们自己查资料吧。

怎么验证这个说法?先找一个运行了1天以上的JVM进程,然后使用top命令看下这个JVM进程的RES列的值,然后再用我后面介绍的jmap -heap 19463 命令看一下JVM进程堆的使用情况就知道了。

这块知识点摘自掘金APP上面 空无 大神的文章《运维:你们 JAVA 服务内存占用太高,还只增不减!告警了,快来接锅》。
熊峰 大神的文章《JVM调优之探索CMS和G1的物理内存归还机制》。
stackoverflow 网站的提问《Does GC release back memory to OS?》。
Oracle官方文档《Default Option Values for Heap Size》。

3 JAVA自带命令–jstat,查看GC(垃圾回收情况)

jstat这个命令在JDK的安装目录bin/下面

jstat命令所在目录

3.1 使用 jstat 查看 GC(垃圾回收) 的情况

jstat -gc jvm进程PID 2000

这个命令会每隔2秒统计一下JVM进程(PID):19463的垃圾收集情况,命令最后2000的意思就是每隔2秒统计一次。使用jstat命令可以实时监测到YGC和FGC的情况,包括每次YGC和FGC各花费了多长时间,到目前为止总共进行了多少次YGC和FGC。

jstat -gc

jstat -gcutil jvm进程PID 2000

这个命令里面的-gcutil 监视内容与-gc基本相同,但输出主要关注已使用空间占总空间的百分比 。

jstat -gcutil 25436 2000

也可以写成 jstat -gcutil jvm进程PID 2s, 2s也是2秒钟刷新一次的意思。还有一种写法是jstat -gcutil 19463 2s 5,这个命令是2秒钟刷新一次,总共统计5次就行了,5次之后自动结束jstat命令,不需要你手工按crtl+c去终止命令。

jstat -gcutil 25436 2s 5

–gcutil监视内容 与 -gc基本相同,但输出主要关注已使用空间占总空间的百分比

jstat -gccause 28549 2000
gccause 与-gcutil功能一样,但是会额外输出导致上一次GC产生的原因

jstat -gccause

工作中我个人使用jstat -gccause和jstat -gc这个俩个命令比较多。

3.2 jstat输出内容解释

  • jstat -gc jvm进程PID 2000

jstat -gc的输出结果

jvm的堆(heap)空间由S0(Survivor,0号幸存区)+S1(Survivor,1号幸存区)+Eden(年轻代)+Tenured(Old老年代)+Permanent(永久代)组成的。

注意:Permanent(永久代)在jdk1.7还是jdk1.8的时候被移除了,换成Metaspace(元数据)了。注意,永久代的意思并不是这块内存永远不会回收,在发生FullGC的时候,永久代里面的垃圾也会被回收掉。

所以jstat的输出结果说明为:
S0C(Capacity):S0的最大内存,总内存。Capacity就是容量的意思。单位:kb

S0U(Used):S0目前已经使用的大小。Used就是已经使用的意思。单位:kb

EC,EU:就是年轻代

PC,PU:就是永久代

OC,OU:就是老年代

YGC:就是年轻代的GC次数

YGCT:就是年轻代GC所花费的时间,单位秒

FGC:就是FGC的次数

FGCT:就是FGC所花费的时间,单位秒

GCT:就是YGC+FGC俩个GC加起来所花费的时间,单位秒

  • jstat -gcutil 4777 2000 5

jstat -gcutil的输出结果

这个命令里面的-gcutil 监视内容与-gc基本相同,但输出主要关注已使用空间占总空间的百分比,所以-gcutil看到的是使用率。

这些命令你会使用了,关键结果你能看得懂吗?其实很简单,我们主要关注,年轻代和老年代和持久代的使用率,目前用了多少G,最大的堆内存空间配置的是多少?是不是快满了,是不是快要内存溢出了就行。GC前后的年轻代和老年代占用的空间是否减少了,如果发生了一次GC,年轻代和老年代占用的空间并没有减少,那说明你的代码发生了内存泄漏。要赶紧使用我下面介绍的jmap命令将java的堆现场的情况dump下来使用MAT软件或者GCeasy或者visualVM或者国内PerfMa社区的软件来分析dump内存文件,找到代码泄漏的真正原因。Perfma社区的阿飞Javaer大神说FullGC一天超过一次肯定就不正常了,发现FullGC频繁的时候优先调查内存泄漏问题。我认为这个说法不太对,我看了一下,我们生产环境的GC情况,FullGC一天500次左右,服务也挺正常的。并且老年代回收完使用率才13%,说明我们生产环境FullGC是可以把垃圾回收掉的。FullGC的次数本质是跟JVM的内存使用量有关系的,如果你们的系统业务很繁忙,FullGC次数多也是正常的,只有GC之后能把垃圾都回收掉就可以。并且每次FullGC的STW线程停顿时间不长也没有关系的。

4. JAVA自带命令–jinfo,查看JVM的配置信息

jinfo这个命令在JDK的安装目录bin/下面

jinfo命令所在目录

jinfo -flags 12832

这个命令可以查看我们给JVM设置的配置项和参数(默认+人工配置)

jinfo -flags 12832

这个命令没啥说的,很简单就是看我们给JVM设置的一些参数信息。

jinfo -flag MaxPermSize 1919,注意这个命令flag后面没有带s,这个命令用来看我们有没有给JVM设置MaxPermSize这个参数。如果有,就将设置的值显示出来。

jinfo -flag MaxPermSize 1919

可以看到我,我给JVM设置的永久代MaxPermSize的最大空间为:-XX:MaxPermSize=1073741824(1个G)

jinfo -flag HeapDumpPath 111552

jinfo -flag MetaspaceSize 111552

jinfo -flag 这个命令不常用,最常用的就是jinfo -flags 这个带s的直接看所有的JVM配置。

使用jinfo命令可以看到我们指定的-Xmx 堆的最大值。这里还有一个经验就是,最好将Xms(jvm堆heap的初始化大小) -Xmx(jvm堆heap的最大值),这个俩个的值设置为一样的,避免每次垃圾回收完成后JVM重新分配内存,可以防止在每次GC后进行内存重新分配,这块知识来自 Perfma社区的阿飞Javaer

5. JAVA自带命令–jmap,查看heap(堆)的内存使用情况

jmap这个命令在JDK的安装目录bin/下面

jmap命令所在目录

jmap -heap 19463 查看java 堆(heap)使用情况

注意看我的截图,一定要放大了截图,然后仔细看

jmap -heap 19463,这个截图一定要看

jmap -histo 19463 查看堆内存(histogram)中的对象数量及大小

jmap -histo 19463

jmap -histo 19463 | head -n100 只显示前100行

jmap -histo 19463 | head -n100

或者使用 jmap -histo:live 19463 | more 查看,使用more命令查看

jmap -histo:live 19463 | more

TIPS:more命令按空格可以翻页查看,按小写字母q可以退出more命令。

jmap -histo:live 19463 这个命令会先触发JVM执行GC(垃圾回收),然后再统计信息。为什么要先触发GC呢?因为这个命令live只统计活着的对象。

jmap -dump:format=b,file=9739_jvm_heap.hprof 9739

先解释一下什么叫做dump。dump的意思是转存储,那什么叫做转存储呢?转存储就是将内存(运存)中的数据导出,然后保存(持久化)下来。我们都知道APP(程序)在运行的时候也会产生一些临时数据或者APP(程序)在运行的时候也需要临时存储一些数据。这些数据的存储都是临时性的,一旦APP(程序)运行结束,这些数据就都消失了。所以当JVM运行的过程中出现问题的时候,注意是JVM在运行的时候出问题了,我们就需要把JVM运行时内存(heap堆)的情况dump(转存储),然后分析一下JVM的heap(堆)上面目前是什么情况?

jmap -dump:format=b,file=9739_jvm_heap.hprof 9739

注意: 执行该命令的时候会将整个JVM上面的所有线程都暂停,如果你的java堆比较大,比如有10个G左右,那暂停的时间可能比较长,有可能长达10分钟,所以在生产环境慎用这个命令。或者在生产环境,先让运维把请求都先负载到别的机器上面,再执行这个命令。

执行完成后在当前目录就会产生一个9739_jvm_heap.hprof 的文件

9739_jvm_heap.hprof 文件

jmap -dump:live,format=b,file=heapLive.hprof 9739 如果带上live会先触发一次GC,GC完则只转存储活着的对象。

然后,这个文件是二进制的文件,人肯定是看不懂的。所以,需要借助分析dump文件的工具,可以使用工具来分析:

  • 国内PerfMa社区的XElephant在线工具
    网站为https://console.perfma.com/https://memory.console.heapdump.cn/

XElephant在线工具

XElephant在线工具

  • GCeasy

网站为https://gceasy.io/

GCeasy

  • Memory Analyzer (MAT)

网站为https://www.eclipse.org/mat/

Memory Analyzer (MAT)

MAT这个工具有一个MemoryAnalyzer.ini配置文件:找到MemoryAnalyzer.ini文件,该文件里面有个Xmx参数,该参数表示最大内存占用量,默认为1024m,根据堆转储文件大小修改该参数即可。MAT工具要求dump文件的后缀名以.hprof结尾。B站PerfMaup主 JVM字节码的探索与实践应用(第一期)直播回放 在第56秒说:如果dump文件太大,MAT也会打不开。

MemoryAnalyzer.ini配置文件

至于这些分析JAVA dump文件的工具怎么用,你们可以自己去Google一下,我后面也会再写一篇关于这些工具的教程。不过有一点需要注意,如果你dump出来的文件很大,那么上面的工具就都不管用了,比如说你dump出来的文件大小为10G,这么大的文件上面的工具想打开一个10G的文件也非常困难了。要知道分析dump文件的工具本身也是一个APP,这个APP要分析这个10G的dump文件也需要把这个10个G的文件加载到自己的内存中去,10G他肯定是不好加载的。这个时候你只能使用jmap -histo 32924 | head -n 60这个命令手动来查看堆内存上面什么对象最多了,这个命令的截图如下:
jmap -histo 32924 | head -n 60

如果你发现这个命令的结果里面有你熟悉的类,那很大可能就是你项目中这个类的对象生成的太多了,并且使用完之后没有释放造成了内存泄漏,是有可能并不是绝对的,这个只能当线索去分析,不能当证据去使用。

如果你要看jmap -histo 32924这个命令的全部结果,可以使用jmap -histo 32924 > /tmp/java_heap_32924.txt这个命令,将命令的结果保存到文件中,然后将文件下载到本地查看。

这块知识来自 网络上的大神:Hollis Java命令学习系列(三)——Jmap
博客园上面的大神:星朝 JVM性能调优实践——JVM篇
HeapDump社区上面的大神Coder的技术之路 高并发服务优化篇:详解一次由读写锁引起的内存泄漏
HeapDump社区上面的大神:Java小能手 记一次线上服务CPU 100%的处理过程

6. JAVA自带命令–jstack,查看JVM内所有的线程运行情况

jstack这个命令在JDK的安装目录bin/下面

jstack命令所在目录

这个命令也比较简单,没啥好讲的,但是非常重要,分析问题时超级有用。 命令就是jstack -l JVMPID就行了。这个命令配合我们前面讲的top -Hp 19235 命令和 printf将线程ID转换成16进制 printf “0x%x\n” 19235 ,能非常快速定位JAVA程序中运行卡顿和缓慢的性能问题。

jstack -l 9739

jstack -l 9739

jstack -l 9739 > /tmp/9739_jvm_thread.dump

将jstack -l 9739的命令的全部输出结果都保存到文件里面去,然后再下载的本地或者网上去分析。

jstack -l 9739 > /tmp/9739_jvm_thread.dump 保存到文件

打开JAVA线程dump文件

打开JAVA线程dump文件

打开JAVA线程dump文件之后,我们就可以利用上面我们讲过的top -Hp 19235 命令和 printf将线程ID转换成16进制 printf “0x%x\n” 19235,拿到最占CPU的线程ID之后,来这个JAVA线程dump文件里面搜索这个线程,就知道这个线程在干嘛了,卡在了哪一行。

grep ‘java.lang.Thread.State’ /tmp/9739_jvm_thread.dump | wc -l

统计总共有多少线程,线程总数。线程如果太多肯定是有问题的,至于多少线程算多我也不知道。观察呗,就跟袁隆平老爷子一样,你没事多下地观察一下水稻是怎么生长的就知道了,经验就是这么来的。你们项目平时正常运行的时候,你上去统计一下,等过一段时间你们项目真出问题了你跟平时的经验对比一下就小葱拌豆腐一清二白了。

统计线程数

grep “java.lang.Thread.State” /tmp/20210713_thread.log |sort| uniq -c | sort -nr

grep “java.lang.Thread.State” /tmp/20210713_vhlthread.log |sort| uniq -c | sort -nr 使用这个命令看下所有的线程都处于什么状态

线程都处于什么状态?

上面介绍的命令使用起来毕竟太原始,效率太低了,不是人干的事。区分一个程序猿到底猴子还是人,主要看他会不会使用工具。介绍俩个分析线程快照的工具:

  • fastThread

网站为https://fastthread的具体使用教程,你们自己网上Google吧。.io/

fastthread——JAVA线程分析工具

分析结果

fastthread——JAVA线程分析结果

fastthread——JAVA线程分析结果

fastthread——JAVA线程分析结果

fastthread的具体使用教程,你们自己网上Google吧。

  • 国内HeapDump社区的XSheepdog在线工具
    网站为https://www.perfma.com/https://console.heapdump.cn/

XSheepdog-JAVA线程在线分析工具

XSheepdog-JAVA线程在线分析结果

XSheepdog-JAVA线程在线分析结果

更多用法需要你自己动手去挖掘。

点赞收藏
四千岁

请关注俺的微信公众号:四千岁

请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

记一次线上RPC超时故障排查及后续GC调优思路

记一次线上RPC超时故障排查及后续GC调优思路

解读JVM级别本地缓存Caffeine青出于蓝的要诀 —— 缘何会更强、如何去上手

解读JVM级别本地缓存Caffeine青出于蓝的要诀 —— 缘何会更强、如何去上手

【全网首发】一次疑似 JVM Native 内存泄露的问题分析

【全网首发】一次疑似 JVM Native 内存泄露的问题分析

解读JVM级别本地缓存Caffeine青出于蓝的要诀2 —— 弄清楚Caffeine的同步、异步回源方式

解读JVM级别本地缓存Caffeine青出于蓝的要诀2 —— 弄清楚Caffeine的同步、异步回源方式

【全网首发】从源码角度分析一次诡异的类被加载问题

【全网首发】从源码角度分析一次诡异的类被加载问题

4
0