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

本文主要是介绍一次生产环境大量CLOSE_WAIT导致服务无法访问的定位过程，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！

1.症状

生产环境的一个服务突然无法访问，服务的交互过程如下所示：

所有的请求都是通过网关进入，之后分发到后端服务。

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

后续执行过如下的操作：

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

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

2.第一次定位

运维使用Top命令（类似于Windows的任务管理器）查看了下机器的状况，如下所示（仅供参考）：

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

执行netstat -nat | grep "CLOSE_WAIT"发现有大量的CLOSE_WAIT连接。参考如下：

商旅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/ 就可以看到结果了。但实际通常使用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文件，打开。

通过分析，并未发现异常，没有内存泄露的痕迹，也没有异常的大的对象。

3.2 Eclipse Memory Analyzer(MAT)

Eclipse Memory Analyzer（简称MAT）是一个功能丰富且操作简单的JVM Heap Dump分析工具，可以用来辅助发现内存泄漏减少内存占用。
MAT支持两种安装方式，一是Eclipse插件的方式，另外一个就是独立运行的方式，建议使用独立运行的方式。
分析结果如下：
Overview：概要界面，显示了概要的信息

Histogram： 直方图，可以查看每个类的实例（即对象）的数量和大小。

Dominator Tree：支配树，列出Heap Dump中处于活跃状态中的最大的几个对象，默认按 retained size进行排序，因此很容易找到占用内存最多的对象。

通过分析，均无内存溢出的痕迹，也无大对象等。MAT用法详见:
Java内存泄漏分析系列之六：JVM Heap Dump（堆转储文件）的生成和MAT的使用
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相差甚远。

4.2 查看堆的情况

执行jmap -heap pid查看堆信息，一切正常，最大堆设置已经生效。

对应关系，给张图自己体会：

最大堆为512M，但是top命令看到实际使用了988M，什么原因？

什么是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与进程内存模型

JVM内存模型（1.7与1.8之间的区别）

所以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。

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

执行ls /proc/17493/task |wc -l(统计进程打开的线程数)，结果如下：

总计283个线程。也不是很多。

4.4查看GC情况

执行jstat -gc pid或者stat -gc pid 5000 2000

gc的次数也不是很多，时间也不长。

4.5TCP连接状态统计

执行netstat -n | awk '/^tcp/ {++state[$NF]} END {for(key in state) print key,"\t",state[key]}'统计TCP状态情况，

常用的三个状态是：ESTABLISHED 表示正在通信，TIME_WAIT 表示主动关闭，CLOSE_WAIT 表示被动关闭 因为linux分配给一个用户的文件句柄是有限的，而TIME_WAIT和CLOSE_WAIT两种状态如果一直被保持，那么意味着对应数目的通道就一直被占着，而且是“占着茅坑不使劲”，一旦达到句柄数上限，新的请求就无法被处理了，接着就是大量Too Many Open Files异常；如果未达到句柄数上限，也可能会出现无连接可用的情况。
上面发现大量的连接处于CLOSE_WAIT，这可能就是服务不可访问的原因。
这说明是客户端先关闭了连接，服务器端没有执行关闭连接的操作，导致服务器端一直维持在CLOSE_WAIT的状态。详见下图：

查看TCP的keep_alive参数sysctl -a |grep keepalive ,结果如下：

TCP默认的保活时间为2个小时，也就是说两个小时TCP才会主动帮我们会清理一次无用的连接。所以现在的问题是什么原因造成了大量CLOSE_WAIT的产生。

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

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

5.找到问题并复现

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

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

一个定位的方向就是：同城的回调导致大量CLOSE_WAIT，于是走读代码，果然有端倪.

这段代码的大致意思是： 收到回调，查询订单是否存在，存在则处理，不存在则执行30的睡眠，之后返回。（不要问为什么有这样的逻辑）。

同程回调接口是这样说明的：

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

造成CLOSE_WAIT占用过多的资源，等不到释放那一刻，系统就已崩溃。

6.解决

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

7.参考文献

• java.io.IOException 断开的管道 解决方法 ClientAbortException: java.io.IOException: Broken pipe

这篇关于一次生产环境大量CLOSE_WAIT导致服务无法访问的定位过程的文章就介绍到这儿，希望我们推荐的文章对编程师们有所帮助！

---