分享一次分析/解決支付應用效能問題的全過程

Reference :  http://supercharles888.blog.51cto.com/609344/1587045

引入：

當我們做的某支付系統，以一組web service的方式，部署到生產環境之後，外界手機APP應用呼叫，發現其響應速度在0.5秒到6秒之間波動，客戶已經為此糾結了2星期了。昨天我應邀幫他們搞定這問題，在許多同事的共同幫助下，終於把這個問題圓滿解決。這裡分享下全過程。

方法論：

模擬整體過程，分段解析，精確定位故障點。 此方法論適用於一切troubleshooting過程（就像在地板上找針，需要把地板劃分為一個一個小格子，找過的格子就標記下，這樣更容易找到針）

首先，需要對我們的請求過程做充分的瞭解，以登入介面為例，我們就有了以下的一個抽象的網路拓撲圖：

然後我們就開始分段排錯,因為整個過程是同步呼叫並且是對稱的，所以只考慮(1)->(11)，而不考慮(12)->(20)。

具體實踐：

步驟1 ，確定客戶端到應用伺服器的網路通訊質量。

從Python客戶端測試機器去ping 應用伺服器的外網地址，測試了1000次後，發現其pin還是挺穩定的，基本都在20毫秒之內，如下圖：

 

所以一下子就排除了拓撲圖中的 (1),(2),(3),(4),(5)這麼多段。

 

 

步驟2：確定其原因不是由我們程式設計師程式碼的內部業務邏輯所導致。

為此，我們讓開發人員在登入介面中遮蔽了一切和外部通訊的部分，也就是不呼叫技術部介面（註釋掉這段程式碼），只在Spring框架進入Service方法和服務完分別列印下伺服器的當前時間戳，然後相減獲得實際內部程式碼業務邏輯（比如請求分流，字串拼接，資料庫操作等），這時候再繪製耗時的曲線圖，如下：

從這裡看出，我們內部邏輯的總用時平均才77毫秒，雖然最多有420毫秒，但是對於300的樣本容量來說，這隻能算極個別的特例的噪音資料，所以我們程式碼業務邏輯耗時正常，這就排除了(6)和(9)

 

然後我們隔離掉自身業務邏輯，又重新做了一個介面，讓其只呼叫技術部的web service，這次發現其圖很有規律（規律我後面會說），此圖如下：

發現它最多還是會用時5秒，而且幾乎類似脈衝。

 

 

步驟3：確定需要深入剖析的可疑點。

這樣看來，可疑點有三段：

1. (7)和(8)。也就是應用伺服器(Tomcat)透過Http(https) Connector轉發請求到Spring容器，然後Spring容器透過Spring框架的DispatcherServlet轉發請求到相應的bean的業務方法。

2. (10)這段。也就是從Spring中的bean方法傳送請求mapi.XXX.com這個web service呼叫中間的網路。

3. (11)這段。也就是技術部介面本身呼叫服務的耗時。

 

當然，大家brainstorming之後還有一些假設。

1. JAVA平臺本身的效能問題。

2. 程式碼中Web Service連線使用後未關閉導致連線過多響應變慢。

3. 記憶體洩露導致伺服器效能急劇下降。

4. Full GC導致特定時間內伺服器效能奇差無比。

 

當然了，D這個可以忽略，因為JAVA作為一種平臺語言，其高效的效能已經被無數例子證明了，要有嚴重效能問題早被發現了，不會到現在剛好被我們運氣好才發現。

 

 

步驟4：排除技術部介面本身的問題（11這段）。

這方面感謝技術部專家的協助，他們送來了技術部介面本身內部呼叫的時間開銷原始資料，樣本容量在1400個左右，我們用程式碼分析並畫圖，可以看到以下曲線圖：

從曲線分佈可以看到，雖然有極個別的要13秒的（可以認為超時了），其他時間基本都控制在1-2秒左右。 因為他們最終介面也要呼叫新浪IP地址庫這些外部介面，所以個別的噪音資料也是能容忍的。所以這張圖說明技術部介面工作正常。

 

 

步驟5：排除Web Service連線未關閉的問題：

我特地去看了下程式碼，發現WebService連線併傳送GET請求後使用完被優雅的關閉了，如下：

 

而且如果是連線未關閉的話，應該是開始快，隨著測試次數變多越來越慢，而不是像步驟2的第二張圖那樣，第一次耗時那麼長（5秒）

 

 

步驟6：排除記憶體洩露導致的效能下降問題。

為此，我讓同事再次執行單獨呼叫技術部介面的web service 300次，在此期間透過5個時間點分別擷取heapdump來分析記憶體洩露。

Step 1： ps –ef  | grep java 獲取登入介面的程式ID

             Step2: cd $JAVA_HOME\bin

           jmap -dump:format=b,file=/tmp/heapdump.hprof      把執行的程式ID傳入，然後用jmap工具來獲得堆dump資訊。

然後利用Eclipse的MAT（Memory Analyze Tool）外掛來分析可能的leak point ,此外掛下載地址在，在擷取了5個巨大的heapdump檔案之後，我對比了這5個點（開始，中間1，中間2，中間3，結束）的記憶體狀況和可能的leak點，（主要關注物件的 retained Size, 它表示釋放該物件會額外釋放多少記憶體空間）

開始：

中間1：（2,3略了，幾乎相同）

 

結束：

 

而且幾個SuspensionPoint,經過物件引用樹的逐層深入排查，也和我們的程式碼無關，所以可以排除記憶體洩露的情況。

 

 

步驟7：排除GC導致的可能導致的延時。

為此，我在Tomcat啟動時候，加了如下的JAVA_OPTION: -XX:+PrintGCApplicationStoppedTime，這個選項的作用是列印垃圾回收期間程式暫停的時間。

正如我所料，執行一次Full GC大概需要41秒，這比才5秒的波峰延遲要高出太多。顯然不可能。

我把效能引數做了一些最佳化：

首先，因為Tomcat7 支援NIO，它效能比IO要高很多，所以我在Connector上配置了NIO

 

請求延遲依然沒本質改變，還是5秒左右波峰，不增也不減。

 

步驟8：排除應用伺服器(Tomcat)透過Http(https) Connector轉發請求到Spring容器，然後Spring容器透過Spring框架的DispatcherServlet轉發請求到相應的bean的業務方法（7和8這段）。

雖然列印出一個請求從應用伺服器中介軟體到Spring再到bean業務方法的時間請求很困難，但是可以做其他實驗。我們拿步驟3中實現的只包含這個內部處理邏輯的bean方法為例子。讓手機客戶端或者客戶端測試程式碼去請求這個bean 方法，獲得的時間曲線大概如下：

其平均用時在591毫秒，而且最長也不到2秒，減去步驟2 圖1的平均用時77毫秒，可以判斷，應用伺服器中介軟體和框架層面的處理平均用時在500毫秒左右。這顯然也排除了應用伺服器和框架層面。

 

 

步驟9：檢視應用伺服器和技術部介面的通訊。

因為其他部分都證明沒問題了，所以用反證法得知這段肯定有問題。為了證明，前天我讓同事寫了2個新的webservice方法，一個是直接透過域名呼叫技術部介面的，一個是透過外網IP技術部介面的。

方法1：publicstaticLoginUserInfoVo getUserInfoFromBLN(String loginName, String loginPassword)

方法2：publicstaticLoginUserInfoVo getUserInfoFromBLNByIP(String loginName, String loginPassword){

非常可惜，第二個方法（透過IP的方法）無法呼叫成功，原因也很容易理解，肯定技術部介面也是有地址對映的，所以某個請求URL肯定是IP和埠組合然後對映到的地址，所以單純靠IP替換無法傳送成功。

 

昨天深入分析的時候，我又從步驟2的第二張圖看出了一些規律：不僅此介面，幾乎所有其他連線技術部的介面都是第一次呼叫很慢，大概5秒多，接下來的呼叫速度會很快。精確的過36秒後，出現第二次波峰，依次類推。因為每次都是36秒間隔，這個更像是在哪裡配置的。但這個可以確定就是應用伺服器到技術部介面的通訊通道上。

 

最後我們找到了原因，原來在應用伺服器上配置的DNS是114.114.114.114,這是個公共DNS服務。它導致我們首次請求技術部介面時候要往外網繞一圈才回來。這就解釋了為什麼所有圖的第一次請求都要超過5秒。隨後，這個DNS解析結果快取在應用伺服器上，並且快取時間間隔在36秒左右。這就解釋為什麼接下來的36秒內每次請求速度都極快（在500毫秒以內），然後直到精確的36秒才出現第二個大於5秒的波峰。

 

步驟10：重做實驗驗證結論。

我們重更新了/etc/hosts檔案，因為其解析優先順序高於DNS解析，所以請求不再透過114.114.114.114從外網兜圈再回技術部介面。我們又把其他呼叫技術部介面的場景都做了測試。果然經過改動後，圖形再也不是一開始的脈衝了，而且很穩定，最長也就1.5秒，平均下來也就600毫秒的樣子，完全滿足我們要求，說明我們這個問題完美解決了。