记一次tomcat无响应事件

机器环境

  • Centos6 双核4G
  • jdk1.7.0_71
  • tomcat7.0.53

出现现象

在一次安全扫描的时候,进行到一半,nginx出现504错误。
进行服务器内, 用 curl测试tomcat服务,发现无响应。
使用htop查看内存及cpu占情况。
内存没占满,CPU占用80%左右。
检查数据库连接。数据库连接正常。

于是使用jstack导出tomcat的调用栈。

jstack调用栈信息分析

整个文件2188行。(正常情况下该项目jstack在500行左右)
文件比较长,不好直接看,所以先搜索统计。

0x1

以关键字http-bio-8080-exec-搜索。
有66个匹配,说明tcomat线程池中大概开了60多个活跃线程。

从最前面查看重复的调用栈。
卡在org.apache.tomcat.util.buf.UEncoder.initSafeChars函数上有39处。每处UEncoder.java的行数,有一样,有不一样,129,132等。

下载tomcat的源代码地址

第127行:safeChars=new BitSet(128);
感觉也没什么。
大概就是在UEncoder初始化的地方。
UEncoder是线程不安全的。

0x2

卡在java.lang.Long.parseLong上面有5处理。
这里是jdk的类,没有什么可以说的。

0x3

卡在http.URLParameter.clear(URLParameter.java:104)
http.URLParameter.clear(URLParameter.java:127)
有18处。
URLParameter.java是框架内的类。找到源码。
定位到104行:this.map.clear();
map的声明是private Map<String, Set<String>> map = new HashMap();这样的。

定位到127行

1
else for (String key : this.keys) {

keys的声明是这样的protected final String[] keys;

从感觉上猜测是回收map的时候出的问题。

0x4

找了下线程是阻塞状态的,只有两条State: BLOCKED

0x5

其中重复比较多的一个片段

1
2
3
4
5
6
7
8
9
10
11
12
13
14
"http-bio-8080-exec-99" daemon prio=10 tid=0x00007f08b445a000 nid=0xaee runnable [0x00007f08975e9000]
java.lang.Thread.State: RUNNABLE
at org.apache.tomcat.util.buf.UEncoder.initSafeChars(UEncoder.java:127)
at org.apache.tomcat.util.buf.UEncoder.<init>(UEncoder.java:45)
at org.apache.catalina.connector.Response.<init>(Response.java:258)
at org.apache.catalina.connector.Connector.createResponse(Connector.java:895)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:374)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313)
- locked <0x00000000d21c8568> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

总的来说

从栈信息来说,虽然是有很多重复的地方,但没有找到可能的原因。
如果是map的清除,引起的gc,占用cpu的情况,也是有可能。
gc占用的CPU优先级比较高,然后GC未完成之前,分配内存很慢,并其它线程等待时间片。
但无法解释UEncoder的问题,UEncoder有的是卡在分配set上,有的是在for循环上。

最终是没有找到原因。缺少更准确和能深入诊断的手段。

这类问题属于综合性的问题,重现一次需要很长时间。
解决的思路:
1,尽量找能快速重现的方法
2,查看外部资源状态,检查外部系统依赖问题
3,查看内部线程状态

当时只用CPU和内存方面查看了系统状态,没有看下磁盘IO及网络IO方面的情况。
目前只用到了jstack,还应该综合其它诊断工具来排查问题。