一次生产环境大量CLOSE_WAIT导致服务无法访问的定位过程

喜欢ヅ旅行 2022-01-29 00:39 442阅读 0赞

## 1.症状 ##

生产环境的一个服务突然无法访问，服务的交互过程如下所示：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70]  
所有的请求都是通过网关进入，之后分发到后端服务。

现在的情况是用户服务无法访问商旅服务，网关有大量`java.net.SocketTimeoutException: Read timed out`报错日志，商旅服务也不断有日志打印，大多是回调和定时任务日志，所以故障点在网关和商旅服务，大概率是商旅服务无法访问导致网关超时。

后续执行过如下的操作：

*  重启商旅服务，访问正常，过几小时后服务又无法访问
 *  重启网关，服务依旧无法访问，接着重启商旅服务，正常访问，过几小时后服务又无法访问
 *  用户调用商旅通路测试接口，无法访问；在网关机器上访问商旅通路测试接口，依旧无法访问；
 *  商旅重启后，网关机器上可以访问商旅通路测试接口

通过上面的操作可以断定网关是OK的，故障点在商旅服务。

## 2.第一次定位 ##

运维使用Top命令（类似于Windows的任务管理器）查看了下机器的状况，如下所示（仅供参考）：  
![在这里插入图片描述][20190520120814991.png]

> 参数解释如下：  
> 　VIRT：进程占用的虚拟内存  
> 　RES：进程占用的物理内存  
> 　SHR：进程使用的共享内存  
> 　S：进程的状态。S表示休眠，R表示正在运行，Z表示僵死状态，N表示该进程优先值为负数  
> 　%CPU：进程占用CPU的使用率  
> 　%MEM：进程使用的物理内存和总内存的百分比

执行`netstat -nat | grep "CLOSE_WAIT"`发现有大量的`CLOSE_WAIT`连接。参考如下：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 1]  
商旅JVM堆内存限制为512M，但是上面显示使用了988M（大了很多），然后在结合运维的经验`JDK7 升级到JDK8后一些JVM参数实效`，看了下现在使用的JVM参数为`-ms512m -mx512m`，这个被认为是旧的JVM参数。所以就断定是JVM参数失效导致内存未限制住，多个JVM内存争用导致服务不可用。于是做出了如下的解决方案：  
把JVM启动参数从`-ms512m -mx512m`改成 `–Xms256m –Xmx512m`，重启服务，正常访问。

## 3.第二次定位 ##

大约过了不到一天，服务又无法访问，top命令结果和第一次定位是一致的，此时依旧认为是JVM参数未生效，内存相互争用导致。由于线上服务还有人等待订票，所以先执行`jmap -dump:format=b,file=文件名 [pid]`导出dump文件供后续定位，然后重启服务后恢复正常。

分析Dump 文件，可用使用`jhat、MAT、jvisualvm`来分析，查看JVM堆内存使用情况，以便查找内存溢出原因。  
正如Thread Dump文件记录了当时JVM中线程运行的情况一样，Heap Dump记录了JVM中堆内存运行的情况。

`jhat`是JDK自带的用于分析JVM Heap Dump文件的工具，使用`jhat <heap-dump-file>`命令可以将堆文件的分析结果以HTML网页的形式进行展示，执行成功之后显示如下结果：`Snapshot resolved.Started HTTP server on port 7000Server is ready.`这个时候访问 [http://localhost:7000/][http_localhost_7000] 就可以看到结果了。但实际通常使用`MAT、jvisualvm`来分析。

建议在JVM启动时增加`-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=c:/heap.bin`参数，所代表的含义就是当程序出现OutofMemory时，将会在相应的目录下生成一份dump文件，而如果不指定选项“XX:HeapDumpPath”则在当前目录下生成dump文件。尽管不借助jmap工具，MAT工具也能够直接生成dump文件，但是考虑到生产环境中几乎不可能在线对其进行分析，大都是采用离线分析，因此使用jmap+MAT工具是最常见的组合。

#### 3.1使用jvisualvm ####

jvisualvm是JDK自带的Java性能分析工具，在JDK的bin目录下，文件名就叫`jvisualvm.exe`。  
jvisualvm可以监控本地、远程的java进程，实时查看进程的cpu、堆、线程等参数，对java进程生成dump文件，并对dump文件进行分析。  
本次是从服务器上dump下来文件，扔给jvisualvm来分析。  
使用方式：直接双击打开jvisualvm.exe，点击文件->装入，在文件类型那一栏选择堆，选择要分析的dump文件，打开。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 2]  
通过分析，并未发现异常，没有内存泄露的痕迹，也没有异常的大的对象。

#### 3.2 Eclipse Memory Analyzer(MAT) ####

Eclipse Memory Analyzer（简称MAT）是一个功能丰富且操作简单的JVM Heap Dump分析工具，可以用来辅助发现内存泄漏减少内存占用。  
MAT支持两种安装方式，一是Eclipse插件的方式，另外一个就是独立运行的方式，建议使用独立运行的方式。  
分析结果如下：  
Overview：概要界面，显示了概要的信息  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 3]  
Histogram： 直方图，可以查看每个类的实例（即对象）的数量和大小。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 4]  
Dominator Tree：支配树，列出Heap Dump中处于活跃状态中的最大的几个对象，默认按 retained size进行排序，因此很容易找到占用内存最多的对象。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 5]  
通过分析，均无内存溢出的痕迹，也无大对象等。MAT用法详见:  
[Java内存泄漏分析系列之六：JVM Heap Dump（堆转储文件）的生成和MAT的使用][Java_JVM Heap Dump_MAT]  
[Java内存分析工具MAT(Memory Analyzer Tool)安装使用实例][Java_MAT_Memory Analyzer Tool]

#### 3.3结论 ####

商旅服务无内存泄露的问题，也不存在内存争用的问题（下面会讲），定位的方向最初就是错误的，于是换思路重新定位问题。

## 4.第三次定位 ##

很快，服务有发生了不可访问，不过这次的重点放在了已近有一些征兆的`CLOSE_WAIT`上。

#### 4.1 文确认件描述符超出限制导致 ####

执行`ulimit -a`, 发现open files是65535，已经做过了优化，不是fd的问题。  
查看商旅进程使用的Fd数量(统计进程打开的句柄数)。`ls -l /proc/pid/fd | wc -l`结果如下，打开的确实很多，但是距离65535相差甚远。  
![在这里插入图片描述][20190520142924372.png]

#### 4.2 查看堆的情况 ####

执行`jmap -heap pid`查看堆信息，一切正常，最大堆设置已经生效。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 6]  
对应关系，给张图自己体会：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 7]  
最大堆为512M，但是top命令看到实际使用了988M，什么原因？  
![在这里插入图片描述][20190520120814991.png]  
什么是RES和VIRT？

*  RES：resident memory usage 常驻内存  
    （1）进程当前使用的内存大小，但不包括swap out  
    （2）包含其他进程的共享  
    （3）如果申请100m的内存，实际使用10m，它只增长10m，与VIRT相反  
    （4）关于库占用内存的情况，它只统计加载的库文件所占内存大小  
    RES = CODE + DATA
 *  VIRT：virtual memory usage  
    （1）进程“需要的”虚拟内存大小，包括进程使用的库、代码、数据等  
    （2）假如进程申请100m的内存，但实际只使用了10m，那么它会增长100m，而不是实际的使用量  
    VIRT = SWAP + RES

Linux与进程内存模型  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 8]  
JVM内存模型（1.7与1.8之间的区别）  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 9]

所以JVM进程内存大小大致为：  
非heap（非heap=元空间+栈内存+…）+heap+JVM进程运行所需内存+其他数据等。

所以对应到商旅988M= 512M（堆） + 283 \*1M（283个线程，每个线程占用1M）+JVM进程本身运行内存+ NIO的DirectBuffer +JIT+JNI+…,所以top命令显示出的实际内存大于512是合理的。

使用系统命令`pmap -x pid`查看进程的内存映射情况，会发现大量的六十多MB内存块存在，这个就表示申请了这么大的内存（影响VIRT），但是实际使用的肯定小于这个值（影响RES），这也解释了为什么VIRT很大，几个G。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 10]

#### 4.3 查看商旅进程中的线程数 ####

执行`ls /proc/17493/task |wc -l`(统计进程打开的线程数)，结果如下：  
![在这里插入图片描述][20190520143206477.png]  
总计283个线程。也不是很多。

#### 4.4查看GC情况 ####

执行`jstat -gc pid`或者`stat -gc pid 5000 2000`  
![在这里插入图片描述][20190520160752227.png]  
gc的次数也不是很多，时间也不长。

#### 4.5TCP连接状态统计 ####

执行`netstat -n | awk '/^tcp/ {++state[$NF]} END {for(key in state) print key,"\t",state[key]}'`统计TCP状态情况，  
![在这里插入图片描述][20190520161043895.png]  
常用的三个状态是：ESTABLISHED 表示正在通信，TIME\_WAIT 表示主动关闭，CLOSE\_WAIT 表示被动关闭 因为linux分配给一个用户的文件句柄是有限的，而TIME\_WAIT和CLOSE\_WAIT两种状态如果一直被保持，那么意味着对应数目的通道就一直被占着，而且是“占着茅坑不使劲”，一旦达到句柄数上限，新的请求就无法被处理了，接着就是大量Too Many Open Files异常；如果未达到句柄数上限，也可能会出现无连接可用的情况。  
上面发现大量的连接处于CLOSE\_WAIT，这可能就是服务不可访问的原因。  
这说明是客户端先关闭了连接，服务器端没有执行关闭连接的操作，导致服务器端一直维持在CLOSE\_WAIT的状态。详见下图：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 11]

查看TCP的keep\_alive参数`sysctl -a |grep keepalive` ,结果如下：  
![在这里插入图片描述][20190520161859895.png]  
TCP默认的保活时间为2个小时，也就是说两个小时TCP才会主动帮我们会清理一次无用的连接。所以现在的问题是什么原因造成了大量CLOSE\_WAIT的产生。

TIME\_WAIT状态可以通过优化服务器参数得到解决，因为发生TIME\_WAIT的情况一般是就是对方连接的异常，总之不是由于自己程序错误导致的。

但是CLOSE\_WAIT就不一样了，如果一直保持在CLOSE\_WAIT状态，那么只有一种情况，就是在对方连接关闭之后，程序里没有检测到，或者程序压根就忘记了这个时候需要关闭连接，于是这个资源就一直被程序占着。个人觉得这种情况，通过服务器内核参数也没办法解决，服务器对于程序抢占的资源没有主动回收的权利，除非终止程序运行。  
所以如果将大量CLOSE\_WAIT的解决办法总结为一句话那就是：查代码。因为问题出在服务器程序里头啊。

## 5.找到问题并复现 ##

大量CLOSE\_WAIT是则么出现的呢？一下两个线索为我们提供了思路：

*  生产的日志大多是同城火车票回调
 *  同城火车票目前只有测试环境，回调地址配置到了生产环境，而开发、黑盒、沙河无回调，使用主动查询逻辑。
 *  同城火车票上线之前服务正常

一个定位的方向就是：同城的回调导致大量CLOSE\_WAIT，于是走读代码，果然有端倪.  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 12]  
这段代码的大致意思是： 收到回调，查询订单是否存在，存在则处理，不存在则执行30的睡眠，之后返回。（不要问为什么有这样的逻辑）。

同程回调接口是这样说明的：  
![在这里插入图片描述][2019052017173887.png]  
所以原因是：开发、黑盒、沙河、生产为了发版本产生了大量的订单、但是只有生产配置了回调地址，所以有大量的回调到生产环境，但是很多单子不是生产环境的，所以导致Sleep了30S，于是在回调返回之前，同城已经超时，程服务端直接关闭连接，同时会再次发送新的回调。一直不停的这样，这样商旅通服务端会造成大量CLOSE\_WAIT堆积，一个CLOSE\_WAIT会维持至少2个小时的时间（系统默认超时时间的是7200秒，也就是2小时）。

造成CLOSE\_WAIT占用过多的资源，等不到释放那一刻，系统就已崩溃。  
![在这里插入图片描述][20190520170555574.png]

## 6.解决 ##

生产环境查不到订单立即返回，不进行SLEEP。  
生产环境升级后，几天内正常，问题解决。

## 7.参考文献 ##

*  [java.io.IOException 断开的管道 解决方法 ClientAbortException: java.io.IOException: Broken pipe][java.io.IOException _ _ ClientAbortException_ java.io.IOException_ Broken pipe]

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70]: /images/20220129/1d20f336449048ce8e205fda62fdfaf7.png
[20190520120814991.png]: /images/20220129/b099f7a02c5f41bfb922de34aa542b0d.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 1]: /images/20220129/2b57134a2baa4d8b957dd56c9b1a7004.png
[http_localhost_7000]: http://localhost:7000/
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 2]: /images/20220129/2567d61577734ee38421757f74ccb5ab.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 3]: /images/20220129/5b31b9ed11ad4eef859f7de5c7d5b8f5.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 4]: /images/20220129/5cadbec5364f4b48ba2ba7d93b28ee95.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 5]: /images/20220129/351882ba875144eaa2fcf74e3b2d4a21.png
[Java_JVM Heap Dump_MAT]: https://www.javatang.com/archives/2017/10/30/53562102.html
[Java_MAT_Memory Analyzer Tool]: https://blog.csdn.net/jin_kwok/article/details/80326088
[20190520142924372.png]: /images/20220129/733b0ee59b354dbcadcd2bb98b374073.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 6]: /images/20220129/4ef78147dd7b4e2a8e01ea19b16b81a7.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 7]: /images/20220129/1a43b396aa6f4a06bcc8b75679c47b67.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 8]: /images/20220129/77778b9330ca42bbb52685ab384777b6.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 9]: /images/20220129/e3072b3f94ab4ed1a0abf6c70991fe47.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 10]: /images/20220129/44a06a6c108649b796c3f303f4b6a6d0.png
[20190520143206477.png]: /images/20220129/15c64c5b4bea4925841f933a32d0d5a2.png
[20190520160752227.png]: /images/20220129/d2d0736b1d8a40898e029b6457dd828c.png
[20190520161043895.png]: /images/20220129/fb861931bfc045deb29191583d17a981.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 11]: /images/20220129/1726cd6e0155439f9ea6faccdc9b0176.png
[20190520161859895.png]: /images/20220129/bb2f0ee6f4f6437ba4bb87eabf872016.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9qaWVuaXlpbWlhby5ibG9nLmNzZG4ubmV0_size_16_color_FFFFFF_t_70 12]: /images/20220129/ad43919420584a78ba361b51ef76e775.png
[2019052017173887.png]: /images/20220129/6235340b315548ff84d12a368128466a.png
[20190520170555574.png]: /images/20220129/fdb6504a5eec484897f48a116794dfe4.png
[java.io.IOException _ _ ClientAbortException_ java.io.IOException_ Broken pipe]: https://blog.csdn.net/zqz_zqz/article/details/52235479