效能分析（3）- 短時程式導致使用者 CPU 使用率過高案例

小菠蘿測試筆記發表於2020-07-31

效能分析小案例系列，可以通過下面連結檢視哦

https://www.cnblogs.com/poloyy/category/1814570.html

 

系統架構背景

  • VM1：用作 Web 伺服器，來模擬效能問題
  • VM2：用作 Web 伺服器的客戶端，來給 Web 服務增加壓力請求
  • 使用兩臺虛擬機器（均是 Ubuntu 18.04）是為了相互隔離，避免交叉感染

 

VM2 執行 ab 命令，初步觀察 Nginx 效能

簡單介紹 ab 命令

  • ab（apache bench）是一個常用的 HTTP 服務效能測試工具
  • 可以向目標伺服器併發傳送請求

 

執行 ab 命令

併發 100 個請求測試 VM1 的 Nginx 效能，總共測試 1000 個請求

ab -c 100 -n 1000 http://172.20.72.58:10000/

從 ab 的輸出結果可以看到，Nginx 能承受的每秒平均請求數只有 145.68（有點差強人意）

 

那到底是哪裡出了問題呢

接下來，我們將通過一系列的命令來觀察哪裡出問題了

 

通過命令分析 VM1 的效能問題

VM2 長時間執行 ab 命令

併發 5 個請求，持續併發請求 10min

ab -c 5 -t 600 http://172.20.72.58:10000/

 

接下來的命令都在 VM1 上執行

 

top 檢視系統 CPU 使用率、程式 CPU 使用率、平均負載

top

結果分析

  • 平均負載已遠超 CPU數量（2）
  • Nginx、docker、php 相關的程式總的 CPU 使用率大概 40%左右
  • 但是系統 CPU 使用率（us+sy）已達到 96%了，空閒 CPU（id）只剩下 3.7%

 

提出疑問

為什麼程式所佔用的 CPU 使用率並不高，但是系統 CPU 使用率和平均負載會這麼高？ 

 

回答疑問，分析程式列表

  • containerd-shim：執行容器的，3.3% 的 CPU 使用率挺正常
  • Nginx 和 php-fpm：執行 Web 服務的，佔用的 CPU 使用率也才 5-6%  
  • 再往後就沒有什麼佔用 CPU 使用率的程式了

 

嘶，發現 top 並沒有滿足我們的需求，看來得祭出另一個命令了

 

pidstat 檢視是否有異常程式的 CPU 使用率過高

每秒取一次結果，共取 10 次

pidstat 1 10

結果分析

跟 top 命令的結果差不多，Nginx、dockerd、php-fpm 的 CPU 使用率偏高，但是加起來並沒有使用者態 CPU 使用率這麼高

 

問題來了

使用者 CPU 使用率已經達到 55%，但卻找不到時哪個程式有問題，這到底是咋肥事？難道是命令太辣雞了嗎？

 

答案

命令的存在肯定是有它的意義，問題肯定是出在我們自己身上，是否遺漏了什麼關鍵資訊？

 

再次執行 top 命令

 

結果分析

 

發現了一個關鍵點，就緒佇列有 6 個程式處於 R 狀態

 

6 個正常嗎？

  • 回想一下 ab 測試的引數，併發請求數是 5
  • 再看程式列表裡， php-fpm 的數量也是 6， 再加上 Nginx
  • 好像同時有 6 個程式也並不奇怪

 

仔細瞧一瞧

php-fpm、Nginx、docker 這麼多個程式只有 1 個 php-fpm 程式是 R 狀態的，其他都處於 S（Sleep）狀態，這就奇怪了

 

找到真正處於 R 狀態的程式

調整 top 列表排序規則

在 top 列表中，按 shift + f，進入 top 列表的顯示規則頁面

可以看到預設排序的列是 %CPU，這裡改成 S 列，就可以更快看到哪些程式的狀態是 R 了

 

來看看到底有哪些 R 狀態的程式呢

  • 真正處於 Running（R）狀態的，卻是幾個 stress 程式
  • 這幾個 stress 程式就比較奇怪了，需要做進一步的分析

 

觀察一段時間， stress 程式的變化

每次重新整理列表，stress 程式的數量都會變化，而且 PID（程式號）也會跟著變

 

更具體的動態檢視 stress 程式的變化

watch -d 'ps aux | grep stress | grep -v grep'

  • 其實可以看到 stress 程式有三種狀態：R、S、Z
  • 多個 stress 程式在不斷生成，由 R 變 S 再變 Z
  • 三種變化：程式PID、程式數量、程式狀態

 

程式 PID 在不斷變化的可能原因

原因一：程式在不停地崩潰重啟

比如因為段錯誤、配置錯誤等等，這時，程式在退出後可能又被監控系統自動重啟

 

原因二：這些程式都是短時程式

  • 就是在其他應用內部通過 exec 呼叫的外面命令
  • 這些命令一般都只執行很短的時間就會結束，很難用 top 這種間隔時間比較長的工具發現

 

stress 程式 PID 為什麼在不斷變化

首先，我並沒有手動執行 stress 命令，所以它很大可能是通過其他命令去執行的 

 

找到 stress 的父程式

pstress | grep stress

stress 是被 php-fpm 呼叫的子程式，並且程式數量不止一個（這裡是 2 個）

 

grep 查詢是否有程式碼在呼叫 stress 

grep stress -r app/

可以看到， index.php 檔案是包含了 stress 命令

 

index.php 原始碼

<?php
// fake I/O with stress (via write()/unlink()).
$result = exec("/usr/bin/stress -t 1 -d 1 2>&1", $output, $status);
if (isset($_GET["verbose"]) && $_GET["verbose"]==1 && $status != 0) {
  echo "Server internal error: ";
  print_r($output);
} else {
  echo "It works!";
}

?>r
  • 很明顯，就是 index.php 中呼叫了 stress 命令
  • 每個請求都會呼叫一個 stress 命令，模擬 I/O 壓力
  • stress 會通過 write()  、 unlink() 對 I/O 程式進行壓測

 

猜測

就是因為 stress 模擬 I/O 壓力導致的 CPU 使用率升高

 

靈魂拷問

如果是模擬 I/O 壓力，為什麼 pidstat 命令的時候 iowait% 並不高呢

看來得繼續深挖分析 

 

VM2 帶引數傳送請求

index.php 有一句原始碼值得注意

if (isset($_GET["verbose"]) && $_GET["verbose"]==1 && $status != 0)

當請求傳了 verbose 引數時...

 

VM2 帶 verbose 引數傳送請求

curl http://172.20.72.58:10000?verbose=1

  • 看到錯誤訊息 mkstemp failed: Permission denied ，以及 failed run completed in 0s
  • 原來 stress 命令並沒有成功，它因為許可權問題失敗退出了

 

結果分析猜測

正是由於許可權錯誤，大量的 stress 程式在啟動時初始化失敗，過多的程式上下文切換，進而導致 CPU 使用率的升高

 

關於程式上下文切換的猜測驗證

未壓測前的系統上下文切換次數

只有 200 左右

 

壓測後的系統上下文切換次數

直蹦 10000 左右了，上下文切換次數的確漲了很多

 

stress 程式的上下文切換次數

前面是猜測 stress 程式有問題，那就來看看 stress 程式的上下文切換次數

pidstat -w 2 | grep stress

  • 黃圈：自願上下文切換次數和非自願上下文切換次數並不高
  • 藍圈：程式PID 一直在變化

 

靈魂拷問

為什麼 stress 程式的上下文切換次數這麼低？

 

回答

  • 因為 stress 是短時程式
  • 會頻繁的產生新的 stress 程式
  • 系統需要從舊的 stress 程式切換到新的 stress 程式再執行，這樣切換次數就會增加

 

VM1 通過 perf 檢視效能分析報告

上一篇文章中也見到過這個 perf 命令

 

記錄效能事件

等待大約 15 秒後按 Ctrl+C 退出

perf record -g

 

檢視效能報告，結果分析

perf report

  • 佔了 CPU 時鐘事件的前幾名都是 stress 程式
  • 而且呼叫棧中比例最高的是隨機數生成函式 random() ，看來它的確就是 CPU 使用率升高的元凶了

 

擴充-swapper 程式是啥？

從上面報告其實可以看到排在前面的還有 swapper 程式，那麼它是啥呢？

  • swapper 跟 SWAP 沒有任何關係
  • 它只在系統初始化時建立 init 程式，之後，它就成了一個最低優先順序的空閒任務
  • 也就是說，當 CPU 上沒有其他任務執行時，就會執行 swapper
  • 所以，你可以稱它 為“空閒任務”

  • 當沒有其他任務時，可以看到 swapper 基本佔滿了 CPU 時鐘事件
  • 它的主要耗費都是 do_idle，也就是在執行空閒任務

 

優化問題

只要修復許可權問題，並減少或刪除 stress 的呼叫

 

總結

  • CPU 使用率升高的主要原因就是短時程式 stress 頻繁的進行程式上下文切換
  • 對於短時程式，我們需要通過 pstree 命令找到它的父程式，然後再分析父程式存在什麼問題

 

注意

當然，實際生產環境中的問題一般都要比這個案例複雜，在你找到觸發瓶頸的命令列後，卻可能發現，這個外部命令的呼叫過程是應用核心邏輯的一部分，並不能輕易減少或者刪除；這時，你就得繼續排查，為什麼被呼叫的命令，會導致 CPU 使用率升高或 I/O 升高等問 題

 

分析整體思路

  1. 短時間壓測，發現伺服器效能低下
  2. 長時間壓測，讓伺服器保持一個高負載的狀態，從而可以慢慢分析問題所在
  3. 通過 top 命令監控系統資源情況，發現使用者態的 CPU 使用率（us）較高，且空閒 CPU （id） 很低
  4. 但是找不到使用者態 的 CPU 使用率很高的程式，最高就 6%
  5. 進一步通過 pidstat 檢視是否有 CPU 使用率異常高的程式
  6. 發現 pidstat 行不通，再次通過 top 命令仔細觀察
  7. 發現 Running（R）狀態的程式有 6 個之多，但是 CPU 使用率較高的程式並沒有處於 R 狀態
  8. 切換 top 列表的排序規則，倒序，集中看 R 狀態的程式一段時間，發現是 stress 程式，而且時多時少，程式 PID 還會變化
  9. 通過 watch 實時觀察 stress 程式，發現 stress 程式會從從 R 狀態變到 S 再變到 Z，而且會不斷生成新的 stress 程式
  10. 猜測 stress 程式可能是短時程式，通過其他程式進行呼叫它
  11. 通過 pstree 找到 stress 程式的父程式，發現是 php-fpm 程式，接下來就是分析父程式了
  12. 通過 grep 查詢 stress 命令是否存在 Nginx 應用中，發現存在 index.php 檔案中
  13. 檢視原始碼，確認每次請求都會觸發 stress 命令
  14. stress 命令可以模擬 I/O 壓力的，通過 top 看到 iowait 其實並不算高
  15. 在 VM2 傳送帶請求引數，可以確認 stress 命令是執行失敗的
  16. 可以猜測大量的請求進來，導致大量的 stress 程式初始化執行失敗，從而增加程式上下文切換次數增加，最終導致 CPU 使用率升高
  17. 通過 vmstat 對比壓測前後的上下文切換次數，可以發現壓測的上下文切換次數的確增加了
  18. 通過 pidstat 檢視 stress 的上下文切換次數，但發現並不高，其實是因為 stress 是短時程式，上下文切換次數主要增加在舊程式切換到新程式的執行上
  19. 通過 perf record 錄製效能事件 30s
  20. 通過 perf report 檢視效能報告，可以看到佔用 CPU 時鐘事件的前幾名都是 stress 程式，然後排程比例最高的是 random 函式
  21. 確認問題根源就是 stress 程式呼叫了 random 函式

 

炒雞重點

  • 其實有時候 top、vmstat、pidstat 命令用完了可能還不一定能發現問題根源
  • 這個時候就要更加細心的檢視這些命令返回結果其中的貓膩，雖然可能找不到問題根源，但可能會發現某些線索
  • perf 雖然強大，但並不是一開始分析就適合用它的

 

相關文章