记一次因为mq连接数爆满导致异常的线上排错

缘起

现场技术支持波兄找到我, 说是页面保存保存不了. 我试了一下, 浏览器转啊转~ 而且是重启服务器之后每过一段时间就会发生无法保存的现象. 于是我开始了侦查工作.

分析

浏览器转啊转，必然是因为后端没响应. 后端没响应，必然是因为有同步代码在等待. 那是哪段代码呢? 反编译查了一下代码，偏偏没做日志（一定是当时写代码的程序员没想到这一点, ps:

关于日志, 我的原则是

  1. 内部系统日志, 只需要抓异常, 打印异常进日志
  2. 涉及到外部接口的, 例如dubbo、RESTful接口调用，一定要打印好入参和接口响应. 对于同步接口, 可以做好超时抛异常的AOP处理

）.

没做日志, 咋办? 怎么定位呢? 这就必须把手术刀———jstack侦探请出场.

首先, 我们在页面操作的时候，tail -f 了一波 日志, 发现了 tomcat 线程日志

1
http-nio-8085-exec-20: 内容内容内容内容...

所以我在jstack日志中查找了 http-nio-8085-exec-20关键字，找到了下面的日志

1
2
3
4
5
6
"http-nio-8085-exec-20" #14612 daemon prio=5 os_prio=0 tid=0x00007f1adc008800 nid=0x175d9 in Object.wait() [0x00007f189f4f2000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
...
	at com.xxx.yyy.modules.config.notify.mq.ResourceNotify.sendNotify(ResourceNotify.java:109)
	...

(这里基于职业道德，将公司的包名隐匿了). 看来就是因为 jms同步发送消息给 activemq，而activemq迟迟不响应导致的. 那么问题来了, 为什么activemq不响应呢? tcpdump 抓包然后wireshark分析, 以 

1
ip.addr==172.25.15.225 && tcp.port == 38692

为过滤器显示如下

这里补充一下, 172.25.15.225 是消息生产者 172.25.15.200是mq服务器. 现在是生产者无法投递消息给服务器.

其中,38692 是一个临时端口. 可以看到, 首先进行了3次握手之后, mq竟然立马发了一个FIN包给200，这是四次挥手的主动发起方. 表明关闭连接是mq服务器主动发起的. 然后225还想哔哔啥的时候, 200表示不想和225说话并丢了一个RST包给他. 而且225和200之间的会话充斥了整个抓包过程. 所以总结来说

1
MQ服务器貌似没有连接资源再给225这个生产者了.

所以一定会在MQ服务器的日志看出端倪. 所以我马上跑到MQ服务器上去看日志, 果然看到了我想看到的东西

1
jvm 1    | ERROR | Could not accept connection : org.apache.activemq.transport.tcp.ExceededMaximumConnectionsException: Exceeded the maximum number of allowed client connections. See the 'maximumConnections' property on the TCP transport configuration URI in the ActiveMQ configuration file (e.g., activemq.xml)

超出了最大连接数. 于是看看activemq.xml的配置

1
<transportConnector name="openwire" uri="tcp://0.0.0.0:61616?maximumConnections=1000&amp;wireFormat.maxFrameSize=104857600"/>

最大连接数为1000而已~ 于是自然的去MQ服务器所在linux服务器上lsof一把， 发现了1010行ESTABLISHED状态的连接. 所以被拒绝并不奇怪. 而且几乎99%的连接都是由172.25.20.211（业务网关，下简称BIG）占用的. 所以我自然想知道BIG和activemq之间在干什么. 于是继续分析抓包文件

使用 

1
ip.addr==172.25.20.211 && tcp.port == 59392 && openwire

作为过滤条件， 发现全部是 心跳包

而以

1
ip.addr==172.25.20.211 && tcp.port == 59392 && !openwire

作为过滤条件，发现全部是 Len=0 的ACK的TCP包. 也就是说这些进程和mq之间没有做任何实质性的事情,但是占用着MQ服务器上宝贵的连接资源.

找到了原因, 解决办法就很显然了. 有以下两种方法

  1. 将activemq的连接配置使用nio协议，而不是openwire协议.
  2. 检查为什么BIG会占用这么多连接而不做实事

但是1是下策. 因为抓包分析结果表明，211占用了很多不必要的连接. 至于2，我没有参与. 很遗憾~