mtop的机器,环境为Ali-Tomcat 7.0.54.2,连接器采用的是NIO模式,在高流量(约1000 qps)的情况下,在Tomcat的启动后一段时间内,抛出ConcurrentModificationException,然后再过一段时间后,Tomcat无法再接受新的请求。
异常堆栈如下:
Exception in thread "http-nio-7001-ClientPoller-1" java.util.ConcurrentModificationException at java.util.HashMap$HashIterator.nextEntry(HashMap.java:793) at java.util.HashMap$KeyIterator.next(HashMap.java:828) at java.util.Collections$UnmodifiableCollection$1.next(Collections.java:1010) at org.apache.tomcat.util.net.NioEndpoint$Poller.timeout(NioEndpoint.java:1421) at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1215) at java.lang.Thread.run(Thread.java:662)
Tomcat共有三种连接器模式,BIO/NIO/APR,其中NIO是异步IO模式的简称。在默认的配置下,NIO的模式的实现模型如下:
如图所示,是一个典型的请求处理过程。其中绿色代表线程,蓝色代表数据。
熟悉并发编程的同学应该都知道,这个异常出现的原因是A线程在遍历某个集合的过程中,另外一个B线程修改了这个集合的内容,在A线程中就会抛出ConcurrentModificationException。
根据异常堆栈,我们可以知道,Poller1线程在处理timeout的时候,会遍历selector上的keys,然后在这个遍历的过程中,另外一个线程修改了keys的数据,导致抛出异常。大致代码如下:
protected void timeout(int keyCount, boolean hasEvents) { ... //timeout Set<SelectionKey> keys = selector.keys(); ... for (Iterator<SelectionKey> iter = keys.iterator(); iter.hasNext();) { SelectionKey key = iter.next(); ... } ...
代码分析看不出端倪,所有对Selector的操作都是在ClientPoller的线程上做的修改,而每个ClientPoller在初始化的过程中各自持有自己的Selector,设计上决定了不应该有多线程的问题。那么到底是谁在修改底层的keys呢?
由于在Tomcat源码中看不出问题所在,我们决定在JDK层面打patch,在JDK层面,所有可能修改keys的地方只有两处,sun.nio.ch.EpollSelectorImpl的implRegister方法以及implDereg方法(注意,不同操作系统下的实现类可能不一样,在linux下是sun.nio.ch.EpollSelectorImpl)。
我们下载了openjdk源码,在sun.nio.ch.EpollSelectorImpl的implRegister方法以及implDereg方法中打印相关信息,并通过以下的方式覆盖JDK的原有实现:
JAVA_OPTS="$JAVA_OPTS -Xbootclasspath/p:/var/tmp/selector-patch.jar"
不幸的是,加上patch之后无法重现问题,看来输出debug信息本身拖慢了线程的执行,导致本来就很小的时间窗口稍纵即逝。不断的缩减输出内容也没有任何重现的迹象,在我们快要放弃的时候,下面这个已经减无可减的输出(放弃输出时戳、并且减少+号)带来了一线曙光。
当把输出从
protected void implRegister(SelectionKeyImpl ski) { SelChImpl ch = ski.channel; fdToKey.put(Integer.valueOf(ch.getFDVal()), ski); pollWrapper.add(ch); keys.add(ski); + System.out.println("> " + Thread.currentThread().getName() + ", " + this); }
换成
protected void implRegister(SelectionKeyImpl ski) { SelChImpl ch = ski.channel; fdToKey.put(Integer.valueOf(ch.getFDVal()), ski); pollWrapper.add(ch); keys.add(ski); + System.out.println(Thread.currentThread().getName() + "> " + this); }
终于重现出了问题。通过分析得到的日志,发现了不寻常的现象,同样的一个ClientPoller线程在进入impleRegister方法的时候操作的是两个不同的Selector实例,并且这两个不同的Selector实例只与这两个ClientPoller关联,看起来的确像两个线程之间的并发问题,但是代码分析并不支持这个观点。
http-nio-7001-ClientPoller-1> sun.nio.ch.EPollSelectorImpl@cc98f2c http-nio-7001-ClientPoller-1> sun.nio.ch.EPollSelectorImpl@5787ae61 http-nio-7001-ClientPoller-0> sun.nio.ch.EPollSelectorImpl@cc98f2c
出现问题的JDK是taobao-jdk 1.6,会不会是JDK的bug呢?为了验证这个想法,我们尝试了Ali-jdk1.7,以及Sun的JDK,但是问题依然存在,这样排除了是JDK的bug的猜想。看来问题又回到了Tomcat端。
那如果只有一个Poller线程,会不会也有这个问题呢?我们验证的结果是,没有问题。这也就进一步确认了是**两个Poller线程才会出现的并发问题**。
那么我们看看到底是从什么地方调到implRegister这个方法来导致出问题的。修改sun.nio.ch.EpollSelectorImpl增加Thread.dumpStack()
protected void implRegister(SelectionKeyImpl ski) { SelChImpl ch = ski.channel; fdToKey.put(Integer.valueOf(ch.getFDVal()), ski); pollWrapper.add(ch); keys.add(ski); + Thread.dumpStack(); }
在得到的结果里面,与ClientPoller相关的堆栈,只有一处是可能造成这个问题的:
1155 -> 1039 -> 897 java.lang.Exception: Stack trace at java.lang.Thread.dumpStack(Thread.java:1249) at sun.nio.ch.EPollSelectorImpl.implRegister(EPollSelectorImpl.java:171) at sun.nio.ch.SelectorImpl.register(SelectorImpl.java:133) at java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:180) at org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run(NioEndpoint.java:897) at org.apache.tomcat.util.net.NioEndpoint$Poller.events(NioEndpoint.java:1039) at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1155) at java.lang.Thread.run(Thread.java:662)
对应的JAVA代码在NioEndpoint#PollerEvent#run方法里面:
socket.getIOChannel().register(socket.getPoller().getSelector(), SelectionKey.OP_READ, key);
对于这个现象唯一可能的解释是,当ClientPoller调用这行代码的时候,只有当socket.getPoller().getSelector()获得的Selector实例和当前ClientPoller所持有的实例不一致,才有可能造成我们前面看到的ClientPoller会操作不同Selector实例的现象。
也就是说,**socket.getPoller()拿到的Poller的实例,不是自己!!!**
这怎么可能!因为socket所代表的数据结构PollerEvent是放在ClientPoller的自身的队列里的,并且放进来的时候PollerEvent上的Poller实例会被置成当前的ClientPoller。
public void register(final NioChannel socket) { socket.setPoller(this); ... addEvent(r); }
那为什么当ClientPoller线程再从socket.getPoller()得到的Poller实例不是自己,这太不科学了。为了验证这一个看似不可能的猜想,我们加入了以下的调试信息来观察当前线程ClientPoller和socket所持有的Poller的关系
if (socket.getPoller() != this) { System.out.println(">>> t: " + Thread.currentThread().getName() + ", s: " + socket.getPoller().getName() + ", " + socket + ", ts: " + System.currentTimeMillis()); } socket.getIOChannel().register(socket.getPoller().getSelector(), SelectionKey.OP_READ, key);
果然有所收获!这说明了**socket所持有的Poller在某些条件下不一定和当前的ClientPoller线程一致**。
t: http-nio-7001-ClientPoller-1, s: http-nio-7001-ClientPoller-0 t: http-nio-7001-ClientPoller-0, s: http-nio-7001-ClientPoller-1 t: http-nio-7001-ClientPoller-1, s: http-nio-7001-ClientPoller-0
进一步的调试发现,当Poller线程从自身的事件队列中拿出socket对象的时候,socket.getPoller拿到的实例就已经错乱了,但是Acceptor线程放入事件队列之前,socket.getPoller拿到的实例是没有错乱的。那么可以肯定的是,socket.getPoller拿到的对象在进入事件队列之后,被修改了。
为什么会被修改呢?出现这个情况只有两种可能:
socket对象封装在PollerEvent对象中,如果是socket对象本身被修改,那么只有一个入口,就是PollerEvent的reset方法,我们在reset方法里面加入调试信息,确没有任何发现。这个方法在socket对象进入队列后根本没有调用过。
如果socket对象没被改变,那唯一的可能性就是socket.getPoller的对象会发生变化。也就是说**同一个socket有可能会被修改两次,而且还是来自两个不同的Poller线程**。
通过对ClientPoller上游的分析,发现tomcat是这么工作的,当请求进来的时候,有一个Acceptor线程负责建立连接,然后递交请求给后面的两个ClientPoller线程来处理
protected boolean setSocketOptions(SocketChannel socket) { // Process the connection try { //disable blocking, APR style, we are gonna be polling it socket.configureBlocking(false); Socket sock = socket.socket(); socketProperties.setProperties(sock); NioChannel channel = nioChannels.poll(); if ( channel == null ) { // SSL setup if (sslContext != null) { ... channel = new SecureNioChannel(socket, engine, bufhandler, selectorPool); } else { // normal tcp setup ... channel = new NioChannel(socket, bufhandler, Thread.currentThread()); } } else { channel.setIOChannel(socket); if ( channel instanceof SecureNioChannel ) { SSLEngine engine = createSSLEngine(); ((SecureNioChannel)channel).reset(engine); } else { channel.reset(); } } getPoller0().register(channel); } catch (Throwable t) { ... // Tell to close the socket return false; } return true; }
为了避免垃圾回收的压力,channel并不是每次都创建,而会从一个 nioChannels
的缓存队列中获取,并在使用完毕后放回该缓存队列。在排除掉 nioChannels
的数据结构(ConcurrentLinkedQueue)本身的并发问题之后,唯一的可能性就指向了:在某种情况下这个缓存队列中,同一个channel对象在队列中存在多份。
按照这个思路,在nioChannels.offer以及nioChannels.poll之前判断队列中是否已经存在要还回的channel实例,或者有要还回的channel实例,如果有,就打印出以下信息。输出的结果证明了猜想是正确的,这是一个**重大的进展**
>>> poll but still found in queue, org.apache.tomcat.util.net.NioChannel@28baf3bf:java.nio.channels.SocketChannel[closed], ts: 1435720813750 >>> offer but already found in queue, org.apache.tomcat.util.net.NioChannel@28baf3bf:java.nio.channels.SocketChannel[closed], ts: 1435720812885
这时,其他同事也发现tomcat的bugzilla上有一个类似的 Bug ,并且跟我们的场景非常类似,并且官方在7.0.58里面已经Fix了。另一位同事提出是否可以升级到新版tomcat试一下,最近我们正好release了Ali-tomcat 7.0.59,于是马上升级到7.0.59,结果果真没有出这个问题。这进一步验证了我们的判断。
或许到这里,很多同学会以为问题到此就结束了,这是tomcat7.0.54上的bug,在新版本的tomcat里面这个问题已经被修复了。
但是这根本挡不住我们刨根问题的好奇心,我们还想知道的是,socket对象到底在什么地方被重复放了两次,以及,有哪些线程会通过nioChannels.offer还回socket对象。由于nioChannel.offer是发生在SocketProcessor的run方法里,并且run方法的总入口是:
public boolean processSocket(NioChannel socket, SocketStatus status, boolean dispatch, int where) { ... SocketProcessor sc = processorCache.poll(); if ( sc == null ) sc = new SocketProcessor(socket,status, where); else sc.reset(socket,status, where); if ( dispatch && getExecutor()!=null ) getExecutor().execute(sc); else sc.run(); ... }
通过改造代码打标( where
)并输出当前执行线程,最终得到以下的日志:
thread: Thread[http-nio-7001-ClientPoller-1,5,main], key: , ka: null, where: 6 thread: Thread[http-nio-7001-ClientPoller-1,5,main], key: sun.nio.ch.SelectionKeyImpl@7da286bb, ka: null, where: 1 thread: Thread[HSF-CallBack-11-thread-2,10,main], key: sun.nio.ch.SelectionKeyImpl@7963cb1e, ka: null, where: 10
其中标记 1
是Poller#processKey,标记 2
是Poller#timeout,标记 3
是Http11NioProcessor#actionInternal(**注意,这里的线程是HSF-CallBack线程,不是http-nio-7001-ClientPoller线程**),其中唯一有可能并发的地方就是HSF-Callback线程与http-nio-7001-ClientPoller线程在交还nioChannel的时候并发,并导致错误。通过阅读代码,发现HSF-CallBack线程这个时候在做Async Complete的操作。熟悉Async Servlet编程的同学应该已经明白了出问题的场景。
首先介绍一下mtop的场景
在mtop的场景中,mtop采用了Async Servlet中调用hsf callback的模式,以提升mtop的性能。
mtop针对Async servlet 超时的设置为4s,因为一些业务特殊需要,最大可按api设置到15s。为了与Async servlet的超时时间错开,hsf callback的默认超时时间是3s。但后端hsf服务可以自定义超时时间,比如阿里云的几个拖慢的api,com.taobao.taotv.alitv.service.AlitvService:1.0.0其hsf超时时间是15s。
在高并发的高qps(当时的qps约为1000)的场景下,如果hsf callback的超时时间设置的大于了Async servlet的超时时间,那么hsf callback就会有很大概率在asyncservlet超时的瞬间返回,导致对于同一个请求,hsf callback与async servlet超时(Poller线程调用Poller#timeout方法)并发的调用NioEndpoint#processSocket方法。同时,如果nginx端此时主动断连,也可能会加剧NioEndpoint#processSocket的并发访问。
Poller线程和Hsf callback线程同时尝试回收socket对象到缓存队列nioChannels中,由于SocketProcessor#doRun方法中,对于并发访问的控制缺陷,导致同一个socket被两个线程分别offer了一次,缓存队列出现重复对象,并且,有极高的概率是被连续offer了两次(两次offer之间没有别的对象被offer进入队列)。
Acceptor线程从缓存队列中取出对象向Poller派发的过程中,由于是Round Robin方式派发,如果socket对象重复出现的位置是连续的,那么一定是被分派到了两个不同的Poller所在的事件队列当中。
其中一个Poller线程(Poller1)进入到timeout处理,会获取selector里面所有连接的Set进行遍历处理。selector底层用一个hashset维护所有连接的SelectionKey,这是一个非线程安全的集合。
不幸同时另外的一个Poller线程(Poller0),正在把socket对象注册到selector上,由于调用socket.getPoller.getSelector拿到的是Poller1的selector上,导致Poller1的keys集合里面的数据被修改。Poller1正在遍历这个集合,因为keys被修改而抛了ConcurrentModificationException异常,因线程未捕获这个异常,Poller1线程直接挂掉退出.
Acceptor线程并不知道Poller1线程已经挂掉了,而是继续在分配连接到这两个poller线程上,那个存活的poller线程可以正常处理业务,而分配到挂掉poller线程的连接请求都无法处理。
Tomcat有一个控制最大可建立请求数的参数,maxConnections,nio下默认是10000,因为挂掉的poller线程上的连接请求一直不处理,所以随着时间累计,分配到这个线程上的连接越多(正常的poller处理完连接后,每次都有50%连接被分配到挂掉的poller线程那,挂掉的poller线程成为黑洞,慢慢吸收连接过去),直到挂掉的poller线程占满10000个连接,accept线程发现连接已满,拒绝接受新的请求,线程进入locksupport.park状态。
因此这个阶段vipserver在健康检查的时候,会有50%的概率成功,在nginx上看到的现象,就是可用的mtop机器数量,按概率上上下下波动。
在tomcat7.0.58版本以后,官方针对一个类似的对象池污染的问题( Bug57340 )做过一个修复。大致的逻辑是通过原子操作来保证多个线程并发的时候最终一个socket对象被offer进入缓存队列。事例代码如下
public void run() { SelectionKey key = socket.getIOChannel().keyFor( socket.getPoller().getSelector()); ... doRun(key, ka); } private void doRun(SelectionKey key, KeyAttachment ka) { int handshake = -1; if (key != null) { handshake = ... } if (handshake == 0) { // 官方针对bug57340的修复在这里 } else if (handshake == -1 ) { if (key != null) { socket.getPoller().cancelledKey(key, SocketStatus.DISCONNECT, false); } nioChannels.offer(socket); socket = null; if ( ka!=null ) keyCache.offer(ka); ka = null; } }
虽然说升级到7.0.59后并没有出问题,但是分析发现,在 else if (handshake == -1)
分支中,也有可能出现重复放入的情况:
>>> 2. thread: Thread[http-nio-7001-ClientPoller-0,5,main], key: , ka: null, where: 1
出现这个情况也是可以理解的。handshake默认值是-1,其中的一种可能性就是入参key为空,很显然,代码没有考虑到处理这种情况。当key为空的时候,从run方法的第一行代码可以知道,这个时候socket已经被其他线程处理过了。
也就是说,**官方在7.0.58上提供的Fix并不能完整的修复这个问题!**
为了避免多线程不往同一个队列里重复放同一个对象,有以下几个办法:
官方在7.0.58上的做法,实际上是方法二,但是正是因为采用这种方法,导致考虑并不周全,造成遗漏。对于遗漏的地方,我们采取的办法是方法二和方法三中间的折中方案,即在key不等于null的时候,在放回缓存队列,对于返回值为null的情况下,不再放入缓存,而是直接丢弃。这是一种在重用和垃圾回收开销之间的权衡方案.
然而到这一步真的就完了吗?并没有!
代码里面不仅仅有nioChannels这个缓存队列,还有以下其他几个缓存队列
那么这几个队列里面有没有可能同样有对象重复放置的问题呢?
答案是有的。keyCache就有这个可能。原因很简单,它的放回逻辑跟nioChannels完全一致。所以keyCache的放回逻辑也应该控制起来,避免重复offer。
最终的修复方案如下:
} } } else if (handshake == -1 ) { + // ALITOMCAT: start, throw away socket if key is null, otherwise, we have to lock not only here, + // but also the offer logic above in if clause, let's bear with it if (key != null) { - socket.getPoller().cancelledKey(key, SocketStatus.DISCONNECT, false); + if (socket.getPoller().cancelledKey(key, SocketStatus.DISCONNECT, false) != null) { + nioChannels.offer(socket); + if (ka != null) keyCache.offer(ka); + } } - nioChannels.offer(socket); socket = null; - if ( ka!=null ) keyCache.offer(ka); ka = null; + // ALITOMCAT: end } else { ka.getPoller().add(socket, handshake); }
我们将分析报告和提交的patch递交给了Apache tomcat,官方很快给予我们回复,并且根据我们的patch,很快作出了fix,基本思路跟我们是一样的,详细可以参考 这里 。
Ali-tomcat也将这个patch back-port回来,发布了taobao-tomcat-7.0.59-255.noarch.rpm这个版本,目前位于yum仓库的test分支。