断网故障时Mtop触发tomcat高并发场景下的BUG排查和修复（已被apache采纳）

该文章来自阿里巴巴技术协会（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)，它是实际的工作线程，用于处理请求。

一个典型的请求处理过程

如图所示，是一个典型的请求处理过程。其中绿色代表线程，蓝色代表数据。

1. Acceptor线程接受请求，从socketCache里面拿出socket对象（没有的话会创建，缓存的目的是避免对象创建的开销），
2. Acceptor线程标记好Poller对象，组装成PollerEvent，放入该Poller对象的PollerEvent队列
3. Poller线程从事件队列里面拿出PollerEvent，将其中的socket注册到自身的selector上，
4. Poller线程等到有读写事件发生时，分发给SocketProcessor线程去实际处理请求
5. 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拿到的对象在进入事件队列之后，被修改了。

为什么会被修改呢？出现这个情况只有两种可能:

1. socket对象本身被修改了.
2. 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并不能完整的修复这个问题！**

解决办法

为了避免多线程不往同一个队列里重复放同一个对象，有以下几个办法：

1. 在队列放入队列之前检查是否有重复，如果有重复，就不放入，优点是实现简单明了，但是这么做的缺点是必须要加锁，这会极大降低并发度。
2. 在多线程放入队列之前，保证只有一处地方放进去了。这么做的好处是，缓存队列还是无锁设计，不会降低并发度。缺点是开发难度比较高，必须要保证所有可能涉及到的地方都要修改。
3. 放弃缓存，不再重用对象。这样能根本解决这个问题，但是缺点也是先而易见的，会带来极大的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分支。

总结

1. 感谢内部其他团队大量的分析和讨论，以及提供了官方类似bug的信息，以及pe同学在排查过程中帮助协调线上流量，以重现这个问题。
2. 排查的过程中有很多让人觉得不可思议的地方，这时候要保持理智和冷静，不要让大脑中潜在的假设干扰了思维，通过缜密的分析，才能找到真正的问题所在。由于在高并发下处理，问题不好重现，所以排查比较耗时间，如果日志打的比较多就会影响并发度，异常就不会复现，这时候不要着急，胜利的曙光其实就在前头。
3. 在这个过程中，为了向线上机器传送patch，学会了使用oss这个工具。在这里强烈推荐使用oss的python客户端，相比之下java客户端就有点那个啥了。
4. 这种错误也就只能在我们大淘宝的高并发场景下才能看到。官方接到过好几次别人的反馈，但是经过仔细代码检查，也没有发现任何的问题，最终只是简单的catch住了这个异常，这只能保证线程不会退出，但是不能保证数据不会产生错乱。而这次的修复应该说从根本上解决了这个异常出现的可能性。