一个正则引发的 java CPU异常问题

上周五开始，系统发布后就出现不稳定现象，经常消息无法获取到或者发不出消息，昨天纠结一天，各种尝试均未解决。最终在关注到某个 java 进程 cpu 居高不下，又通过一次意外的搜索，找到方法分析了内存，找到问题代码，然后，一切终于 TMD 正常了

好了，这是一个有意义的事件，先做记录下整个过程，再来谈谈收获

问题系统

问题系统是一个在线聊天消息服务器，主要用于转发聊天消息，在问题之前并不清楚系统详细变更内容

事件进展

[上周五] 是系统上线的日子，问题也从上周五上线后开始

[上周末] 因为没有人在公司，未真正处理问题，只是简单重启服务器，但问题依旧

[昨天]

早上：先讨论和解决了机制问题，确定了一些规则，避免周末无人处理的情况再次发生，完了查找问题原因，一无所获，问题依旧，期间前端把新改好的消息处理更新上去，仍然无法解决问题

下午：问题查找的进展缓慢，期间出现几个事件，让整个事情感觉到有所进展，首先是关于 socketio，我们关注到我们使用的 socketio 连接虽然最终是通过 websocket 连接，但在此之前会尝试使用polling的方式连接服务器，而且错误时都是关于跨域权限的问题，但整个下午绕来绕去，仍然没有什么进展，期间同事通过监控看到服务器 cpu 被占满，但没有引起我的注意，另一个问题是 CLOSE_WAIT 状态连接数量异常，通过一些命令检查了连接，但也仅限于检查出异常，问题原因被引到 socketio 引起 CLOSE_WAIT 数量异常上。

几句相关的代码：

#检测80端口连接数
netstat-nat|grep-i"80"|wc-l
#检测状态为ESTABLISHED的网络连接数
netstat-na|grepestABLISHED|wc-l
#检测状态为CLOSE_WAIT的网络连接数
netstat-na|grepCLOSE_WAIT|wc-l

下班后：关注到 CLOSE_WAIT 连接数异常后，通过命令意外发现原来的项目 jedis 连接出现异常，有大量 CLOSE_WAIT 现象存在，直接关闭该项目，并重启了问题系统，同时通过指定 transports:["websocket"] 的方式，只允许使用 websocket 连接，服务器 CLOSE_WAIT 及系统状态基本恢复正常，但仍然会出现 socket 连接超时重连后才连接上等现象，同时 CLOSE_WAIT 状态的连接虽然不多，但仍然在缓慢增长。一则时间关系已经比较晚，二来系统通过简单测试没有发现特别的异常现象，问题暂时告一段落。

晚上回家后，大家在使用过程中出现长文本消息无法正常发送并且发送时会被强制从服务器端断开的现象。

[今天]

由于昨晚的问题处理并不是完全解决了问题，也没有真正找到原因，所以一大早跑到公司，进入时间思考的状态，首先检查了服务器，仍然是 CLOSE_WAIT 连接占满的问题，发现 google 并仔细阅读了socket CLOSE_WAIT 产生的原因，大致了解了产生原因后，开始怀疑问题系统使用的框架(netty-socket)是否有问题，搜索了一翻 issues，无果。突然，我终于注意到了 java 进程 cpu 居高不下的问题，并且叮嘱同事千万不要重启或关闭问题系统，脑子里第一个想法是分析内存情况，分析内存就要 dump 内存，google 之，翻看了几篇 Blog 后终于看到一个 dump 并有具体分析方法的 Blog，与之前分析过的方法不太一样，但是跟现在的场景很切合，都是通过内存分析 cpu 居高不下。

JAVA 内存问题分析与定位

1. 首先dump出该进程的所有线程及状态

使用命令 jstack PID 命令打印出cpu占用过高进程的线程栈.

jstack-l5683>5683.stack

2. 使用top命令找到耗cpu的线程

使用top -H -p PID 命令查看对应进程是哪个线程占用cpu过高. （乖乖，原来可以看到线程对应的进程，并且还能看到 cpu、内存情况，这不正是我要的吗，继续跟着文章提示走）

[goocar@LoginSVR~]$top-H-p5683
top-09:14:06up270days,18:33,8users,loadaverage:7.94,9.70,10.31
Tasks:48total,2running,46sleeping,0stopped,0zombie
cpu(s):20.4%us,30.5%sy,0.0%ni,43.8%id,5.4%wa,0.0%hi,0.0%si
Mem:16625616ktotal,16498560kused,127056kfree,22020kbuffers
Swap:16771820ktotal,9362112kused,7409708kfree,2224132kcached

PIDUSERPRNIVIRTRESSHRS%cpu%MEMTIME+COMMAND
5728ecar1602442m1.3g288mR38.38.4208:06.62java
5726ecar1602442m1.3g288mS37.38.4209:08.91java
5727ecar1602442m1.3g288mR37.38.4213:14.04java
5729ecar1602442m1.3g288mS35.68.4211:39.23java
5683ecar1602442m1.3g288mS0.08.40:00.00java
5685ecar1802442m1.3g288mS0.08.40:01.62java
5686ecar1602442m1.3g288mS0.08.421:13.33java

实际问题系统中占用cpu过高的线程远比文章所说的要多得多

3. 将线程的pid 转成16进制，比如5729 = 0x1661

到第一步dump出来的 5683.stack 里面找0x1661 就知道是哪个线程了

"nioEventLoopGroup-7-12"prio=10tid=0x00007f7bc4013000nid=0x19b8runnable[0x00007f7c22de9000]
java.lang.Thread.State:RUNNABLE
...
atjava.util.regex.Matcher.find(Matcher.java:592)
atcom.daoman.chat.common.LinkUtil.matchURL(LinkUtil.java:30)

好了，看到这里，项目中的包和类，我知道问题已经被找到了，新上的消息服务器每次会通过正则处理用户提交的消息，并且替换消息中的 URL。

停用新上的功能，不处理消息中的 URL，至此，问题被真正解决。

总结

本来问题应该被更早地解决，在解决过程中出现了几个比较明显的异常，但没有被引起注意。

1. cpu 占用 100%，这个最明显的异常问题，居然被忽略掉了

2. 长文本消息发送过程中的异常，虽然跟表现的问题没有表面上的关联，但是这两个问题同时出现了，说明实际是有关系的。

3. 没有注意到问题系统更新前后的变更内容

如果能够早点注意到上面三个问题的任意一个问题，也许问题早就被解决了，所以在解决问题的时候，千万不要忽略掉那些与直接问题一起产生的其他问题，同时 cpu及内存异常应被第一时间注意到，这次事件学习到的分析内存的方法不用什么特别的工具，方便实用，也算是一个不小的收获。