目录
[显示]

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的情况。