當 etcd 伺服器 CPU 飆高時,最快的定位方法就是直接剖析執行中的程序,並解讀它的 Go 級別 CPU 火焰圖。本教程中,OpenResty XRay 會分析一個佔用了超過 70% CPU 核心資源的未經修改的 etcd 二進位制程式——無需改動任何程式碼,也無需重啟——並精準定位最熱的 Go 程式碼路徑:gRPC 請求處理(processUnaryRPC)、鍵值儲存的 range 和 put 處理函式,以及 Go 執行時的棧增長(runtime.newstack)。

本教程演示使用 OpenResty XRay 分析 Go 的 etcd 伺服器內部是如何耗費 CPU 時間的。我將展示其中最耗 CPU 的 Go 程式碼路徑。OpenResty XRay 會自動分析 Go(golang)語言級別的 CPU 火焰圖。

問題症狀:etcd 佔用超過 70% 的 CPU 核心

執行 top 命令可以看到,etcd 程序佔用了超過 70% 的 CPU 核心資源(這裡是 74.3%):

top 命令顯示 etcd 程序佔用了 74.3% 的 CPU 核心

ps 命令確認這是一個標準的 etcd 二進位制程式(/usr/local/bin/etcd),以普通的叢集引數啟動——沒有自定義構建、沒有任何剖析插樁,也沒有任何形式的改動:

ps 命令顯示未經修改的 /usr/local/bin/etcd 二進位制程式及其命令列

使用引導式分析定位 etcd 最熱的 Go 程式碼路徑

藉助 OpenResty XRay,我們可以實時分析這個未經修改的執行中程序。“Guided Analysis”(引導式分析)嚮導會依次引導我們選擇診斷型別、分析目標和應用型別。我們選擇 High CPU usage(高 CPU 使用率)作為要診斷的問題:

OpenResty XRay 引導式分析的問題型別選單,其中包含 High CPU usage 選項

接著,我們選擇執行中的 etcd 程序作為分析目標。OpenResty XRay 將其識別為一個 Go 應用(PID 3638889,約 76% CPU),我們保持預設的 Go 語言級別和預設的 300 秒最大執行時間,然後開始分析:

在 OpenResty XRay 中選擇執行中的 etcd Go 程序作為分析目標

經過幾輪取樣後,OpenResty XRay 生成了一份報告。它按 CPU 時間對最熱的 Go 程式碼路徑進行排名,同時列出 read 和 write 系統呼叫各消耗了多少 CPU:

OpenResty XRay 的 CPU 報告,按 CPU 時間對 etcd 最熱的 Go 程式碼路徑排名,processUnaryRPC 以 17.6% 居首

這個是佔用 CPU 時間最多的 Go 級別程式碼路徑,佔了 17.6% 的 CPU 時間:

報告中排名第一的最熱 Go 程式碼路徑,佔 17.6% 的 CPU 時間

這個 processUnaryRPC 是 Go 的 gRPC 庫中的一個函式。它負責處理最簡單的 gRPC 訊息——單個請求對應單個響應:

程式碼路徑中高亮顯示的 processUnaryRPC 函式,來自 Go 的 gRPC 庫

它的上級呼叫函式是 handleStream

程式碼路徑顯示 handleStream 是 processUnaryRPC 的上級呼叫函式

點選 “More” 檢視細節資訊:

點選 More 按鈕檢視這條程式碼路徑的細節資訊

解讀 Go CPU 火焰圖

上面的程式碼路徑就是從這個 Go 級別 CPU 火焰圖中自動推匯出來的。在火焰圖中,每個棧幀的寬度與它所佔的 CPU 時間成正比:

OpenResty XRay 為執行中的 etcd 程序取樣得到的 Go 級別 CPU 時間火焰圖

點選這個圖示放大火焰圖:

點選放大圖示放大 Go CPU 火焰圖

繼續放大:

繼續放大火焰圖中最熱的呼叫棧

_KV_Range_Handler 函式可以獲取鍵值資料庫中一定範圍內的 key:

火焰圖放大到 processUnaryRPC 之下的 etcd _KV_Range_Handler 函式

_KV_Put_Handler 函式將給定的 key 放入鍵值資料庫中:

火焰圖中的 etcd _KV_Put_Handler 函式,負責將 key 寫入鍵值儲存

Range 函式用於按範圍查詢儲存在 etcd 中的鍵值資料:

火焰圖中 etcd 的 Range 函式,用於按範圍查詢鍵值資料

它會呼叫 runtime.newobject 建立大量的 golang GC 物件:

火焰圖顯示 Range 查詢之下的 runtime.newobject 分配大量 Go GC 物件

runtime.newstack 函式在 etcd 寫入資料時有較高的 CPU 開銷。該函式是 Go 語言執行時的一個內部函式,它為新的 goroutine 建立一個新的執行時棧:

火焰圖顯示 etcd 寫入路徑上的 runtime.newstack 棧建立開銷

下面是對當前問題更詳細的解釋和建議,例如減少網路上傳輸的資料、使用連線池以及調優 gRPC 配置:

OpenResty XRay 對 processUnaryRPC 程式碼路徑的解釋以及最佳化建議

它提到了函式 processUnaryRPC

解釋文字中提到的 processUnaryRPC 函式

也提到了它是處理一元 RPC 的:

解釋文字說明 processUnaryRPC 負責處理一元 RPC

跳轉到原始碼行

讓我們回到剛才的程式碼路徑上來。把滑鼠放在第一個函式的綠色框上:

滑鼠懸停在程式碼路徑第一個函式的綠色框上

可以看到這個函式的原始檔名。在提示框中還可以看到 server.go 檔案的完整路徑:

提示框顯示 processUnaryRPC 的原始檔 grpc server.go 的完整路徑

這行原始碼的行號是 1024:

提示框顯示該行原始碼的行號是 1024

點選這個圖示,複製這個函式完整的 Go 原始檔路徑:

點選複製圖示複製完整的 Go 原始檔路徑

使用 find 命令來查詢原始檔:

在終端中使用 find 命令查詢 Go 原始檔

貼上我們剛剛複製的檔案路徑:

在 find 命令中貼上剛剛複製的原始檔路徑

複製完整的檔案路徑。使用 vim 編輯器,檢視這個檔案裡的 golang 程式碼。您可以使用任何您喜歡的編輯器:

使用 vim 編輯器開啟 grpc server.go 原始檔

正如 OpenResty XRay 建議的那樣跳轉到第 1024 行:

vim 中跳轉到 grpc server.go 的第 1024 行

函式 md.Handler 會根據 gRPC 訊息的不同型別,選擇合適的訊息處理程式來呼叫。我們之前看到的 _KV_Range_Handler_KV_Put_Handler 就是 md.Handler 回撥函式的兩個例項:

原始碼第 1024 行的 md.Handler 呼叫,分發到各個 gRPC 訊息處理函式

在狀態列中可以看到這行程式碼也確實在 processUnaryRPC 函式中,正如之前報告中提到的:

vim 狀態列確認第 1024 行程式碼位於 processUnaryRPC 函式中

其他熱點程式碼路徑

CPU 佔用第二熱的 Go 程式碼路徑,使用了大約 12% 的 CPU 資源:

報告中排名第二的最熱 Go 程式碼路徑,佔約 12% 的 CPU 時間

這個函式的作用是把資料寫入到網路 socket 裡:

程式碼路徑顯示把響應資料寫入網路 socket 的函式

這裡執行的是 write 這個系統呼叫:

程式碼路徑底部執行的 write 系統呼叫

這個函式透過 HTTP/2 協議將響應資料傳送到網路 socket:

程式碼路徑中透過 HTTP/2 協議傳送響應資料的函式

排名第三的最熱 Go 程式碼路徑佔用了大約 11% 的 CPU 時間:

報告中排名第三的最熱 Go 程式碼路徑,佔約 11% 的 CPU 時間

這裡的 runtime.mcall 函式主要負責排程執行 goroutine:

程式碼路徑中負責排程 goroutine 的 runtime.mcall 函式

這是 CPU 佔用第四熱的 Go 程式碼路徑,佔了約 10.5% 的 CPU 時間:

報告中排名第四的最熱 Go 程式碼路徑,佔約 10.5% 的 CPU 時間

這個函式的功能是記錄每一次一元 gRPC 請求的呼叫。為了節約 CPU 資源,我們可以選擇不做這樣的日誌記錄:

程式碼路徑中記錄每次一元 gRPC 呼叫日誌的函式

etcd CPU 全自動監控與報告

除了按需執行的引導式分析,OpenResty XRay 還能自動監控線上程序,並在 “Insights” 頁面生成以日和周為週期的報告。對於這個 etcd 例項,日報顯示 CPU 使用率平均為 51.33%(峰值達 164%),其中 write 系統呼叫和 Go GC 物件分配位列 CPU 消耗最多的專案之中:

OpenResty XRay 的 Insights 日報,展示 etcd 的平均和峰值 CPU 使用率以及消耗 CPU 最多的專案

由於這些報告是自動生成的,您並不需要親自去執行引導式分析——引導式分析在應用開發和演示場景下最為有用。

常見問題

為甚麼我的 etcd 伺服器佔用這麼多 CPU?

在本例中,etcd 的大部分 CPU 時間都花在了處理 gRPC 請求上。最熱的單條 Go 程式碼路徑是 Go gRPC 庫中的 processUnaryRPC(佔 17.6% 的 CPU 時間),它會分發到 etcd 的 _KV_Range_Handler_KV_Put_Handler——分別負責從鍵值儲存中讀取某一範圍的 key 以及向其中寫入 key。透過 HTTP/2 傳送響應資料,以及 Go 執行時的工作(runtime.newobjectruntime.newstack 以及經由 runtime.mcall 的 goroutine 排程)佔據了其餘的大部分。同樣的方法適用於任何 CPU 使用率偏高的 Go 程式;參見如何定位最熱的 Go 程式碼路徑

如何在不修改、不重啟 etcd 的情況下剖析它的 CPU 使用情況?

OpenResty XRay 直接分析執行中的、未經修改的 etcd 程序——無需改動程式碼、無需重新構建、也無需重啟。它的 “Guided Analysis”(引導式分析)功能會對執行中的程序進行取樣,並自動推匯出 Go 級別的 CPU 火焰圖和最熱的程式碼路徑。

etcd 在高 CPU 下最熱的程式碼路徑有哪些?

對於本次負載,最熱的幾條路徑是:(1) processUnaryRPC 處理一元 gRPC 呼叫,進而進入 KV 的 range 和 put 處理函式(17.6%);(2) 透過 HTTP/2 將響應資料寫入網路 socket(11.7%);(3) runtime.mcall 排程 goroutine(11.1%);(4) 記錄每一次一元 gRPC 呼叫的日誌(10.5%)——為節約 CPU 時間,您可以考慮跳過這類日誌。

關於 OpenResty XRay

OpenResty XRay 是一個動態追蹤產品,它可以自動分析執行中的應用程式,以解決效能問題、行為問題和安全漏洞,並提供可行的建議。在底層實現上,OpenResty XRay 由我們的 Y 語言驅動,可以在不同環境下支援多種不同的執行時,如 Stap+、eBPF+、GDB 和 ODB。

關於作者

章亦春是開源 OpenResty® 專案創始人兼 OpenResty Inc. 公司 CEO 和創始人。

章亦春(Github ID: agentzh),生於中國江蘇,現定居美國灣區。他是中國早期開源技術和文化的倡導者和領軍人物,曾供職於多家國際知名的高科技企業,如 Cloudflare、雅虎、阿里巴巴, 是 “邊緣計算“、”動態追蹤 “和 “機器程式設計 “的先驅,擁有超過 22 年的程式設計及 16 年的開源經驗。作為擁有超過 4000 萬全球域名使用者的開源專案的領導者。他基於其 OpenResty® 開源專案打造的高科技企業 OpenResty Inc. 位於美國矽谷中心。其主打的兩個產品 OpenResty XRay(利用動態追蹤技術的非侵入式的故障剖析和排除工具)和 OpenResty Edge(最適合微服務和分散式流量的全能型閘道器軟體),廣受全球眾多上市及大型企業青睞。在 OpenResty 以外,章亦春為多個開源專案貢獻了累計超過百萬行程式碼,其中包括,Linux 核心、Nginx、LuaJITGDBSystemTapLLVM、Perl 等,並編寫過 60 多個開源軟體庫。

關注我們

如果您喜歡本文,歡迎關注我們 OpenResty Inc. 公司的部落格網站 。也歡迎掃碼關注我們的微信公眾號:

我們的微信公眾號

翻譯

我們提供了英文版原文和中譯版(本文)。我們也歡迎讀者提供其他語言的翻譯版本,只要是全文翻譯不帶省略,我們都將會考慮採用,非常感謝!