现象
前几日在生产环境上出现了SSL连接泄露的问题,具体现象是
- 客户端使用SSL协议不停尝试重连MQ,客户端上使用netstat查看,同时存在的连接数量不超过2个,但是MQ的服务器上使用netstat查看发现连接数量不断增长,且IP均为该客户端。
- 连接数量达到4500时发现MQ的activemq.log中出现了
java.lang.OutOfMemoryError: unable to create new native thread
异常,也就是堆外内存溢出。 - ActiveMQ页面上发现连接数量(100左右)远小于netstat查看得到的数量。
- MQ重启后,连接数量仍然上升,客户端修改逻辑使用failover机制而不是connection.start + stop后恢复正常。
在问题ActiveMQ中,使用的是BIO模式,也就是说每个连接使用1个线程承载。
分析
通过jstack获取到MQ重启后客户端修改前的线程日志后发现(此时连接数量约500),客户端的Transport线程为BLOCKED状态,在等待锁释放,而持有该锁的线程是ActiveMQ BrokerService线程,该线程为RUNNABLE状态,但是这个状态持续了很长时间都未释放锁。
此外BrokerService线程持有的锁还导致了另一类Inactivity Monitor Worker线程BLOCKED,这三类线程数量基本持平,都为500个左右。也就是说一个连接泄露会出现3个同时存在的线程。两个为BLOCKED状态,一个为RUNNABLE状态但长时间持有两个锁不释放。根据JVM的默认配置Xss=1MB,也就是说一个线程会占用操作系统1MB的堆外内存,当出现大量连接泄露的时候,就导致了堆外内存用尽,出现了OOM。
进一步从ActiveMQ的源码分析,BrokerService这个线程是从线程池中创建,用于连接建立时的握手等,BrokerService卡在的方法是oracle的SSL连接performInitialHandshake方法,从方法名可以看出来是SSL连接的初次协议握手。僵死的位置是SocketInputStream.socketRead0,也就是读阻塞了。
此时连接还没有完成建立,而Transport线程是BLOCKED在往OutputStream里写数据,在等待BrokerService从InputStream里读完数据;Inactivity Monitor Woker线程是BLOCKED在关闭连接的过程中,因为BrokerService线程持有了一个starting的锁,这个锁标识着连接建立是否完成。Inactivity线程发现连接建立超时了,尝试关闭的时候又发现连接仍然在建立过程中,无法关闭。
ActiveMQ默认不开启TCP KEEPALIVE机制,而是使用自己的Inactivity Monitor机制,但是未曾想Inactivity机制也被阻塞了。
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
at sun.security.ssl.InputRecord.read(InputRecord.java:480)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:927)
- locked <xxxxxxxxxxxxxxx> (a java.lang.Object)
at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1312)
接下来就是看看为啥会出现读阻塞了,其实可以看到这里阻塞的位置已经很底层了,所以可以大致考虑是触发了操作系统或者JDK的bug。看了下还真有符合的。JDK-8143992到oracle jdk底层的堆栈信息完全一样,只是这里的错误是从HTTPS中报出的,但是都是SSL协议。进一步可以看到这个BUG是【JDK-8075484】的Duplicated。
As noted at JDK-8049846, the implementation of Java_java_net_SocketInputStream_socketRead0 assumes that read() won't block after poll() reports that a read is possible. This assumption does not hold, as noted on the man page for select (referenced by the man page for poll): Under Linux, select() may report a socket file descriptor as "ready for reading", while nevertheless a subsequent read blocks. This could for example happen when data has arrived but upon examination has wrong checksum and is discarded. There may be other circumstances in which a file descriptor is spuriously reported as ready. Thus it may be safer to use O_NONBLOCK on sockets that should not block.
大意是Linux中告诉jvm说socket文件描述符可读但是不代表这个socket一定不会阻塞,而JDK却认为一定不会阻塞。
问题解决方法:
- 考虑开启TCP KEEPALIVE机制看看能不能把异常连接给关了,因为肯定没有数据流了。但是Linux的TCP KEEPALIVE机制需要2个小时才会生效,所以需要调整一下KEEPALIVE机制的时间。
- 升级JDK到Fixed的版本。
此外还存在几个问题:
- 这个BUG是偶发的,但是从生产环境看,竟然变成了每次建立连接都会触发,这是为什么呢?
- 客户端建立连接,发送消息,关闭连接这个过程并未报错,为什么?connection.stop这个方法中可是有个向服务器同步发送关闭连接信息的动作。
嗯。。。还需要继续研究看看。。。。。