一、效能分析的完整思路

效能分析一直是效能實施專案中的一個難點。對於只做效能測試不做效能分析的團隊來說，總是不能把問題非常顯性地展示出來，不能給其他團隊非常明確的引導。對於這種型別的測試實施，只能把問題丟擲來，讓其他相關團隊去查。溝通成本很高。

而一個成熟的效能團隊應該是要把問題點分析出來，給其他團隊或責任人非常明確的瓶頸點，以加快問題的處理進度。

從完整的分析思路上考慮。有兩個要點：分段和分層。

如上圖所示，分段就是要把1-6以及在server1/2、DB上消耗的時間都統計出來。分層就是要把上圖中各種不同顏色的層都分析到。

可以使用的方法在不同的專案中各不一樣，取決於應用的架構。

二、效能分析的深度

效能分析的深度要到什麼程度為宜呢？主要是看組織的結構和專案中涉及到的人的職責定義。要把握的深度就是讓各團隊沒有技術上的gap。這一點非常重要。

從實際的操作層面來說，因為效能主要是在大壓力下是否能保持住時間的可接受性。所以主要把握如下幾點：

1. 從響應時間到具體的程式碼；

2. 從響應時間到具體的sql；

3. 從響應時間到具體的配置

有了這幾個層面的分析，基本上就可以確定一個問題的瓶頸點了。

三、效能分析中的資料理解

在資料理解上，有兩個階段：

知道計數器的含義

這個階段看似簡單，但能記得住那麼多performance counter的人並不多，這個記不住倒是沒有太大關係，遇到就查，多遇幾次自然就記住了；

比如，對於上圖來說，要理解的計數器就是await和svctm，await高是肯定存在問題。如果要判斷問題是嚴重不嚴重還要看另一個計數器就是avgqu-sz，它是佇列長度。svctm是平均每次io的時間（單位：ms）。

再來看看cpu的計數器。

cpu的計數器在top中有8個，在mpstat中多兩個。在上面的計數器中，通常的說法是，us cpu是使用者態的，如果這部分高，通常是應用程式碼消耗的；sy cpu是系統態的，如果這部分高，通常是os層的配置有問題。這種說法在大部分情況下是合理的，但是不管是us cpu還是sy cpu，高和低都只是問題的表現。分析到此並不是效能分析的結束，下面要找到的就是為什麼這麼高？這一步是非常關鍵的。一般情況下，分析路徑是： 

所以下一步就很清晰了，就是找哪個程序、執行緒消耗的cpu高，進而查到程式碼。

知道計數器的值之間的關係

這個階段大部分人都需要好幾年的時間才能完全掌握常規的計數值，之所以說只能掌握常規的計數值是因為有一些數值的聯動關係不是那麼容易碰得到。比如說CPU模式對TPS和RT的影響，大部分人都是拿到硬體的時候都是Full performance mode了，並不關心還有沒有其他的模式；比如說網路計數值導致的TPS有規律或無規律的抖動。這些場景都要求做效能分析的在看到某個計數值的時候能有直接的反應，但是這一點非常難。因為數值的高低對大部分人來說就是一個謎，經常有人問這樣的問題，這個值是高還是低，應該說只要不是一起工作的人都說不上來某個值是高還是低（當然對一些非常清晰的場景是比較容易判斷的），合理還是不合理。

如上圖所示：procs 的b列很高，這個值的含義是等io的程序數，它在上圖中和cpu wa列是對應的。同時，也和io的bi、bo列是對應的，從這幾個值關聯來看下步是要看哪個程序消耗的IO多了。

能經過資料理解的這一層次，才算是到了中級效能分析工程師的能力。

四、效能分析中的曲線理解

壓力工具的曲線

做效能分析，看曲線是最直接了當的。壓力工具可以給我們的明確的資訊就是這個系統是不是有問題的，這也是壓力工具自身曲線可以明確顯示的唯一的資訊。請看下面幾張圖：

TPS圖：

響應時間圖：

執行緒遞增圖：

怎麼理解這幾張圖呢，先看張執行緒圖。可以知道多個業務都有設定併發遞增執行緒。這個圖能給的資訊就是這個且只有這個。

結合TPS圖可以知道，在第三個梯度的時候，TPS到了峰值。在第四個梯度的時候，TPS已經開始下降了。

再結合響應時間圖，在第三個梯度的時候，響應時間是明顯地擡了頭。後面響應時間在持續增加，每個梯度都有增加。

這時候有兩個動作可做：

1. 修改場景接著測試。如何修改場景？把執行緒數降低。降到在梯度增加的過程中，響應時間沒有明顯增加的趨勢之後再來看TPS是什麼趨勢。對於一個系統來說，響應時間有增加、TPS沒有增加（或有下降）、執行緒數有增加，這幾個判斷就明確說明了系統是有瓶頸的，並且也僅能說明這一點。

2. 在當前場景下，分析瓶頸點，看時間消耗在哪個環節上。

   這兩個動作取決於目標，如果TPS在第三個梯度上已經達到了業務指標，那可以不做優化。所以第一個動作的前提是TPS目標已達到。

顯然，第二個動作就是TPS目標還未達到。

當然有人提出TPS目標達到了，有瓶頸也是需要優化呀？在這一點上，就要看做決定的人怎麼考慮了，因為優化是要付出成本的。

再說另一種曲線。

系統監控曲線

由於作業系統級的監控有非常多的監控曲線，這裡拿一個記憶體的來舉例子。

記憶體曲線圖：

對linux作業系統來說，作業系統的記憶體會慢慢被分配掉，變成caching memory。所以如果只看available memory的意義並不大，需要-/+ buffer/cache之後再看可用記憶體。這一點大家都清楚。

那麼上面是不是說記憶體沒有問題呢？當然不是。因為記憶體不僅被用光了，而且還斷了一段，後面又有了資料，接著又用光，又斷了一段時間。紅色的框中，是有問題的，因為這一段連資料都沒有抓到，抓資料的程序應該是沒了。

所以available memory的下降並不是要關注的重點，-/+ buffer/cache之後的available memory才是要關注的重點。另外從上圖中看到的斷掉的時間點也是要分析的重點。

另外，上圖中，藍框內記憶體一直在很低的狀態，後面卻突然升高了那麼多。這裡也是要分析的重點。

JVM圖

對JVM曲線來說，也是要看趨勢的，基礎知識是jvm gc的邏輯。YGC一直在做，heap一直在增加，這個過程是不是正常的呢？對於沒有做過Full GC的JVM來說，heap是有增加的趨勢是可以理解的，但是這個“理解”需要一個前提，就是業務有沒有增量。如果是有業務的增量，上圖就是正常的；如果沒有業務增量，上圖就是不正常的，那什麼樣的才是沒有業務增量的正常呢？看下圖：

上圖就明顯是個非常正常的jvm。

對於曲線的理解，首先要知道的是資料的來源和含義。在效能分析中，有很多曲線的趨勢都不是可以直接指明問題的，只能通過收集全部的資訊來做完整的分析才能判斷問題存在點。 上面舉了兩個例子的角度分別是：壓力工具生成的曲線和後端伺服器相應的工具生成的曲線。就是為了說明一點：曲線分析是在關注所有的層面。

五、例項一：堆外記憶體溢位導致穩定性場景失敗

連續三天，晚上在執行一個業務場景持續幾個小時之後，就開始連續報錯。伺服器連不上了。但在報錯的一開始，並不是全部都報錯，而是有部分是可以成功的，但是過一段時間之後，所有業務都報錯了。

次日來看，發現程序不見了。本來以為是程序崩潰退出了，那日誌中應該留下來些證據。但是打開了日誌查看了一下，沒有任何異常資訊。連續三天都出現。登入zabbix上去看了一下主機資源。

紅框內的是出現問題的時間段。看到這裡似乎明白了為什麼並不是所有業務都失敗。因為記憶體還有上升的這個階段。但是為什麼降到底之後又上去，再次降到底呢？先看一下拓撲圖。

兩個主機，四個程序，既然程序都沒了，應該不是一塊沒的，要不然不會還有業務可以成功翻了一下應用日誌，確實沒有什麼和程序消失相關的錯誤資訊。

既然是程序沒了，日誌也沒資訊，那下一步是什麼呢？就是看dmesg了。系統日誌總有些資訊吧。程序死了無非就那麼幾個地方能看到。

• 應用日誌

• 系統日誌。

在這裡提醒一下，最好直接執行dmesg命令，而不是去看/var/log/dmesg檔案。因為命令中會把其他message也放進去，會全一點。

查看了dmesg之後，發現如下資訊：

從時間上來算一下。系統執行時間41.45天，確實和第一個圖上的21：30的時間對應得上。從這裡來看是6341程序被殺了。

再看第二個圖：

再來算一下時間。41.55天，和第一個圖上的11：45能對得上。

看來是OOM Killer主動把這兩個程序給殺了。從下面的資訊來看是這兩個程序消耗linux主機的實體記憶體和虛擬記憶體太大，以致於把記憶體都給消耗光了，最後OOM Killer就站出來主持公道了：小子挺橫呀，老子分給你了一畝三分地，不好好呆著，敢來搶地盤，幹它！於是就真的被kill了。

既然知道了記憶體消耗得多，那這個場景就好復現了。接著用原場景測試。看下java程序的記憶體，java的記憶體分成堆內堆外。 因為是作業系統的OOM Killer幹掉的，所以基本上可以排除堆內的記憶體導致的。因為堆是有限制的嘛。

既然這樣，那就是堆外。

打個threaddump看看。

怎麼這麼多執行緒？並且也看到了開發的包名。

把這個路徑給了開發之後，讓他們翻翻這一段的原始碼，看到類似如下內容：

Thread thread = new Thread();（當然還有呼叫的程式碼，就不一一羅列了）

開發這才知道是為啥有這麼多新建立的執行緒。

於是拿回去改去了。

六、例項二：防火牆配置導致鋸齒TPS

使用者遞增圖：

TPS圖：

通過檢視網路連線狀態，看到有大量的TIME_WAIT出現。

tcp 0 0 ::ffff:192.168.1.12:59103 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59085 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59331 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:46381 ::ffff:192.168.1.104:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59034 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59383 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59138 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59407 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp b 0 0 ::ffff:192.168.1.12:59288 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:58905 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:58867 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:58891 ::ffff:192.168.1.11:3306 TIMEWAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59334 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0)

嘗試過程。

為TIME_WAIT修改TCP引數

通過檢查sysctl.conf，看到所有的配置均為預設，於是嘗試如下修改：

net.ipv4.tcp_tw_recycle = 1
net.ipv4.tcp_tw_reuse = 1
net.ipv4.tcp_fin_timeout = 3
net.ipv4.tcp_keepalive_time = 3

迴歸測試，問題依舊。

修改nginx的proxyignoreclient_abort

考慮到當客戶端主動斷開時，伺服器上也會出現大量的TIME_WAIT，所以開啟 proxy_ignore_client_abort，讓nginx忽略客戶端主動中斷時出現的錯誤。 proxy_ignore_client_abort on;

修改後，重啟nginx，問題依舊。

修改tomcat引數

檢視tomcat的server.xml時，看到只設置了maxthreads。考慮到執行緒的分配和釋放也會消耗資源。所以在這裡加入如下引數：

maxKeepAliveRequests="256" minSpareThreads="100" maxSpareThreads="200"

重啟tomcat，問題依舊。

換nginx伺服器

在分段測試的時候，看到通過nginx就會出現TPS上到300就會下降的情況，所以考慮是nginx機器的配置問題，於是換了在另一臺機器上重新編譯了nginx，所有的作業系統都是一樣的配置。

通過新的nginx做壓力，問題依舊，所以可以判斷這個問題是和作業系統的配置有關，和nginx本身的配置無關。

停掉防火牆

和網路連線有關的內容，剩下的就只有防火牆了。於是執行了：

Service iptables stop

在執行了之後，看到TPS立即就上去了。並且可以增加得非常高。

從而定位，TPS的下降和防火牆有關。

系統日誌

進到/var/log，檢視messages，看到大量的如下資訊：

Nov 4 11:35:48 localhost kernel: _ratelimit: 108 callbacks suppressed Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet. Nov 4 11:35:53 localhost kernel: _ratelimit: 592 callbacks suppressed Nov 4 11:35:53 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:53 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: _ratelimit: 281 callbacks suppressed Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nfconntrack: table full, dropping packet. Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet. Nov 4 11:36:14 localhost kernel: __ratelimit: 7 callbacks suppressed

引數修改

因為出現大量的nf_conntrack: table full, dropping packet.所以在sysctl.conf中加入瞭如下引數設定。

    net.netfilter.nf_conntrack_max = 655350
    net.netfilter.nf_conntrack_tcp_timeout_established = 1200

修改引數後，執行：

Service iptables start

可以看到，TPS仍然可以很高，從而解決問題。

解決問題後的TPS圖

上圖中有兩次TPS下降的過程是因為又嘗試了修改防火牆的引數配置，重啟了兩次防火牆。

從TPS曲線上看，又恢復到了正常的水平。

七、綜述

綜上，對於效能分析來說，不僅是現象的解釋，還有瓶頸的定位及問題的解決。這些工作所要求的基礎知識較多，一個人力不能及的時候，就需要一個團隊來做。關鍵是要把問題分析得清晰透徹。