【原创】记一次线上Tomcat故障排查-struts2 “bug”导致tomcat阻塞

现象

15年5月25日下午6：30分，我们的QA收到我们的一个线上项目页面一定概率会出现ERROR页面。

当时问题分析及处理方案

此页面是nginx的error页面，并不是我们业务的500页面。通过每台机器ip直接访问，发现 其中有一台机器挂了。马上联系运维同学，重启tomcat后正常。

事后问题排查

1.查看业务log4j 日志



发现当时应用一直在重连zookeeper,但是这并不会导致nginx error。

2.查看nginx日志



由日志可以看出当时tomcat响应码为499。499状态码很少见，百度一下。
ngx_null_string, /* 499, client has closed connection */
可以看到，499对应的是 “client has closed connection”。这很有可能是因为服务器端处理的时间过长，客户端“不耐烦”了。
还有一种原因是 我后来测试发现 确实是客户端关闭了连接,或者说连接超时 ,无论你设置多少超时时间多没用 原来是php进程不够用了 改善一下php进程数 问题解决 默认测试环境才开5个子进程。
tomcat处理时间过长？或者tomcat响应请求的线程不够？
查看tomcat的tomcat.catalina.out日志，发现18：03 确实tomcat的work queue full。



通过查看线上机器的tomcat配置文件server.xml。设置的响应线程数最大值为 120



问题越来越清晰了
通过cat（公司内部的监控系统，非常强大，已开源）查看18：03当时的线程快照信息（problem -> headbeat）



发现除了catalina-exec-1和catalina-exec-2 Running状态，其他118个线程全部是Blocked状态并且被catalina-exec-1和catalina-exec-2线程占领锁资源。
查看一直锁代码位于struts的ognl模块的一处代码：（OgnlRuntime.java）



struts属性注入或者freemarker都是通过ognl实现，代码中synchronized(method)，method可以为对应的getter和setter方法，_methodAccessCache是缓存一个类中，getter和setter方法的可访问性。一个类中一个方法只有一个实例。

那catalina-exec-1和catalina-exec-2到底在干嘛？长时间占用锁？



一直在 ognl.IntHashMap.get（）处运行。查看源代码(IntHashMap.java)



看这地方唯一能导致方法一直running只有 for的死循环。从cat的loadavg图可以查看，从我上完线16：13到18：40负载一直莫名的很高，正常情况下这几台机器负载应该极低。（18：40重启完毕）。而且16：13catalina-exec-1和catalina-exec-2就开始处于running状态。一直到18：03work queue full期间，不断的有线程被block，直到full。





负载异常的高，而且很均匀。应该可以推理出死循环？
查看IntHashMap，发现这个hashMap并不是一个线程安全的类，ognl是通过外层的同步实现线程安全。在map，put和get是通过synchronized（method）实现，也就是对不同的method并不能起到对IntHashMap的同步访问。



通过同事了解，Map有经典的“HashMap Infinite Loop”问题。http://coolshell.cn/articles/9606.html
但是本人一直怀疑，struts作为一款成熟的mvc框架，应该不至于犯这么低级错误。目前，我已经向struts社区发邮件，看他们是如何解释的。
附Cat地址：https://github.com/dianping/cat