現(xiàn)象描述

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

排查思路及方法說明

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

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

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

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

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

確認當時網(wǎng)絡情況是否正常，是否有網(wǎng)絡丟包等現(xiàn)象。
以上排查建議在有全面監(jiān)控的基礎上進行，偶現(xiàn)問題比較難定位，有全面的監(jiān)控數(shù)據(jù)進行排查就方便多了。

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

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

nginx排查

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

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

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

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

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

案例2：nginx日志排查出網(wǎng)絡問題

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

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

應用層排查

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

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

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

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

如果有產(chǎn)品內部監(jiān)控，如典型業(yè)務調用的處理時間、慢操作日志監(jiān)控，那就比較方便了

如果很不幸，監(jiān)控數(shù)據(jù)很少，且現(xiàn)有數(shù)據(jù)難以分析，那推薦兩個百試不爽的分析工具，Nprofile和Btrace。

Btrace在線調試神器

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

案例3：Btrace在線分析
生產(chǎn)環(huán)境出現(xiàn)某種請求有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()執(zhí)行之前進行監(jiān)控。beginTime = timeMillis();// 監(jiān)控行為是記錄一個開始時間。 }// OnMethod代表運行一個方法的時候進行監(jiān)控，location @Location(Kind.RETURN)代表在方法返回的時候觸發(fā)監(jiān)控行為。 @SuppressWarnings("deprecation") @OnMethod( clazz = "/com.netease.XXX.usercenter.web.dwr.YYYBean/", method = "/.+/", location = @Location(Kind.RETURN) ) public static void traceExcute() { // 監(jiān)控行為是根據(jù)開始時間計算出方法運行時間。 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
觀察日志發(fā)現(xiàn)updateVideoTime方法大部分調用時間大于500ms，基本能判斷是該方法需要進行性能優(yōu)化。

Nprofile分析調用熱點

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

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

可以發(fā)現(xiàn)一次getMyCourse，會有十幾次的getFirstLesson和getLastestLearnedLesson調用。
經(jīng)過確認，確實存在無用的循環(huán)調用問題。解決后性能有30%以上的提升。

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

數(shù)據(jù)庫層排查

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

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

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

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

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

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

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

數(shù)據(jù)層性能問題可以通過Mysql監(jiān)控、或mysql-slow.log進一步詳細分析。

總結

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

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