计算机

一次Tomcat hang住问题排查手记

2014-08-05
大胆假设：现网Tomcat线程池设置的太大了，因为某种原因导致线程堵住了，然后不停的创建线程，然后被堵的越多，Tomcat创建线程越多，同时线程上下文切换代价越来越大，恶性循环，最后整个Tomcat进程hang住了。增大线程数或连接数等，只是延迟了请求堆积的时间。

• 连接池：C3P0，MyBatis POOLED
• 缓存：MyBatis缓存，MySQL缓存，Redis缓存
• dump分析：大量BLOCKED (on object monitor)，都是- locked <0x0000000763c01dc0> (a com.mchange.v2.resourcepool.BasicResourcePool)
• 运维反馈是Tomcat线程耗完了，但是MySQL端连接很少
• 系统资源消耗：重点关注线程
• 故障的时候到底有多少的请求落到MySQL上面了
• 应用程序没有抛异常
• 我们用的MySQL版本比较新

重现：使用MyBatis默认的连接池（没做什么参数调优），TPS只有几十，日志表现就是读取MySQL的地方很慢。MySQL端看没有慢查询，线程都是sleeping……
但是貌似不是必现的，Loadrunner压测表现为：第一次压测总体TPS正常，但是有波动，从波动的周期看很像是因为MyBatis缓存的问题。

c3p0重现：500路没问题，尝试800路并发压，tomcat最大线程池为3000，c3p0连接池为100：
发现Tomcat线程越来越多，TPS越来越低，当线程达到Tomcat线程池设置的 最大值后，整个Tomcat hang住了（这时mysql的线程也很多），TPS基本为0,从体质表现来看，响应时间超长。值得注意的是测试环境重现是发现Tomcat会从僵死的状态恢复过来，但是线程数一直满的。然后过一段时间又“悲剧重演”。

从测试时的thread dump来看跟现网故障时表现一直，90%以上都是Object.wait() ,wait的地方也是一样的,表现正常的情况Object.wait()占用的比例会少很多。

尝试快速重现：减少Tomcat线程数（500），减少c3p0的连接池大小（100），同样800路并发。
结果是：TPS反而更高，性能表现更稳定。从thread dump来看，相对的Object.wait()比例少很多。
是不是有可能是之前的线程池太高了，上下文切换开销太大了。

再次尝试，保持c3p0连接数100不变，Tomcat线程6000
压了1个小时，没有重现，线程数也没有疯涨，维持在1000以下，处于busy的线程只有100多

尝试大的线程池和连接池，6000,3000
没有重现

不是必现的。

===============
因为很难重现，所以想进一步模拟现网的场景。多个接口混合压测
version,config,downres各1/3共800路，线程数和连接池和上面一样。
只有version接口的TPS非常低，从thread dump看Object.wait()非常严重而且貌似死循环

定位还是Version接口有问题，用jvisualvm监控：
从监控的结果看，CPU基本都耗在了com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable这个方法上，这个之前的thread dump表现是一致的

猜测：MyBatis使用有问题，或者是查询SQL有问题，只是version接口表现的更严重，现网出现故障的时候不会是有大量的version不过：

可能突破：终于看到应用程序抛异常了
看异常信息好像是MySQL挂掉了，难道把MySQL压挂了，telnet一下：Too many collections

一直只是断定应用程序有问题，MyBatis问题，没怎么关注MySQL本身。

ERROR 1040 (HY000): Too many connections

查看mysql端的连接数达到了将近5000，mysql设置的最大值,mysql大量线程长时间sleep

究其原因还是因为应用端链接堵住了导致连接池没有可用的空闲连接，至于为什么堵住，还是得进一步分析。

尝试通过慢查询分析看是不是有哪个SQL执行太慢导致整个连接堵住了，最终把连接池耗完了。

mysqladmin -uroot -p密码 status -i 5 

这是回头看了下应用程序的thread dump发现有大量(95%)的MySQL Statement Cancellation Timer线程处在Obeject.wait()状态。

===============

看源码
从thread dump看，还有现网将所有MySQL请求都走缓存之后恢复正常来看，嫌疑最大的还是MyBatis这块，要不是使用有问题，要不是NyBatis自身问题。

===============
黔驴技穷，死马当活马医
- MyBatis版本问题
- 或者MySQL和JDBC驱动不兼容问题
- 或者是JDK版本问题

==============================
能够确认的
- c3p0的表现跟MyBatis的表现基本一致，也存在性能不稳定的情况（无论是downres还是version）
- 使用MyBatis如果缓存不开启性能非常差，Tomcat和MySQL连接数都很高

==========明天计划===============
- 将tomcat换到31上试试 没解决
- mysql wait_timeout...
- mybatis版本 升级到3.2.6没解决
- mysql版本
- jdbc驱动版本
- 精简version接口sql试试
- GC的版本 见第1点
- 找一个稳定的版本，长时间压测观察

2014-08-06

对比测试
换了一台机器（82.31）Tomcat，同一个war包，同一个MySQL(也是82.31)，同一个jdk。
开没开启MyBatisTPS都是2300左右

Tomcat线程很正常，800多，MySQL的连接数也之前（Tomcat部署在82.32）上低很多，之前最高达到了将近5000(too many connections)，现在稳定后只有1300多

怀疑：可能是Tomcat的问题，但是不排除是因为82.31上时本机访问MySQL性能会更好点，因为毕竟少了网络交互，虽然是内网影响应该微乎其微。
于是将82.31上的Tomcat复制到82.32再压，结果还是性能很差。

更换MyBatis驱动
将MyBatis驱动从3.2.3升级到3.2.6
从82.32测试，TPS来看有不错的提升（20%，TPS1400+到1700+），但是82.31上测试则几乎没有提升。

更换JDBC驱动版本
目前是mysql-connector-java-5.1.26，升级到5.1.30从TPS来看没有提升。

MySQL wait_timeout参数设置

重大突破
在之前82.31一直表现较正常的机器上重现了MySQL连接数暴高的现象，导致请求卡死,Tomcat进程直接被kill掉，这时MySQL段看线程也很多，而且大量线程sleep。
使用的是mysql-connector-java-5.1.30和mybatis-3.2.6，mybatis缓存开不开器表现一样，就是mysql连接数暴增，连带导致Tomcat线程池耗尽，最后Tomcat hang住了。

查看tomcat进程发现资源存在泄漏，内存很大，然后进程被kill掉。回头看82.32上面的。

只要对MyBatis的配置文件mysql-config-ossp21imebase.properties进行修改，就会导致MySQL连接数暴增（测试时是从400多一下暴增大3600多，可能是跟前端压力有关），貌似是只要改文件的最后修改时间发生变化就会导致这种现象。这不一定是现网的问题，但可能是个突破口，但定位到昨晚调试MySQL出现too mant connections的原因。

MyBatis应该是对配置文件做了监听，当配置文件修改的时候会重建所有连接，也有可能是其他什么因素触发了这个操作。

thread dump表现也是大部分都处于Object.wait()状态，但是跟现网故障表现不一样的是，测试环境处于这个状态的大部分是一个叫做MySQL Statement Cancellation Timer的线程,而现网除了这个线程大部分都是Tomcat线程。此外测试环境还有很多Tomcat线程处于Waiting on condition

Thread Name
catalina-exec-20
State
Waiting on condition
Java Stack
at sun.misc.Unsafe.park(Native Method) 
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226) 
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082) 
at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467) 
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:86) 
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:32) 
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) 
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) 
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) 
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) 
at java.lang.Thread.run(Thread.java:745) 
Native Stack
No Native stack trace available

hread Name
MySQL Statement Cancellation Timer
State
in Object.wait()
Java Stack
at java.lang.Object.wait(Native Method) 
at java.lang.Object.wait(Object.java:503) 
at java.util.TimerThread.mainLoop(Timer.java:526) 
- locked [0x00000006162e50d0] (a java.util.TaskQueue) 
at java.util.TimerThread.run(Timer.java:505) 
Native Stack
No Native stack trace available

从MySQL看连接数也一直维持在一个很高的值，尝试调整interactive_timeout和wait_timeout两个参数：http://www.itpub.net/thread-1308603-1-1.html。

===================================
后续能做的
- 稳定的测试环境，长时间压测看能不能重现现网问题
- 分析mysql的slowlog
- 现网MyBatis缓存都开启
- 减小MySQL的wait_timeout和interactive_timeout以及系统的TIME_WAIT,能让连接尽快的释放掉，这样可以减少MySQL和Tomcat的sleep线程（测试验证）。
- 现象Tomcat线程池设置太了
- 统计下零点哪些接口暴增

=====================================
2014-08-07
重新梳理
根据运维反应现网Tomcat hang住的时候，tomcat线程耗尽，c3p0没有可用的连接，但是后端mysql看过来的连接却很少。

感觉还是c3p0连接池的问题，很多配置可以优化，网上也有不少跟我们现网情况很像的：

http://stackoverflow.com/questions/14105932/c3p0-hangs-in-awaitavailable-with-hibernate
http://sourceforge.net/p/c3p0/bugs/55/
http://stackoverflow.com/questions/7824481/spring-orm-with-c3p0-or-dbcp-is-leaking-connections

Connection leak
http://www.mchange.com/projects/c3p0/#configuring_to_debug_and_workaround_broken_clients

debug连接泄露
http://blog.csdn.net/xfworld/article/details/7434462
debugUnreturnedConnectionStackTraces和unreturnedConnectionTimeout

==============================
90%以上tomcat线程处于下面的waiting on condition：

at sun.misc.Unsafe.park(Native Method) 
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) 
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043) 
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) 
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:104) 
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:32) 
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) 
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) 
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) 
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) 
at java.lang.Thread.run(Thread.java:745)

但这可能是正常的：
That is a SchedeuledExecutorService which will be waiting probably most of the time. You should look else where. The waiting in here does not consume CPU so would not cause further performance problems.

http://stackoverflow.com/questions/8086463/finding-the-cause-for-waiting-sleeping-threads

但也：
http://stackoverflow.com/questions/10878983/100-threads-timed-waiting-in-tomcat-causing-it-to-stall-as-total-number-of-thre

This got fixed when we fixed our code which was leaking DB connections managed by c3p0. There were few flows in our code where we were not calling rollback() specifically in catch block before closing entity Manager in finally block, so in case of exceptions connection was not coming back to pool and if frequency of exception is high(more than size of pool within timeout interval) then all other process threads would pile up to get connection

足够多的线程，但是没有足够多的内存
http://stackoverflow.com/questions/8086463/finding-the-cause-for-waiting-sleeping-threads

I'm going to agree with @ptyx on this. Presumably clicking a button in your application sends a requests to the Tomcat server. My guess is that you have a bad configuration telling Tomcat to be able to handle an obscenely large number of requests because you want to be enterprisey. Tomcat keeps making a new Thread in its ThreadPoolExecutor because it hasn't reached corePoolSize. Ultimately crashing your server because you have configured for a large number of threads but not allowed for enough memory to allocate all the stack space needed for those threads. But that is just my guess.

==========================
MyBatis性能问题
如果没有开启MySQL查询缓存，及时是类似select 1这样的查询语句执行都非常的慢。

mysql后端表现在runing的线程始终只有1,2个，其他线程再多都在sleeping。

插入性能 500路tps也只有300多。

===========================
最后一些经验总结

• 现网部署结构优化：mongodb,redis
• 组件优化：
  MongDB：分片不合理出现热点数据，重新分片，faults值很高，touch，连接数很高：db.runCommand({ setParameter : 1, releaseConnectionsAfterResponse : true })，新版本才有这个参数，numa的问题
  分库，减小字段值
  MySQL:5.7
  Redis:mget或get的数据量比较大的时候(4k)性能会比较低，分片和主从
• 业务逻辑优化：业务逻辑精简，remote cache and local cache

有时候提升程序的吞吐量和性能总是容易从底层的技术着手，比如数据存储是否可扩展，其实有时候回过头来，发现业务上的一点点优或取舍可能会带来巨大的性能提升。

Assertion Results对jmeter压测的throughout有严重的影响。

性能测试一定得建立在精确的测量之上，测试方法和手段会严重影响或干扰测试结果。
选择合理的测试场景对测试结果影响很大。