現象描述

不管是性能測試中，還是生產環境中，經常會遇到響應時間過長的問題。
響應時間是性能評估的一個重要指標，會對最終用戶產生直接影響，一個產品是快是慢，響應時間是最直觀的感受。
因此面對響應時間長的問題，一定想盡辦法消滅它。
以下定位方法是針對比較典型的nginx+tomcat應用架構。

排查思路及方法說明

常見有兩種表現：偶現極少量的請求出現響應時間偏長，或者會有大量、批量的請求響應時間長。
對偶然出現的少量響應時間長的問題，可能是外部影響、網絡異常等造成。

偶然出現少量響應時間過長時，可以排查以下幾個方面來定位問題，

查看當時服務器日志是否有錯誤；

檢查服務器資源使用情況是否正常，load average、CPU使用率（尤其是單核CPU）是否有飆高現象；

檢查是否出現磁盤短暫負載較高，比如iostat util%飆高等；

確認當時網絡情況是否正常，是否有網絡丟包等現象。
以上排查建議在有全面監控的基礎上進行，偶現問題比較難定位，有全面的監控數據進行排查就方便多了。

案例1：單核CPU使用率高導致偶現響應時間長
某產品線上出現少量的響應時間長的問題，定位結果發現是兩個CPU密集型服務部署在同一臺機器上，
其中一個服務會使得單個CPU使用率100%，導致另一個服務出現少量請求響應慢。解決辦法是服務隔離。

如果出現比較多的響應時間過長，首先要排查所有服務器是否存在資源使用瓶頸，
如CPU使用率高、單核CPU使用率高、內存使用是否正常、是否有頻繁FullGC、磁盤IO壓力情況、網路時延情況等。
如果不能通過以上檢查發現問題所在，那就要逐步分析是系統架構中哪個環節導致的問題。

nginx排查

首先排查nginx access.log日志，分析響應時間可能慢在哪里。

log_format中定義了$request_time字段，它指的是從接受用戶請求數據到發送完回復數據的時間。
那究竟是慢在了nginx還是上游服務器？

log_format同時提供了$upstream_response_time字段，它是指從nginx向后端建立連接開始到接受完數據然后關閉連接為止的時間。
那就是說：

如果兩者相差很大，也即是$upstream_response_time數值比較小，則需要查看nginx模塊配置或nginx與客戶端的網絡是否有性能瓶頸了。

如果$reques{t}_{t}ime與$upstream_response_time相差不大，則可能是nginx連接上游服務器比較慢，或者上游服務比較慢，需要進入下一步應用層排查。

案例2：nginx日志排查出網絡問題

一線上產品出現某個操作響應時間30%以上都大于2s，通過分析access.log發現$reques{t}_{t}ime與$upstream_response_time相差不大，
進一步檢查nginx的配置，以及nginx服務器所在的交換機流量發現，nginx所在交換機流量基本快跑滿了，導致nginx返回數據較慢。

nginx層排查除了以上日志排查外，還需要關注nginx本身的配置，比如nginx worker_connections設置過小會導致響應時間長，tps上不去，具體可參考上一期《tps上不去》。

應用層排查

排除Nginx層的問題，那要著重定位應用層自身代碼、或者第三方調用、或者數據庫等其它依賴服務是否存在響應慢的情況。
首先確認是否存在以下問題：

確認應用服務是否有某些線程CPU使用率高，通過top -H可以方便實時查看

確認線程是否存在異常狀態，如頻繁blocked、死鎖等，推薦使用visualVM、Jconsole、jstack查看線程狀態，進行線程dump

連接數檢查，應用層連接數設置過小，會導致響應時間長，tps上不去，可以參考上一期《tps上不去》問題

如果有產品內部監控，如典型業務調用的處理時間、慢操作日志監控，那就比較方便了

如果很不幸，監控數據很少，且現有數據難以分析，那推薦兩個百試不爽的分析工具，Nprofile和Btrace。

Btrace在線調試神器

BTrace 是一款利用hotSpot虛擬機可以動態替換class的特點而完成的，可以對online的程序動態的改變類的行為, 進而進行線上調試的一個工具。
也就是說可以不需要重啟服務可以直接在線調試分析。關于Btrace的教程隨意搜索就能找到很多。

案例3：Btrace在線分析
生產環境出現某種請求有30%的比例響應時間比較長，需要定位具體是哪個接口或調用響應時間長。
1、首先要了解應用層的調用關系，我們對com.netease.XXX.usercenter.web.dwr.YYYBean進行跟蹤，完成Btrace腳本：

@BTrace
public class LessonLearnRecordServiceImpl {

@TLS static long beginTime;@OnMethod(clazz = "/com.netease.XXX.usercenter.web.dwr.YYYBean/", method = "/.+/") public static void traceExecuteBegin() {// 在方法btrace.test.MyBtraceTest.execute()執行之前進行監控。beginTime = timeMillis();// 監控行為是記錄一個開始時間。 }// OnMethod代表運行一個方法的時候進行監控，location @Location(Kind.RETURN)代表在方法返回的時候觸發監控行為。 @SuppressWarnings("deprecation") @OnMethod( clazz = "/com.netease.XXX.usercenter.web.dwr.YYYBean/", method = "/.+/", location = @Location(Kind.RETURN) ) public static void traceExcute() { // 監控行為是根據開始時間計算出方法運行時間。 print(strcat("entered ", name(probeClass()))); print(strcat(".", probeMethod())); println(strcat(" taken : ",strcat(str(timeMillis() - beginTime), "ms"))); }

}
2、獲取服務的進程PID，啟動Btrace agent：btrace
查看生成的日志如下：

entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 818ms
entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 619ms
entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 930ms
entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 613ms
entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 515ms
entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 716ms
觀察日志發現updateVideoTime方法大部分調用時間大于500ms，基本能判斷是該方法需要進行性能優化。

Nprofile分析調用熱點

Nprofile也即是AJprofile，是由何卓斌開發的一個自身開銷比較小，可以profile調用時間和調用熱點的小工具。
原理是在需要跟蹤的函數調用前后通過AOP調用一些計時的代碼，并進行一些簡單的統計處理。
使用說明參考:http://doc.hz.netease.com/pages/viewpage.action?pageId=25690763(內部資料)

案例4: 循環調用導致響應時間長
某web應用，一個Http get請求，性能測試最高tps240，平均響應時間接近1s，CPU使用偏高。不滿足性能測試通過條件。
對該接口進行profile：

可以發現一次getMyCourse，會有十幾次的getFirstLesson和getLastestLearnedLesson調用。
經過確認，確實存在無用的循環調用問題。解決后性能有30%以上的提升。

Nprofile堪稱利器，在性能問題分析和定位中非常有效，且比Jprofiler輕便，開銷小，對性能測試結果影響小。

數據庫層排查

通常web應用會有大量的數據庫操作，數據庫性能對web應用的性能表現至關重要。如果應用層的分析發現大量線程
等待數據庫的響應，就需要對數據庫層進行排查。最常見的數據庫性能問題有：

索引缺失或者索引建的不合理，sql語句不合理導致沒有走索引，進而導致SQL的執行時間長

SQL語句自身寫的有問題，導致執行時間比較長

鎖等待和鎖超時導致事務回滾以致于響應時間很長

數據庫的配置不合理，例如最大并發連接過小，bufferpool的設置過小等引起的性能問題

案例5：未創建索引導致響應時間長，CPU飆高
某接口tps只有150時，cpu使用率飚滿，且響應時間大于1s。通過Nprofile分析，

發現其中一個方法調用消耗了99%的CPU調用，該方法主要是進行數據庫讀操作，檢查數據庫發現未創建索引。
解決后tps上升一倍，響應時間下降到250ms左右。

數據層性能問題可以通過Mysql監控、或mysql-slow.log進一步詳細分析。

總結

以上是生活随笔為你收集整理的响应时间过长问题分析的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。