一次tomcat压测调优记录

QQ叫紫珊

1. 前言
该tomcat web应用承担集团登录注册页面功能，对性能有一定要求，由于先前没有太多相关经验（只压测过一个dubbo服务），这次调得比较艰辛，便做个记录。
2. 调优过程
起初没有给运维任何tomcat配置要求，同时也没留意去确认tomcat配置，这个导致了后续压测过程各种诡异的问题。
a.在压测初期，持续请求10分钟左右出现无请求进来，netstat查看的tomcat所在服务器存在大量CLOSE_WAIT的连接。
CLOSE_WAIT的连接一般是自己程序中缺少关闭连接等引起，但是查看程序也没发现哪里没有关闭，而且大多CLOSE_WAIT是与浏览器端的http协议下的tcp连接。后经运维排查是centos自身的BUG引起，升级到centos-release-6-6.el6.centos.12.2.x86_64后解决。
其中对于CLOSE_WAIT和TIME_WAIT的TCP连接起初一直不太理解是怎么出现，怎么解决，后详细查看TCP四次挥手断开连接了解了整个过程。 （图片来自网络）
http://img.blog.csdn.net/20151024103749050
比如客户端应用程序发起CLOSE信息，服务端接收到后进入CLOSE_WAIT状态并做ACK，之后服务端程序发起CLOSE信息，客户端接收到之后进入TIME_WAIT，服务端收到客户端的ACK之后进入CLOSED状态，客户端TIME_WAIT需要等待到超时才进入CLOSED状态。
基于此，服务器端出现大量CLOSE_WAIT不是一个正常的状态，首先需要确认CLOSE_WAIT状态对方的IP，再查看这个IP对应的代码是否缺少关闭连接。
但是如果出现大量TIME_WAIT，不是太要紧，只要不占满句柄就行，如果真的占满了可以尝试修改内核TCP超时时间和TCP的TIME_WAIT重用。
b.然后压测500个并发出现connection timeout和read timeout，这种情况基本是在请求数超过了配置的最大值，一开始找运维排除nginx和vm的限流，然后再查看tomcat的限制，发现tomcat未配置最大线程数，默认情况最大线程数是200，最大等待队列100，然后修改tomcat的server.xml配置
12调整protocol使用nio的，调整最大线程（maxThreads）为2048用于压测，最小空闲线程数（minSpareThreads）100，接收请求队列最大（acceptCount）为512
，到这里压1000或者2000并发都不会出现拒绝请求的情况。
这里再细化下connection timeout和read timeout，connection timeout处于连接还没建立就超时的状态，如果不是网络问题，多半是maxThreads+acceptCount不够处理并发请求，可以尝试增加这两个值；read timeout是建立连接后，一种是等待在队列太久没处理导致超时、一种是程序自身执行时间太久，可通过access log记录请求执行时长排查。
c.再压一段时间后，出现请求响应慢，请求进不来，此时大多是connection refused（由于先前调整的线程池，一直还在排查线程池问题），后来查看gc日志发现一直在做full gc并且老年代内存无法释放，由于没有指定过gc方式，当时以为是gc引起，所以先调整了gc配置为cms
记录gc日志和服务挂掉时dump内存配置
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/vol/logs/heap.bin -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/vol/logs/gc.log1修改为cms的gc方式的配置
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=10 -XX:+CMSClassUnloadingEnabled -XX:+CMSParallelRemarkEnabled -XX:MaxTenuringThreshold=15 -XX:CMSInitiatingOccupancyFraction=70 1对CMS的GC理解不深，大致知道默认的gc方式是阻塞应用，CMS采用并发标记清理的方式，后续再翻书学习下。TODO
d.通过修改gc方式得到了一定的缓解，在压测不到30分钟左右时发现又出现吞吐量降低，响应非常慢的问题；
大致知道是有很多对象没释放，通过jmap查看前20个占用最大的对象（./jmap -histo pid | head -n 20 ），好像都还好，最大的是session不过也才300多M（估计是当时刚好不在压力期间已经被释放完了）；
然后在出现慢的时候dump了全部内存下来，但是实在太大了（5G），下载太久；
之后把堆内存调整为1G并压到出现慢，查看dump也是session最大，占百分之八十左右，这时候还没意识到是session的问题，以为1G太小看不出根本问题；
再把堆内存调整为2G并压到出现慢，查看dump发现session占了1.5G，突然灵光一闪，我这边request session是封装放到redis的，本地的tomcat session占这么大是不对的。。。（闪得也太迟了点吧），然后把tomcat的session超时时间设置成一分钟果然不会再出现频繁FULL GC的问题。再查看代码，原来是封装的session的地方脑抽的写了个super.getSession(true)。默认配置下每次请求来都会生成新的session，并且超时时间是30分钟，在内存中占30分钟才被销毁！！
看起来上面的问题都非常明显。。。但是在一个压测环境下去找这些问题源头是什么真是麻烦死了。。
e.好了，最后一步，光明就在不远的前方。压测结果不算太理想，tps在4800左右，不过最起码长时间压下来算是稳定了。之后通过jprofile工具查看cpu的消耗在哪来分析单次请求耗时点。
http://img.blog.csdn.net/20150927214704344
jprofile去连接远程机器时需要在远程机器开启agent，执行bin/jpenable后选择是给gui访问然后填写端口即可。
f.这里再记录下稳定压测后想做一些优化遇到的问题：
这边在尝试提高TPS的时候，发现查看所有的压测指标资源貌似都未被占满，但是吞吐量始终上不去（应该是哪个未留意到的资源被占满了），tomcat线程池一半不到，cpu百分之70左右浮动，堆内存1G不到，磁盘IO在百分之八左右，带宽占用很低（速度在80k/s）tcp连接数在1W+
排查这个问题时首先怀疑到可能是使用到的一个后端http服务跟不上，通过mock掉该服务后无明显提升
后怀疑是tomcat没配置正确，然后空压一个test.jsp，tps在2W+
再怀疑是redis没使用正确，在空test.jsp前使用一个redis session filter，相当于只压redis，tps也在1W8到2W+
这个时候已排除了所有的外围服务，确认了是自身程序的问题，通过jprofile去查看耗时较大的一个函数，发现ua解析较慢，通过将解析结果放到threadlocal，tps得到小幅增长，从4800到5000+
然后发现log4j的block较多，通过将log4j的级别调整到ERROR后，tps一下能到7000+，但是还是不能理解，后有同事说可能是磁盘IO次数的限制，这个当时没有关注到的点，但是环境已被撤除。
3. tips
3.1 压测开始前准备
设定压测业务场景：比如用户从加载登录页面到使用账号密码登录完成
准备压测环境：与线上同等配置的服务器以及数据量,资源无共享的纯净环境
根据线上需求制定压测目标：比如TPS>1000，平均响应时间