作者：王清培(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、作業系統等等。

作者：王清培

本文版權歸作者和部落格園共有，歡迎轉載，但未經作者同意必須保留此段宣告，且在文章頁面明顯位置給出原文連線，否則保留追究法律責任的權利。