性能壓測詭異的Requests/second 響應刺尖問題

做者：王清培(Plen wang)  滬江Java資深架構師

最近一段時間都在忙着轉java項目最後的衝刺，前期的coding翻代碼、debug、fixbug都逐漸收尾，進入上線前的性能壓測。

雖然不是大促前的性能壓測要求，可是爲了安全起見，須要摸個底內心有個數。

畢竟此次轉java的服務都是集團核心公共服務(主要是訂單域服務)。（等咱們順利上線了，我再來好好總結下其中的坎坷和壯舉。）

廢話很少說了，直接進入主題。

因爲此次壓測主要重點是關注正向的兩個核心訂單服務，下單服務、查單服務。查單服務初步壓測下來問題不大，主要是db的索引和cache的問題。

下單服務有兩個核心接口，預訂單查詢、建立訂單。預訂單查詢主要是訂單的前置狀態的結算頁彙總計算（不只是結算頁），不落具體訂單，如，各類促銷、卡券碼、虛擬幣的規則計算等等。

建立訂單邏輯稍微複雜點，對周邊的系統及中間件依賴也比較多，因此須要重點關注，至少心中要有數，哪怕下游的哪一個服務的性能有問題，在下次大促的時候能夠優化掉。

（並非說全部性能問題都須要及時優化，只要保證能撐得起業務量的必定範圍就好，由於性能優化無止境，須要把握好節奏。）

提交橫向壓測前咱們須要本身先過一遍，這樣才能加快壓測的效率，因爲時間比較緊再加上客觀的環境問題，我將服務中幾個沒有壓測環境的依賴去掉。（有關壓測的一些實踐我將在下篇文章好好總結下，這裏就不展開了。）壓測了幾輪（時間差很少30分鐘左右。），消除了一些環境、代碼、依賴的障礙，提交橫向走壓測流程，接着就去忙其餘的事情了。（詭異的問題比較多~_~，mybatis pagehelperplugin好像也有點併發問題，還沒定位到，不知道是用的不對仍是什麼狀況，繼續排查，有結論了我在總結分享下。）

1.壓測報告：

併發用戶數沒變化，平均響應時間沒變化，可是request/second奇怪了。我相信大多數開發的直覺就是fullgc了，我也同樣。

立馬去看下服務器的GC監控，同時看下程序的GCer配置是CMS。（CMS主要解決低延遲問題《深刻理解JAVA虛擬機》）

2.查看服務器監控狀況：

JAVA GC：

沒發現fullgc，再看下幾個其餘的系統資源是否有異樣。

cpu:

刺尖的幾個點CPU idle 基本都是100%，us也是0%，很是奇怪。再看下其餘的資源。

network：

也是比較奇怪的，receive到是挺正常的，send基本爲0了，感受像是某個調用或者發送中止了，能接受請求，可是對下游的調用貌似中止了。

memory：

內存咋一看好像有點問題，可是瞭解linux 內存計算方式和使用原理都知道這其實問題不大。(下篇文章中會具體講解關於壓測的時候各個指標如何查看和計算，在壓測時候重點關注top中的swap區。)

我程序裏面基本上沒有用到什麼大量的磁盤操做，基本上就一個日誌輸出，別的沒有了。（linux cache區不論是讀仍是寫都會被cache住，會在cache裏維護一個邏輯地址空間。我將在下篇文章中演示出來，每當我刪除磁盤的日誌文件，cache區都會瞬間釋放。https://www.ibm.com/developerworks/cn/linux/l-cache/index.html）

重點是關注下JAVAGC 容量：（java程序的內存分配由「內存分配器+GC完成」《java性能優化權威指南》）

這是壓測的下單服務機器資源狀況。

3.查看DB狀況：

看了下DB狀況，也沒啥異樣，都是在相同的時間點，一會兒負載沒有了，時間都能對上。網絡、磁盤、CPU都沒有活動。

4.分析

上面圖中有一幅圖有點問題，不知道你們看出來了沒有。就是我下單服務的應用服務器的網絡流量有問題，receive、send對不上。

咱們分析下，receive、send不配對意味着什麼，咱們有200併發，延遲1秒啓動，基本上跑上個十幾分鍾，你能大概想象出200併發的請求空間路線圖麼。其實它會呈現出每秒鐘都有請求進來，這是壓力機的請求，每秒也會有請求出去，去訪問它所依賴的服務或者中間件。若是，咱們設想從壓力機爲開始點，把請求和響應想象成一個圓，那在圓的任何一個角度上都有請求和響應。

咱們注意看下，DB的網絡流量圖，它就是比較正常的，沒有請求沒有發送。而應用服務器有點說不通，只有進來的沒有出去的，這段時間內到底在幹嗎，並且分佈很平均。

5.排查

其實這個時候有一個結論，就是服務器其實沒有瓶頸，不論是應用服務器仍是DB、cache。那問題應該是在程序方面。（性能分析由上至下、由下至上集合分析《java性能優化權威指南》）。

開始嘗試排查依賴服務，下單服務主要依賴商品、促銷。cache不是問題，由於本地有一級緩存，並且緩存的過時時間對不上，壓測環境的redis和MySQL在一臺機器上。因此DB沒有問題，基本上redis應該也沒啥問題。（這臺機器很強悍）還有部分的依賴業務方的接口我已經註釋掉了，不會有依賴。

開始懷疑商品、促銷，可是我以前分別對這兩個服務進行過壓測，這兩個服務基本上都是命中cache，QPS基本上接近18000。如今也只好對這兩個服務再進行一輪詳細的壓測。

結果很遺憾，沒啥線索，性能很好。

開始排查線程池問題，是否有block線程，經過jstack 打印出線程，基本上都是XNIO的condition wait，也沒有啥不正常。由於下單服務的其餘接口都挺正常的，線程池問題應該不大。下單成功以後有意個hold的場景，就是hold虛擬幣、卡券碼等等之類的邏輯，這裏面使用了fiexd線程池（5個，設置了飽和策略及日誌輸出。），問題也不大。

開始排查日誌，restful-slow.log，jdbc-slow.log、錯誤日誌等等，一頓cat… grep…wc –l，啥也沒有異常。(shit開始冒汗了。。。)

只能上大招了，開始嘗試注代碼，而後壓測，逐個嘗試，先註釋DB、而後線程池hold邏輯、而後發送消息。(無賴之舉。。。)

6.浮出水面

等我嘗試註釋掉髮送消息的邏輯時候發現問題不出現了，有但願了。開始進去看代碼，沒啥邏輯，走的是spring 的RabbitTemplate.convertAndSend 方法。（這是個同步方法，沒有任何聲明說他是async的。）

/**發送消息*/
template.convertAndSend(messageConfig.getExchangeName(), routingKey, message, amqpMessage -> {

翻了下資料，沒啥特殊的使用要求。

順便看了下配置文件，發送消息走的是qa環境，這個我知道，由於當時壓測環境的rabbitmq一時還沒好，並且咱們走的是先定義再使用queue的流程，因此若是要用我須要先上去配置好才能使用。當時圖省事就先用了，本身壓測下來也沒啥問題，畢竟MQ的設計吞吐量都很高的，TPS足夠咱們用的，再加上我以前也壓過qa的MQ沒啥問題。

（資源沒隔離是由於一些客觀緣由，有時候壓測環境是臨時搭建的。用到qa環境的中間件還有codis，可是codis基本是二級緩存，因此問題不大，先過。(回頭沒轍再來找它。)

搞來了qa環境的rabbitmq服務器帳號，同時打開rabbtimq管理界面中的dashboard。開始重點關注這臺服務器。(top命名打開，P\M看下rabbitmq各項指標。)

問題一如既往的出現了（我已經能接受了~_~，它要是不出現我纔想死尼，已經來回折騰好久了。）很好，rabbtimq dashboard也出現刺尖了。

如今基本上是rabbtimq服務器的性能問題了，可能你會以爲問題找到了。可是我仍是無解，爲何出現這個問題，爲何時間這麼規律，確定有蹊蹺，繼續排查，究竟是rabbtimq服務器的CPU問題仍是disk問題，仍是network問題。此次重點看下top。

一樣問題的出現CPU不正常，並且wait 率比較高。是否是能夠這樣推理，wait率高了，致使大量線程（子進程）掛起，因此看起來CPU利用率佔的就高，也說的通。（先這麼假設，來驗證它就知道了）

有一點我能夠確定，根據rabbtimq推送消息原理，一個消息必須發送給全部監聽的queue，這些queue必須落盤纔算此次publish成功，纔會返回。(能夠參考《Rabbitmq in Action》)

這一點能夠經過rabbtimq queue的dashboard 中的publish in 和 publish out才查看，publish out 是publish in * queue的數量。

也就是說發送消息不是發送給exchange就結束了，咱們配置的是topic模式，這個消息類型後面有4個queue，同時這幾個queue都有消費者在獲取消費消息。可是因爲獲取消息的方式是pull模式，也不會存在多大的併發獲取消息的狀況。並且這些queue裏面的消息都很是多，當我不壓的時候CPU也不高，pull消息的開銷對服務器來講network多點，CPU不會太多。

上圖中的cpu wait率有點不正常是由於exchange同步寫4個queue且落盤，因此有這個問題。

基於這個推理，我考慮用一個空exchange來接受消息，根據原理指導，exchange收到消息以後若是發現沒有任何queue能夠投遞就直接丟棄了。

壓測下來一切正常，沒有出現刺尖狀況（真爽~_~），cpuwait 正常0。基本上定位到問題了。是由於rabbtimq自己的負載不夠了，性能跟不上因此致使這個問題，這也算加深了rabbtimq的部分原理。

在基於這個推理，我用了一個不持久化的queue來接受消息，也就是說這個消息是不會持久化的，cpuwait應該是0。

壓測下來一切正常，cpuwait爲0（心情無比的順暢）。

提交橫向第二輪壓測。

7.打臉

等我在開會的時候，壓測兄弟找我，哥哥那個問題又出現了。

（我一時矇蔽，我擦什麼狀況。）調整了下，仔細看了下那個刺尖的出現的時間比之前長了。原來大概十五分鐘，如今要半小時。因爲qa環境機器沒有安裝壓測監控工具，不知道那段時間裏發生了什麼。（壓測執行時間1小時）

我以前都是30分鐘，我嘗試用空exchange壓了一小時（已經是週五晚24:00點左右，洗澡睡覺，明早上看結果)。

早上起來看沒出現那個問題。爲何我用不持久的queue還有問題，並且這個queue是沒有任何consumer的，這已經涉及到rabbtimq的底層原理了。rabbtimq用的是erlang語言寫的，看源碼一時半會估計路都找不到。仍是想其餘辦法。

又嘗試用持久化queue來壓測一把，看下到時候啥狀況，仔細盯着rabbtimq dashboard，果真又出現了。（計算機問題永遠不存在巧合，不肯定。）

注意看下圖中的In memory，shit原來落盤了，哪怕你設置不持久化爲了內存利用率，它會將消息落盤，注意看Persistent沒有任何消息。消息總量1.1G，內存中只有119MB。

爲何會有那麼大的disk write。因爲大量的磁盤寫入，致使publish消息的時候block了。具體爲何會這樣就要去研究rabbtimq源碼了。這些在rabbtimq的配置中應該有策略的，因爲不是太熟悉rabbtimq，因此這裏就只好先告一段落了。

8.總結

能隔離環境的儘可能隔離，排查環境問題最頭疼，可是有時候又沒法避免。（下篇壓測文章分享下，環境問題的排查方式和工具）

遇到問題必定要搞清楚根源，就算找不到根源也知道把它限定在某個範圍內，好比限制到DB、操做系統等等。

 

做者：王清培

出處：http://www.cnblogs.com/wangiqngpei557/

本文版權歸做者和博客園共有，歡迎轉載，但未經做者贊成必須保留此段聲明，且在文章頁面明顯位置給出原文鏈接，不然保留追究法律責任的權利。