Java线上故障排查

客官°小女子只卖身不卖艺 2023-09-27 10:27 100阅读 0赞

线上故障主要会包括cpu、磁盘、内存以及网络问题，而大多数故障可能会包含不止一个层面的问题，所以进行排查时候尽量四个方面依次排查一遍。同时例如jstack、jmap等工具也是不囿于一个方面的问题的，基本上出问题就是df、free、top 三连，然后依次jstack、jmap伺候，具体问题具体分析即可。

### cpu ###

一般来讲我们首先会排查cpu方面的问题。cpu异常往往还是比较好定位的。原因包括业务逻辑问题(死循环)、频繁gc（这个归到下面的GC章节里说）以及上下文切换过多。而最常见的往往是业务逻辑(或者框架逻辑)导致的，可以使用jstack来分析对应的堆栈情况。

#### jstack ####

我们先用**ps**命令找到对应进程的pid(如果你有好几个目标进程，可以先用top看一下哪个占用比较高)。

> ps

接着用**top -H -p pid**来找到cpu使用率比较高的一些线程，然后将占用最高的pid转换为16进制**printf ‘%x\\n’ pid**得到nid

> **top -H -p pid**  
> **printf ‘%x\\n’ pid**

接着直接在jstack中找到相应的堆栈信息

> **jstack pid |grep ‘nid’ -C5 –color**

![在这里插入图片描述][f4ed8581c9324c1d8ddd8383f73a687d.png]

可以看到我们已经找到了nid为0x42的堆栈信息，接着只要仔细分析一番即可。  
当然更常见的是我们对整个jstack文件进行分析，通常我们会比较关注WAITING和TIMED\_WAITING的部分，BLOCKED就不用说了。  
我们可以使用以下命令来对jstack的状态有一个整体的把握，如果WAITING之类的特别多，那么多半是有问题啦。

> cat jstack.log | grep “java.lang.Thread.State” | sort -nr | uniq -c

#### 上下文切换 ####

针对频繁上下文问题，我们可以使用**vmstat**命令来进行查看  
![在这里插入图片描述][5124397a76be4ed9be2ef241f1ad94c1.png]

更细致的命令，以3秒为时间间隔，连续收集10次性能数据：

> vmstat 3 10

cs(context switch)一列则代表了上下文切换的次数。 如果我们希望对特定的pid进行监控那么可以使用

> pidstat -w pid

![在这里插入图片描述][48d9464e73464a6eb78b40c3933cce75.png]

cswch和nvcswch表示自愿及非自愿切换。

### 磁盘 ###

磁盘问题和cpu一样是属于比较基础的。首先是磁盘空间方面，我们直接使用下面的命令来查看文件系统状态

> df -hl

![在这里插入图片描述][137350e4f70545768aa11e7edbbd6fbc.png]

更多时候，磁盘问题还是性能上的问题。我们可以通过下面命令来进行分析

> iostatiostat -d -k -x

![在这里插入图片描述][217f13cf5f774167ab1b9392c4e74926.png]

最后一列%util可以看到每块磁盘写入的程度，而rrqpm/s以及wrqm/s分别表示读写速度，一般就能帮助定位到具体哪块磁盘出现问题了。

不过这边拿到的是tid，我们要转换成pid，可以通过readlink来找到pid。

> readlink -f /proc/\*/task/tid/…/…

![在这里插入图片描述][7bf65f571cb04ed6ae71d12a8a60c0d7.png]

找到pid之后就可以看这个进程具体的读写情况

> cat /proc/pid/io

![在这里插入图片描述][dd0d950ec96b446c8d44754dc05e6298.png]

确定具体的文件读写情况

> lsof -p pid

![在这里插入图片描述][bac7554ce198456cb621c243547d7276.png]

### 内存 ###

内存问题排查起来相对比CPU麻烦一些，场景也比较多。主要包括OOM、GC问题和堆外内存。一般来讲，我们会先用**free**命令先来检查一发内存的各种情况。  
![在这里插入图片描述][91d1f265e96343d39d6d2701d3a2e3ae.png]

#### 堆内内存 ####

内存问题大多还都是堆内内存问题。表象上主要分为OOM和StackOverflow。

##### OOM #####

JMV中的内存不足，OOM大致可以分为以下几种：

*  **Exception in thread “main” java.lang.OutOfMemoryError: unable to create new native thread** 这个意思是没有足够的内存空间给线程分配java栈，基本上还是线程池代码写的有问题，比如说忘记shutdown，所以说应该首先从代码层面来寻找问题，使用jstack或者jmap。如果一切都正常，JVM方面可以通过指定Xss来减少单个thread stack的大小。另外也可以在系统层面，可以通过修改/etc/security/limits.confnofile和nproc来增大os对线程的限制
 *  **Exception in thread “main” java.lang.OutOfMemoryError: Java heap space** 这个意思是堆的内存占用已经达到-Xmx设置的最大值，应该是最常见的OOM错误了。解决思路仍然是先应该在代码中找，怀疑存在内存泄漏，通过jstack和jmap去定位问题。如果说一切都正常，才需要通过调整Xmx的值来扩大内存。
 *  **Caused by: java.lang.OutOfMemoryError: Meta space** 这个意思是元数据区的内存占用已经达到XX:MaxMetaspaceSize设置的最大值，排查思路和上面的一致，参数方面可以通过XX:MaxPermSize来进行调整(这里就不说1.8以前的永久代了)。

##### StackOverflow #####

栈内存溢出，这个大家见到也比较多。 **Exception in thread “main” java.lang.StackOverflowError** 表示线程栈需要的内存大于Xss值，同样也是先进行排查，参数方面通过Xss来调整，但调整的太大可能又会引起OOM。

##### jmap #####

上述关于OOM和StackOverflow的代码排查方面，我们一般使用JMAP

> jmap -dump:format=b,file=filename pid

来导出dump文件，通过mat(Eclipse Memory Analysis Tools)等dump分析软件导入dump文件进行分析，内存泄漏问题一般我们直接选Leak Suspects即可，mat给出了内存泄漏的建议。另外也可以选择Top Consumers来查看最大对象报告。和线程相关的问题可以选择thread overview进行分析。除此之外就是选择Histogram类概览来自己慢慢分析，大家可以搜搜mat的相关教程。  
![在这里插入图片描述][ae6ab3447626441faddf68f23e3155ee.png]

![在这里插入图片描述][7128c21977634fb89b9c465e3db7fd1a.png]

日常开发中，代码产生内存泄漏是比较常见的事，并且比较隐蔽，需要开发者更加关注细节。比如说每次请求都new对象，导致大量重复创建对象；进行文件流操作但未正确关闭；手动不当触发gc；ByteBuffer缓存分配不合理等都会造成代码OOM。  
另一方面，我们可以在启动参数中指定下面命令来保存OOM时的dump文件。

> \-XX:+HeapDumpOnOutOfMemoryError

#### 堆外内存 ####

如果碰到堆外内存溢出，那可真是太不幸了。首先堆外内存溢出表现就是物理常驻内存增长快，报错的话视使用方式都不确定，如果由于使用Netty导致的，那错误日志里可能会出现**OutOfDirectMemoryError**错误，如果直接是DirectByteBuffer，那会报**OutOfMemoryError: Direct buffer memory**。  
堆外内存溢出往往是和NIO的使用相关，一般我们先通过pmap来查看下进程占用的内存情况

> pmap -x pid | sort -rn -k3 | head -30

这段意思是查看对应pid倒序前30大的内存段。这边可以再一段时间后再跑一次命令看看内存增长情况，或者和正常机器比较可疑的内存段在哪里。

![在这里插入图片描述][93dd3bac3b7d427e933b9add54b1ee2e.png]

不过其实上面那些操作也很难定位到具体的问题点，关键还是要看错误日志栈，找到可疑的对象，搞清楚它的回收机制，然后去分析对应的对象。比如DirectByteBuffer分配内存的话，是需要full GC或者手动system.gc来进行回收的(所以最好不要使用-XX:+DisableExplicitGC)。那么其实我们可以跟踪一下DirectByteBuffer对象的内存情况，通过**jmap -histo:live pid**手动触发fullGC来看看堆外内存有没有被回收。如果被回收了，那么大概率是堆外内存本身分配的太小了，通过\*\*-XX:MaxDirectMemorySize\*\*进行调整。如果没有什么变化，那就要使用jmap去分析那些不能被gc的对象，以及和DirectByteBuffer之间的引用关系了。

### GC问题 ###

欲善其事必利其器，所以我们得知道gc能通过什么工具进行查看信息：

*  公司的监控系统：大部分公司都会有，可全方位监控JVM的各项指标。
 *  JDK的自带工具，包括jmap、jstat等常用命令：
    
     *  查看堆内存各区域的使用率以及GC情况 ：jstat -gcutil -h20 pid 1000
     *  查看堆内存中的存活对象，并按空间排序：jmap -histo pid | head -n20
     *  dump堆内存文件：jmap -dump:format=b,file=heap pid
 *  可视化的堆内存分析工具：JVisualVM、MAT等

有时候我们可以先确定下gc是不是太频繁，使用下面命令来对gc分代变化情况进行观察。

> jstat -gc pid 1000

![在这里插入图片描述][0d4b3ac687ec4847a4441da852d0420f.png]

1000表示采样间隔(ms)，S0C/S1C、S0U/S1U、EC/EU、OC/OU、MC/MU分别代表两个Survivor区、Eden区、老年代、元数据区的容量和使用量。YGC/YGT、FGC/FGCT、GCT则代表YGC、FGC的耗时和次数以及总耗时。如果看到gc比较频繁，再针对gc方面做进一步分析。

我们是通过GC日志来排查问题的，在启动参数中加上\*\*-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps **来开启GC日志, jdk8以上的话也可以使用**\-Xlog:gc\*\*\*来查看日志。

GC会对程序产生影响呢？根据严重程度从高到底，我认为包括以下4种情况：

*  YGC过于频繁：即使YGC不会引起服务超时，但是YGC过于频繁也会降低服务的整体性能，对于高并发服务也是需要关注的。
 *  YGC耗时过长：一般来说，YGC的总耗时在几十或者上百毫秒是比较正常的，虽然会引起系统卡顿几毫秒或者几十毫秒，这种情况几乎对用户无感知，对程序的影响可以忽略不计。但是如果YGC耗时达到了1秒甚至几秒（都快赶上FGC的耗时了），那卡顿时间就会增大，加上YGC本身比较频繁，就会导致比较多的服务超时问题。
 *  FGC过于频繁：FGC通常是比较慢的，少则几百毫秒，多则几秒，正常情况FGC每隔几个小时甚至几天才执行一次，对系统的影响还能接受。但是，一旦出现FGC频繁（比如几十分钟就会执行一次），这种肯定是存在问题的，它会导致工作线程频繁被停止，让系统看起来一直有卡顿现象，也会使得程序的整体性能变差。
 *  FGC耗时过长：FGC耗时增加，卡顿时间也会随之增加，尤其对于高并发服务，可能导致FGC期间比较多的超时问题，可用性降低，这种也需要关注。

其中，「FGC过于频繁」和「YGC耗时过长」，这两种情况属于比较典型的GC问题，大概率会对程序的服务质量产生影响。剩余两种情况的严重程度低一些，但是对于高并发或者高可用的程序也需要关注。

#### YGC过频繁 ####

YGC 频繁一般是短周期小对象较多，先考虑是不是 新生代设置的太小了，看能否通过调整 **-Xmn、-XX:SurvivorRatio** 等参数设置来解决问题。如果参数正常，但是 young gc 频率还是太高，就需要使用 jmap 和mat对 dump 文件进行进一步排查了。

#### **YGC耗时过长** ####

耗时过长问题就要看GC日志里耗时耗在哪一块了。以G1日志为例，可以关注Root Scanning、Object Copy、Ref Proc等阶段。Ref Proc耗时长，就要注意引用相关的对象。Root Scanning耗时长，就要注意线程数、跨代引用。Object Copy 则需要关注对象生存周期。而且耗时分析它需要横向比较，就是和其他项目或者正常时间段的耗时比较。比如说图中的Root Scanning和正常时间段比增长较多，那就是起的线程太多了。

#### FGC过频繁 ####

FGC 频繁有可能就是内存不够的，得进行扩容，或者是代码里显性调用System.gc()，否则的话就是出现堆内内存泄漏。还是得使用 jmap 和mat对 dump 文件进行进一步排查了。

#### **FGC耗时过长** ####

这个比较难搞，每种收集器的处理方式都不一样，只能根据各自的特性来调整配置解决问题。

### 网络问题 ###

涉及到网络层面的问题一般都比较复杂，场景多，定位难，成为了大多数开发的噩梦，应该是最复杂的了。这里会举一些例子，并从tcp层、应用层以及工具的使用等方面进行阐述。

#### 超时 ####

超时错误大部分处在应用层面，所以这块着重理解概念。超时大体可以分为连接超时和读写超时，某些使用连接池的客户端框架还会存在获取连接超时和空闲连接清理超时。

*  读写超时。readTimeout/writeTimeout，有些框架叫做so\_timeout或者socketTimeout，均指的是数据读写超时。注意这边的超时大部分是指逻辑上的超时。soa的超时指的也是读超时。读写超时一般都只针对客户端设置。
 *  连接超时。connectionTimeout，客户端通常指与服务端建立连接的最大时间。服务端这边connectionTimeout就有些五花八门了，jetty中表示空闲连接清理时间，tomcat则表示连接维持的最大时间。
 *  其他。包括连接获取超时connectionAcquireTimeout和空闲连接清理超时idleConnectionTimeout。多用于使用连接池或队列的客户端或服务端框架。

我们在设置各种超时时间中，需要确认的是尽量保持客户端的超时小于服务端的超时，以保证连接正常结束。  
在实际开发中，我们关心最多的应该是接口的读写超时了。  
如何设置合理的接口超时是一个问题。如果接口超时设置的过长，那么有可能会过多地占用服务端的tcp连接。而如果接口设置的过短，那么接口超时就会非常频繁。  
服务端接口明明rt降低，但客户端仍然一直超时又是另一个问题。这个问题其实很简单，客户端到服务端的链路包括网络传输、排队以及服务处理等，每一个环节都可能是耗时的原因。

#### TCP队列溢出 ####

tcp队列溢出是个相对底层的错误，它可能会造成超时、rst等更表层的错误。因此错误也更隐蔽，所以我们单独说一说。  
![在这里插入图片描述][89768ba0435b4091a8cbc99a2cd0187d.png]

如上图所示，这里有两个队列：syns queue(半连接队列）、accept queue（全连接队列）。三次握手，在server收到client的syn后，把消息放到syns queue，回复syn+ack给client，server收到client的ack，如果这时accept queue没满，那就从syns queue拿出暂存的信息放入accept queue中，否则按tcp\_abort\_on\_overflow指示的执行。  
tcp\_abort\_on\_overflow 0表示如果三次握手第三步的时候accept queue满了那么server扔掉client发过来的ack。tcp\_abort\_on\_overflow 1则表示第三步的时候如果全连接队列满了，server发送一个rst包给client，表示废掉这个握手过程和这个连接，意味着日志里可能会有很多**connection reset / connection reset by peer**。  
那么在实际开发中，我们怎么能快速定位到tcp队列溢出呢？使用以下命令：

> **netstat命令，执行netstat -s | egrep “listen|LISTEN”**

![在这里插入图片描述][0955f26ff1ec473a895f7aa2d0517757.png]

如上图所示，overflowed表示全连接队列溢出的次数，sockets dropped表示半连接队列溢出的次数。

或者以下命令：

> **ss -lnt**

![在这里插入图片描述][fe6a2b09d6b046a995d0c76af3e9e543.png]

上面看到Send-Q 表示第三列的listen端口上的全连接队列最大为5，第一列Recv-Q为全连接队列当前使用了多少。  
接着我们看看怎么设置全连接、半连接队列大小吧：  
全连接队列的大小取决于min(backlog, somaxconn)。backlog是在socket创建的时候传入的，somaxconn是一个os级别的系统参数。而半连接队列的大小取决于max(64, /proc/sys/net/ipv4/tcp\_max\_syn\_backlog)。  
在日常开发中，我们往往使用servlet容器作为服务端，所以我们有时候也需要关注容器的连接队列大小。在tomcat中backlog叫做**acceptCount**，在jetty里面则是**acceptQueueSize**。

#### RST异常 ####

RST包表示连接重置，用于关闭一些无用的连接，通常表示异常关闭，区别于四次挥手。  
在实际开发中，我们往往会看到**connection reset / connection reset by peer**错误，这种情况就是RST包导致的。

##### 端口不存在 #####

如果像不存在的端口发出建立连接SYN请求，那么服务端发现自己并没有这个端口则会直接返回一个RST报文，用于中断连接。

##### 主动代替FIN终止连接 #####

一般来说，正常的连接关闭都是需要通过FIN报文实现，然而我们也可以用RST报文来代替FIN，表示直接终止连接。实际开发中，可设置SO\_LINGER数值来控制，这种往往是故意的，来跳过TIMED\_WAIT，提供交互效率，不闲就慎用。

##### 客户端或服务端有一边发生了异常，该方向对端发送RST以告知关闭连接 #####

我们上面讲的tcp队列溢出发送RST包其实也是属于这一种。这种往往是由于某些原因，一方无法再能正常处理请求连接了(比如程序崩了，队列满了)，从而告知另一方关闭连接。

##### 接收到的TCP报文不在已知的TCP连接内 #####

比如，一方机器由于网络实在太差TCP报文失踪了，另一方关闭了该连接，然后过了许久收到了之前失踪的TCP报文，但由于对应的TCP连接已不存在，那么会直接发一个RST包以便开启新的连接。

##### 一方长期未收到另一方的确认报文，在一定时间或重传次数后发出RST报文 #####

这种大多也和网络环境相关了，网络环境差可能会导致更多的RST报文。  
之前说过RST报文多会导致程序报错，在一个已关闭的连接上读操作会报connection reset，而在一个已关闭的连接上写操作则会报connection reset by peer。通常我们可能还会看到broken pipe错误，这是管道层面的错误，表示对已关闭的管道进行读写，往往是在收到RST，报出connection reset错后继续读写数据报的错，这个在glibc源码注释中也有介绍。  
我们在排查故障时候怎么确定有RST包的存在呢？当然是使用tcpdump命令进行抓包，并使用wireshark进行简单分析了。tcpdump -i en0 tcp -w xxx.cap，en0表示监听的网卡。  
![在这里插入图片描述][9a48cca2397f4916bd13b7d0adb6d84c.png]

接下来我们通过wireshark打开抓到的包，可能就能看到如下图所示，红色的就表示RST包了。  
![在这里插入图片描述][7a53e85b8cbf449b996d1fa534e4c0f1.png]

#### TIME\_WAIT和CLOSE\_WAIT ####

TIME\_WAIT和CLOSE\_WAIT是啥意思相信大家都知道。 在线上时，我们可以直接用命令

> netstat -n | awk ‘/^tcp/ \{++S\[$NF\]\} END \{for(a in S) print a, S\[a\]\}’

来查看time-wait和close\_wait的数量  
用ss命令会更快

> ss -ant | awk ‘\{++S\[$1\]\} END \{for(a in S) print a, S\[a\]\}’

##### TIME\_WAIT #####

time\_wait的存在一是为了丢失的数据包被后面连接复用，二是为了在2MSL的时间范围内正常关闭连接。它的存在其实会大大减少RST包的出现。  
过多的time\_wait在短连接频繁的场景比较容易出现。这种情况可以在服务端做一些内核参数调优:

#表示开启重用。允许将TIME-WAIT sockets重新用于新的TCP连接，默认为0，表示关闭
    net.ipv4.tcp_tw_reuse = 1
    #表示开启TCP连接中TIME-WAIT sockets的快速回收，默认为0，表示关闭
    net.ipv4.tcp_tw_recycle = 1

当然我们不要忘记在NAT环境下因为时间戳错乱导致数据包被拒绝的坑了，另外的办法就是改小tcp\_max\_tw\_buckets，超过这个数的time\_wait都会被干掉，不过这也会导致报time wait bucket table overflow的错。

##### CLOSE\_WAIT #####

close\_wait往往都是因为应用程序写的有问题，没有在ACK后再次发起FIN报文。close\_wait出现的概率甚至比time\_wait要更高，后果也更严重。往往是由于某个地方阻塞住了，没有正常关闭连接，从而渐渐地消耗完所有的线程。  
想要定位这类问题，最好是通过jstack来分析线程堆栈来排查问题，具体可参考上述章节。这里仅举一个例子。  
开发同学说应用上线后CLOSE\_WAIT就一直增多，直到挂掉为止，jstack后找到比较可疑的堆栈是大部分线程都卡在了countdownlatch.await方法，找开发同学了解后得知使用了多线程但是确没有catch异常，修改后发现异常仅仅是最简单的升级sdk后常出现的class not found。

[f4ed8581c9324c1d8ddd8383f73a687d.png]: https://img-blog.csdnimg.cn/f4ed8581c9324c1d8ddd8383f73a687d.png
[5124397a76be4ed9be2ef241f1ad94c1.png]: https://img-blog.csdnimg.cn/5124397a76be4ed9be2ef241f1ad94c1.png
[48d9464e73464a6eb78b40c3933cce75.png]: https://img-blog.csdnimg.cn/48d9464e73464a6eb78b40c3933cce75.png
[137350e4f70545768aa11e7edbbd6fbc.png]: https://img-blog.csdnimg.cn/137350e4f70545768aa11e7edbbd6fbc.png
[217f13cf5f774167ab1b9392c4e74926.png]: https://img-blog.csdnimg.cn/217f13cf5f774167ab1b9392c4e74926.png
[7bf65f571cb04ed6ae71d12a8a60c0d7.png]: https://img-blog.csdnimg.cn/7bf65f571cb04ed6ae71d12a8a60c0d7.png
[dd0d950ec96b446c8d44754dc05e6298.png]: https://img-blog.csdnimg.cn/dd0d950ec96b446c8d44754dc05e6298.png
[bac7554ce198456cb621c243547d7276.png]: https://img-blog.csdnimg.cn/bac7554ce198456cb621c243547d7276.png
[91d1f265e96343d39d6d2701d3a2e3ae.png]: https://img-blog.csdnimg.cn/91d1f265e96343d39d6d2701d3a2e3ae.png
[ae6ab3447626441faddf68f23e3155ee.png]: https://img-blog.csdnimg.cn/ae6ab3447626441faddf68f23e3155ee.png
[7128c21977634fb89b9c465e3db7fd1a.png]: https://img-blog.csdnimg.cn/7128c21977634fb89b9c465e3db7fd1a.png
[93dd3bac3b7d427e933b9add54b1ee2e.png]: https://img-blog.csdnimg.cn/93dd3bac3b7d427e933b9add54b1ee2e.png
[0d4b3ac687ec4847a4441da852d0420f.png]: https://img-blog.csdnimg.cn/0d4b3ac687ec4847a4441da852d0420f.png
[89768ba0435b4091a8cbc99a2cd0187d.png]: https://img-blog.csdnimg.cn/89768ba0435b4091a8cbc99a2cd0187d.png
[0955f26ff1ec473a895f7aa2d0517757.png]: https://img-blog.csdnimg.cn/0955f26ff1ec473a895f7aa2d0517757.png
[fe6a2b09d6b046a995d0c76af3e9e543.png]: https://img-blog.csdnimg.cn/fe6a2b09d6b046a995d0c76af3e9e543.png
[9a48cca2397f4916bd13b7d0adb6d84c.png]: https://img-blog.csdnimg.cn/9a48cca2397f4916bd13b7d0adb6d84c.png
[7a53e85b8cbf449b996d1fa534e4c0f1.png]: https://img-blog.csdnimg.cn/7a53e85b8cbf449b996d1fa534e4c0f1.png