首页 » GC » 正文

【转载】Tomcat7连接数异常导致超时问题的排查

原文出处:http://blog.2baxb.me/archives/1309?from=timeline&isappinstalled=0

1.摘要

前几天线上tomcat出了一次诡异的超时问题,在此记录下来。每次问题的排查都很痛苦,而定位原因之后再回想整个过程又常常有“当时如果看了那个其实早就能知道了”之类的懊恼,看来问题排查流程的标准化还有很长的路要走。

2.现象和处理

  1. 某天某个跑在tomcat上的java服务的所有接口都突然开始出现偶发超时,响应时间从几十毫秒增长到几秒,甚至几十秒。
  2. 比较灵异的一个现象tomcat处理日志和业务日志中都没有发现超时,日志里打出来的请求的响应时间都在几十毫秒,并且对线程数的监控也没有发现波动。
  3. 怀疑是负载均衡的问题,查看nginx日志,发现nginx访问后端时有很多慢请求。
  4. 查看tomcat的gc情况,比较正常。
  5. 在tomcat本机调用接口,发现同样存在超时问题,排除nginx的嫌疑。
  6. 感觉问题基本出在tomcat上,决定先重启服务,果然重启后响应时间恢复。

3.原因排查

  1. 重启的时候从集群中摘除了一台节点保留现场,因为服务已经两周没有上过线,所以怀疑跟某种资源堆积有关。
  2. 尝试复现问题:
    1. 直接调用摘除的节点没有发现问题。
    2. 尝试使用ab压测,没有复现。
    3. 尝试使用tcpcopy引流,在引流单台5倍流量的情况下依然没有出现。
    4. 把节点重新加回到线上集群,问题神奇的重现了。
  3. jstack查看出问题时的线程栈,没有发现死锁或者大量线程阻塞。
  4. jmap做heap dump,分析了一下内存,没发现特别明显的内存泄露或者大对象。
  5. strace查看系统调用,发现poll()系统调用偶发会超时,超时时间和connectionTimeout设定的时间一致。
  6. 继续追查了一下poll()超时的问题,发现请求超时和poll()超时之间没有什么必然联系,在没有poll()超时的时间段里也会出现偶发的请求超时,这条路似乎走不通。
  7. 同时使用strace和tcpdump,在特定机器上调用一个特殊的uri,uri会打印在strace得到的read()的返回值里,从而得可以得到fd,并找出相应的accept()和write(),并结合对指定ip的tcpdump,可以得出这个请求的处理时间轴大概是:
    • 0s 发出请求,tcp握手
    • 11s accept()
    • 11s read()
    • 11s 业务日志
    • 11s write()
    • 11s tomcat access日志
  8. 基本可以定位是tcp握手到accept()之间出了什么问题,查看rx_queue,没有发现堆积,排查方向转到tomcat调用accept()部分。
  9. 查看tomcat源码,线上使用的是tomcat7.0.24,bio connector。在JioEndpoint的代码里发现了比较可疑的地方:

    内部是一个LimitLatch:

  10. 简单阅读了一下源码,使用bio的connector时,线程分为:
    • 接收请求并创建client socket的accetpor线程(默认1个),在acceptor中维护了connectionCount,就是上面的connectionLimitLatch(最大连接数,bio中的默认最大值与maxThreadCount相同)
    • 实际处理请求的exec线程(线程池中线程的最大数量等于maxThreadCount),执行exec的线程池中也有一个线程数threadCount(最大值为maxThreadCount)

    网上随便找了张图,bio的处理流程:

    bio图片来自http://www.infoq.com/cn/articles/zh-tomcat-http-request-1

  11. 通过刚才拿到的heap dump查看connectionLimitLatch的值为800,跟配置的maxThreadCount相同,而当时实际tomcat的工作线程只有不到100个,所以猜测是connectionLimitLatch这个计数值异常导致新请求的accept被阻塞了
  12. 继续追查代码,在实际处理的线程中对这个计数的减操作是这么处理的:

    似乎对Exception没有做什么处理,进一步查看handler的代码:

    进一步查看ExceptionUtils.handleThrowable(e):

  13. 到这里可以确定如果线程抛出了ThreadDeath或者VirtualMachineError,那么这个计数应该会有问题。
  14. 进一步搜索出错之前的日志,在catalina.out里发现有偶发的StackOverflowError:
  15. 根据线程栈定位到异常的原因是进行正则表达式匹配时栈溢出。

4.解决问题

  1. 尝试最小代码重现问题,把tomcat的maxThreadCount调成1,直接在Servlet里throw new StackOverflowError(),调用普通接口没有问题,调用一次错误接口后,再普通接口发现请求hang住了,与线上表现一致。
  2. 把tomcat的connector改为nio,问题解决。
  3. 升级tomcat到7.0.61,并改回bio,问题解决。进一步查看代码发现tomcat7.0.61已经修复了这个bug,单独判断了StackOverflow的情况。