转载

断网故障时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),它是实际的工作线程,用于处理请求。

一个典型的请求处理过程

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

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

  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住了这个异常,这只能保证线程不会退出,但是不能保证数据不会产生错乱。而这次的修复应该说从根本上解决了这个异常出现的可能性。
原文  http://yq.aliyun.com/articles/2889
正文到此结束
Loading...