一次tomcat壓測調(diào)優(yōu)記錄

1. 前言

該tomcat web應用承擔集團登錄注冊頁面功能，對性能有一定要求，由于先前沒有太多相關經(jīng)驗（只壓測過一個dubbo服務），這次調(diào)得比較艱辛，便做個記錄。

2. 調(diào)優(yōu)過程

起初沒有給運維任何tomcat配置要求，同時也沒留意去確認tomcat配置，這個導致了后續(xù)壓測過程各種詭異的問題。

a.在壓測初期，持續(xù)請求10分鐘左右出現(xiàn)無請求進來，netstat查看的tomcat所在服務器存在大量CLOSE_WAIT的連接。 
CLOSE_WAIT的連接一般是自己程序中缺少關閉連接等引起，但是查看程序也沒發(fā)現(xiàn)哪里沒有關閉，而且大多CLOSE_WAIT是與瀏覽器端的http協(xié)議下的tcp連接。后經(jīng)運維排查是centos自身的BUG引起，升級到centos-release-6-6.el6.centos.12.2.x86_64后解決。

其中對于CLOSE_WAIT和TIME_WAIT的TCP連接起初一直不太理解是怎么出現(xiàn)，怎么解決，后詳細查看TCP四次揮手斷開連接了解了整個過程。 （圖片來自網(wǎng)絡）
 
比如客戶端應用程序發(fā)起CLOSE信息，服務端接收到后進入CLOSE_WAIT狀態(tài)并做ACK，之后服務端程序發(fā)起CLOSE信息，客戶端接收到之后進入TIME_WAIT，服務端收到客戶端的ACK之后進入CLOSED狀態(tài)，客戶端TIME_WAIT需要等待到超時才進入CLOSED狀態(tài)。

基于此，服務器端出現(xiàn)大量CLOSE_WAIT不是一個正常的狀態(tài)，首先需要確認CLOSE_WAIT狀態(tài)對方的IP，再查看這個IP對應的代碼是否缺少關閉連接。 
但是如果出現(xiàn)大量TIME_WAIT，不是太要緊，只要不占滿句柄就行，如果真的占滿了可以嘗試修改內(nèi)核TCP超時時間和TCP的TIME_WAIT重用。

b.然后壓測500個并發(fā)出現(xiàn)connection timeout和read timeout，這種情況基本是在請求數(shù)超過了配置的最大值，一開始找運維排除nginx和vm的限流，然后再查看tomcat的限制，發(fā)現(xiàn)tomcat未配置最大線程數(shù)，默認情況最大線程數(shù)是200，最大等待隊列100，然后修改tomcat的server.xml配置

<Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol" connectionTimeout="30000"
        enableLookups="false" maxThreads="2048" minSpareThreads="100" acceptCount="512" URIEncoding="UTF-8"/>12

調(diào)整protocol使用nio的，調(diào)整最大線程（maxThreads）為2048用于壓測，最小空閑線程數(shù)（minSpareThreads）100，接收請求隊列最大（acceptCount）為512 
，到這里壓1000或者2000并發(fā)都不會出現(xiàn)拒絕請求的情況。

這里再細化下connection timeout和read timeout，connection timeout處于連接還沒建立就超時的狀態(tài)，如果不是網(wǎng)絡問題，多半是maxThreads+acceptCount不夠處理并發(fā)請求，可以嘗試增加這兩個值；read timeout是建立連接后，一種是等待在隊列太久沒處理導致超時、一種是程序自身執(zhí)行時間太久，可通過access log記錄請求執(zhí)行時長排查。

c.再壓一段時間后，出現(xiàn)請求響應慢，請求進不來，此時大多是connection refused（由于先前調(diào)整的線程池，一直還在排查線程池問題），后來查看gc日志發(fā)現(xiàn)一直在做full gc并且老年代內(nèi)存無法釋放，由于沒有指定過gc方式，當時以為是gc引起，所以先調(diào)整了gc配置為cms 
記錄gc日志和服務掛掉時dump內(nèi)存配置

-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采用并發(fā)標記清理的方式，后續(xù)再翻書學習下。TODO

d.通過修改gc方式得到了一定的緩解，在壓測不到30分鐘左右時發(fā)現(xiàn)又出現(xiàn)吞吐量降低，響應非常慢的問題； 
大致知道是有很多對象沒釋放，通過jmap查看前20個占用最大的對象（./jmap -histo pid | head -n 20 ），好像都還好，最大的是session不過也才300多M（估計是當時剛好不在壓力期間已經(jīng)被釋放完了）； 
然后在出現(xiàn)慢的時候dump了全部內(nèi)存下來，但是實在太大了（5G），下載太久； 
之后把堆內(nèi)存調(diào)整為1G并壓到出現(xiàn)慢，查看dump也是session最大，占百分之八十左右，這時候還沒意識到是session的問題，以為1G太小看不出根本問題； 
再把堆內(nèi)存調(diào)整為2G并壓到出現(xiàn)慢，查看dump發(fā)現(xiàn)session占了1.5G，突然靈光一閃，我這邊request session是封裝放到redis的，本地的tomcat session占這么大是不對的。。。（閃得也太遲了點吧），然后把tomcat的session超時時間設置成一分鐘果然不會再出現(xiàn)頻繁FULL GC的問題。再查看代碼，原來是封裝的session的地方腦抽的寫了個super.getSession(true)。默認配置下每次請求來都會生成新的session，并且超時時間是30分鐘，在內(nèi)存中占30分鐘才被銷毀??！

看起來上面的問題都非常明顯。。。但是在一個壓測環(huán)境下去找這些問題源頭是什么真是麻煩死了。。

e.好了，最后一步，光明就在不遠的前方。壓測結(jié)果不算太理想，tps在4800左右，不過最起碼長時間壓下來算是穩(wěn)定了。之后通過jprofile工具查看cpu的消耗在哪來分析單次請求耗時點。 
 
jprofile去連接遠程機器時需要在遠程機器開啟agent，執(zhí)行bin/jpenable后選擇是給gui訪問然后填寫端口即可。

f.這里再記錄下穩(wěn)定壓測后想做一些優(yōu)化遇到的問題： 
這邊在嘗試提高TPS的時候，發(fā)現(xiàn)查看所有的壓測指標資源貌似都未被占滿，但是吞吐量始終上不去（應該是哪個未留意到的資源被占滿了），tomcat線程池一半不到，cpu百分之70左右浮動，堆內(nèi)存1G不到，磁盤IO在百分之八左右，帶寬占用很低（速度在80k/s）tcp連接數(shù)在1W+ 
排查這個問題時首先懷疑到可能是使用到的一個后端http服務跟不上，通過mock掉該服務后無明顯提升 
后懷疑是tomcat沒配置正確，然后空壓一個test.jsp，tps在2W+ 
再懷疑是redis沒使用正確，在空test.jsp前使用一個redis session filter，相當于只壓redis，tps也在1W8到2W+ 
這個時候已排除了所有的外圍服務，確認了是自身程序的問題，通過jprofile去查看耗時較大的一個函數(shù)，發(fā)現(xiàn)ua解析較慢，通過將解析結(jié)果放到threadlocal，tps得到小幅增長，從4800到5000+ 
然后發(fā)現(xiàn)log4j的block較多，通過將log4j的級別調(diào)整到ERROR后，tps一下能到7000+，但是還是不能理解，后有同事說可能是磁盤IO次數(shù)的限制，這個當時沒有關注到的點，但是環(huán)境已被撤除。

3. tips

3.1 壓測開始前準備 
設定壓測業(yè)務場景：比如用戶從加載登錄頁面到使用賬號密碼登錄完成 
準備壓測環(huán)境：與線上同等配置的服務器以及數(shù)據(jù)量,資源無共享的純凈環(huán)境 
根據(jù)線上需求制定壓測目標：比如TPS>1000，平均響應時間<100ms，錯誤率<0.01%，穩(wěn)定運行，CPU<80%，無內(nèi)存溢出，F(xiàn)ull GC間隔時長>30分鐘，gc時長<150ms 
配置資源數(shù)：各線程池、連接池大小，內(nèi)存分配大小，tomcat連接數(shù)

3.2 制定壓測目標 
TPS >= (80% * 單日訪問量) / (40% * 24 * 60 * 60)，線上80%的請求量幾種在40%的時間，根據(jù)線上情況進行調(diào)整

3.3 如何配置資源數(shù) 
根據(jù)平均響應時間和TPS計算tomcat線程池大小，TPS/(1/RT)，比如TPS>=5000，平均響應時間<=100ms，線程池大小配置5000/10,再往上調(diào)整CPU數(shù)目的整數(shù)比例（這種計算方式不一定好，主要響應時間這個不太好定，上下會相差較大，） 
數(shù)據(jù)庫連接池或其他線程池大小可先設定為tomcat線程大小的一半，根據(jù)壓測結(jié)果再進行調(diào)優(yōu)

3.4 壓測指標及對應查看工具 
CPU，top/visualvm 
內(nèi)存，free查看系統(tǒng)內(nèi)存使用情況/jmap可查看最大使用的內(nèi)存對象以及dump全部堆/visualvm/mat查看dump分析內(nèi)存泄露對象及其引用 
磁盤IO，iostat 
磁盤空間，df -hl 
網(wǎng)絡帶寬，iptraf 
連接數(shù)，netstat 
線程，top -Hp pid/jstack pid/visualvm/tda查看線程dump/jprofile監(jiān)控實時線程block情況 
FULL GC，-Xloggc:/path/gc.log開啟gclog后查看gclog、jstat -gc 
響應時長，jprofile查看耗時較大的函數(shù)

3.5 定位瓶頸分三步走 
檢查壓測端瓶頸，可通過壓一個恒定標準測試（比如壓空的test.jsp），基本就在壓測初期檢查一次就差不多 
通過查看壓測指標變化情況定位資源瓶頸，再根據(jù)資源瓶頸定位程序瓶頸 
比如根據(jù)監(jiān)控顯示每次GC后堆內(nèi)存呈上漲趨勢，可在兩次GC之后分別查看占用內(nèi)存較大的對象，對比這些對象的數(shù)目和大小，如果有明顯上漲較厲害的，可特別查看下 
TODO圖片 
在第二步查看問題中，可能出現(xiàn)影響因素較多的情況，這樣可通過mock掉部分懷疑的因素或者單壓某懷疑因素 
比如系統(tǒng)中使用的外圍服務包括數(shù)據(jù)庫、redis，現(xiàn)在懷疑可能是查數(shù)據(jù)庫或者在查redis的時候?qū)е峦掏铝可喜蝗ィ藭r可通過mock掉數(shù)據(jù)庫的查詢查看下吞吐量是否有提升，如果有提升則說明多半是數(shù)據(jù)庫查詢導致

3.6 優(yōu)化 
在定位到瓶頸點之后，相對來說優(yōu)化就沒那么復雜，無外乎對瓶頸資源的少用、復用和交換資源。 
比如在程序中一個請求下來會查詢N次賬號信息，可以考慮把該賬號信息放置到緩存或者內(nèi)存之類的。 
可以從業(yè)務角度去考慮優(yōu)化，比如某個擴展業(yè)務直接影響到主業(yè)務的性能，且該擴展業(yè)務本身不是那么重要，可以考慮通過縮減該擴展業(yè)務的方式做到優(yōu)化。