该文章来自阿里巴巴技术协会（ATA）精选集
目录
- 现象
- NIO模式背景介绍
- 排查过程
- 结合业务场景解释问题产生的原因
- 进一步的发现
- 解决办法
- 向Apache社区的反馈
- 总结
现象
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)
NIO模式背景介绍
Tomcat共有三种连接器模式，BIO/NIO/APR，其中NIO是异步IO模式的简称。在默认的配置下，NIO的模式的实现模型如下：
- Acceptor线程：全局唯一，负责接受请求，并将请求放入Poller线程的事件队列。Accetpr线程在分发事件的时候，采用的Round Robin的方式来分发的
- Poller线程：官方的建议是每个处理器配一个，但不要超过两个，由于现在几乎都是多核处理器，所以一般来说都是两个。每个Poller线程各自维护一个事件队列（无上限），它的职责是从事件队列里面拿出socket，往自己的selector上注册，然后等待selector选择读写事件，并交给SocketProcessor线程去实际处理请求。
- SocketProcessor线程：Ali-tomcat的默认配置是250(参见server.xml里面的maxThreads)，它是实际的工作线程，用于处理请求。
一个典型的请求处理过程
如图所示，是一个典型的请求处理过程。其中绿色代表线程，蓝色代表数据。
- Acceptor线程接受请求，从socketCache里面拿出socket对象（没有的话会创建，缓存的目的是避免对象创建的开销），
- Acceptor线程标记好Poller对象，组装成PollerEvent，放入该Poller对象的PollerEvent队列
- Poller线程从事件队列里面拿出PollerEvent，将其中的socket注册到自身的selector上，
- Poller线程等到有读写事件发生时，分发给SocketProcessor线程去实际处理请求
- SocketProcessor线程处理完请求，socket对象被回收，放入socketCache
排查过程
熟悉并发编程的同学应该都知道，这个异常出现的原因是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对象本身被修改了.
- socket里面的Poller对象被修改了。
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并不能完整的修复这个问题！**
解决办法
为了避免多线程不往同一个队列里重复放同一个对象，有以下几个办法：
- 在队列放入队列之前检查是否有重复，如果有重复，就不放入，优点是实现简单明了，但是这么做的缺点是必须要加锁，这会极大降低并发度。
- 在多线程放入队列之前，保证只有一处地方放进去了。这么做的好处是，缓存队列还是无锁设计，不会降低并发度。缺点是开发难度比较高，必须要保证所有可能涉及到的地方都要修改。
- 放弃缓存，不再重用对象。这样能根本解决这个问题，但是缺点也是先而易见的，会带来极大的GC开销。
官方在7.0.58上的做法，实际上是方法二，但是正是因为采用这种方法，导致考虑并不周全，造成遗漏。
对于遗漏的地方，我们采取的办法是方法二和方法三中间的折中方案，即在key不等于null的时候，在放回缓存队列，对于返回值为null的情况下，不再放入缓存，而是直接丢弃。这是一种在重用和垃圾回收开销之间的权衡方案.
然而到这一步真的就完了吗？并没有！
代码里面不仅仅有nioChannels这个缓存队列，还有以下其他几个缓存队列
- keyCahce
- processorCache
- eventCache
那么这几个队列里面有没有可能同样有对象重复放置的问题呢？
答案是有的。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);
}
向Apache社区的反馈
我们将分析报告和提交的patch递交给了Apache tomcat，官方很快给予我们回复，并且根据我们的patch，很快作出了fix，基本思路跟我们是一样的，详细可以参考这里。
Ali-tomcat也将这个patch back-port回来，发布了taobao-tomcat-7.0.59-255.noarch.rpm这个版本，目前位于yum仓库的test分支。
总结
- 感谢内部其他团队大量的分析和讨论，以及提供了官方类似bug的信息，以及pe同学在排查过程中帮助协调线上流量，以重现这个问题。
- 排查的过程中有很多让人觉得不可思议的地方，这时候要保持理智和冷静，不要让大脑中潜在的假设干扰了思维，通过缜密的分析，才能找到真正的问题所在。由于在高并发下处理，问题不好重现，所以排查比较耗时间，如果日志打的比较多就会影响并发度，异常就不会复现，这时候不要着急，胜利的曙光其实就在前头。
- 在这个过程中，为了向线上机器传送patch，学会了使用oss这个工具。在这里强烈推荐使用oss的python客户端，相比之下java客户端就有点那个啥了。
- 这种错误也就只能在我们大淘宝的高并发场景下才能看到。官方接到过好几次别人的反馈，但是经过仔细代码检查，也没有发现任何的问题，最终只是简单的catch住了这个异常，这只能保证线程不会退出，但是不能保证数据不会产生错乱。而这次的修复应该说从根本上解决了这个异常出现的可能性。
