golang pprof 監控系列(5) —— cpu 佔用率 統計原理
大家好，我是藍胖子。
經過前面的幾節對pprof的介紹，對pprof統計的原理算是掌握了七八十了，我們對memory,block,mutex,trace,goroutine,threadcreate這些維度的統計原理都進行了分析，但唯獨還沒有分析pprof 工具是如何統計cpu使用情況的，今天我們來分析下這部分。
http 介面暴露的方式
還記得 golang pprof監控系列（2） —— memory，block，mutex 使用 裡我們啟動了一個http服務來暴露各種效能指標資訊。讓我們再回到當時啟動http服務看到的網頁圖。
當點選上圖中profile連結時，便會下載一個關於cpu指標資訊的二進位制檔案。這個二進位制檔案同樣可以用go tool pprof 工具去分析，同樣，關於go tool pprof的使用不是本文的重點，網上的資料也相當多，所以我略去了這部分。
緊接著，我們來快速看下如何用程式程式碼的方式生成cpu的profile檔案。
程式程式碼生成profile
os.Remove("cpu.out")
f, _ := os.Create("cpu.out")
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
// .... do other things
程式碼比較簡單，pprof.StartCPUProfile 則開始統計 cpu使用情況，pprof.StopCPUProfile則停止統計cpu使用情況，將程式使用cpu的情況寫入cpu.out檔案。cpu.out檔案我們則可以用go tool pprof去分析了。
好的，在快速的看完如何在程式中暴露cpu效能指標後，我們來看看golang是如何統計各個函式cpu使用情況的。接下來，正戲開始。
cpu 統計原理分析
首先要明白，我們究竟要統計的是什麼內容？我們需要知道cpu的使用情況，換言之就是cpu的工作時間花在了哪些函式上，最後是不是就是看函式在cpu上的工作時長。
那麼函式的在cpu上工作時長應該如何去進行統計？
golang還是採用部分取樣的方式，透過settimmer 系統呼叫設定了 傳送SIGPROF 的定時器，當達到runtime.SetCPUProfileRate設定的週期間隔時，作業系統就會向程式傳送SIGPROF 訊號，預設情況下是100Mz(10毫秒)。
一旦設定了 傳送SIGPROF訊號的定時器，作業系統便會定期向程式傳送SIGPROF訊號。
設定定時器的程式碼便是在我們呼叫pprof.StartCPUProfile方法開啟cpu資訊取樣的時候。程式碼如下，
// src/runtime/pprof/pprof.go:760
func StartCPUProfile(w io.Writer) error {
const hz = 100
cpu.Lock()
defer cpu.Unlock()
if cpu.done == nil {
cpu.done = make(chan bool)
}
// Double-check.
if cpu.profiling {
return fmt.Errorf("cpu profiling already in use")
}
cpu.profiling = true
runtime.SetCPUProfileRate(hz)
go profileWriter(w)
return nil
}
在倒數第三行的時候呼叫了設定取樣的週期，並且緊接著profileWriter 就是用一個協程啟動後去不斷的讀取cpu的取樣資料寫到檔案裡。而呼叫settimer的地方就是在runtime.SetCPUProfileRate裡，runtime.SetCPUProfileRate最終會呼叫 setcpuprofilerate方法 ，setcpuprofilerate 又會去呼叫setProcessCPUProfiler方法設定settimer 定時器。
// src/runtime/signal_unix.go:269
func setProcessCPUProfiler(hz int32) {
.....
var it itimerval
it.it_interval.tv_sec = 0
it.it_interval.set_usec(1000000 / hz)
it.it_value = it.it_interval
setitimer(_ITIMER_PROF, &it, nil)
....
經過上述步驟後，cpu的取樣就真正開始了，之後就是定時器被觸傳送SIGPROF訊號，程式接收到這個訊號後，會對當前函式的呼叫堆疊進行記錄，由於預設的取樣週期設定的是100Mz，所以，你可以理解為每10ms，golang就會統計下當前正在執行的是哪個函式，在取樣的這段時間內，哪個函式被統計的次數越多，是不是就能說明這個函式在這段時間內佔用cpu的工作時長就越多了。
由於golang藉助了linux的訊號機制去進行cpu執行函式的取樣，這裡有必要額外介紹下linux 程式與訊號相關的知識。首先來看下執行緒處理訊號的時機在什麼時候。
執行緒處理訊號的時機
執行緒對訊號的處理時機一般 是在由核心態返回到使用者態之前，也就是說，當執行緒由於系統呼叫或者中斷進入核心態後， 當系統呼叫結束或者中斷處理完成後，在返回到使用者態之前，作業系統會檢查這個執行緒是不是有未處理的訊號，如果有的話，那麼會先切回到使用者態讓 執行緒會首先處理訊號，訊號處理完畢後 又返回核心態，核心此時才會將呼叫棧設定為中斷或者系統呼叫時 使用者程式中斷的地方 ，然後切換到使用者態後就繼續在使用者程式之前中斷的地方繼續執行程式邏輯了。由於程式幾乎每時每刻都在進行諸如系統呼叫的工作，可以認為，訊號的處理是幾乎實時的。 如下是執行緒核心態與使用者態切換的過程，正式訊號處理檢查的地方。整個過程可以用下面的示意圖表示。
知道了訊號是如何被執行緒處理的，還需要了解下，核心會如何傳送訊號給程式。
核心傳送訊號的方式
核心向程式發訊號的方式是對程式中的一個執行緒傳送訊號，而透過settimmer 系統呼叫設定定時器 傳送SIGPROF 訊號的方式就是隨機的對程式中的一個執行中執行緒去進行傳送。而執行中執行緒接收到這個訊號後，就呼叫自身的處理函式對這個訊號去進行處理，對於SIGPROF 訊號而言，則是將執行緒中斷前的函式棧記錄下來，用於後續分析函式佔用cpu的工作時長。
由於只是隨機的向一個執行中的執行緒傳送SIGPROF 訊號，這裡涉及到了兩個問題？
第一因為同一個程式中只有一個執行緒在進行取樣，所以在隨機選擇執行執行緒傳送SIGPROF訊號時，要求選擇執行緒時的公平性，不然可能會出現A,B兩個執行緒，A執行緒接收到SIGPROF訊號的次數遠遠大於B 執行緒接收SIGPROF訊號的次數，這樣對A執行緒進行取樣的次數將會變多，影響了我們取樣的結果。
而golang用settimmer 設定定時器傳送SIGPROF 訊號 的方式的確被證實在linux上存線上程選擇公平性問題(但是mac os上沒有這個問題) 關於這個問題的討論在github上有記錄，這是連結 這個問題已經在go1.18上得到了解決，解決方式我會在下面給出，我們先來看隨機的向一個執行中的執行緒傳送SIGPROF 訊號 引發的第二個問題。
第二 因為是向一個執行中的執行緒去傳送訊號，所以我們只能統計到取樣時間段內在cpu上執行的函式，而那些io阻塞的函式將不能被統計到，關於這點業內已經有開源庫幫助解決，https://github.com/felixge/fgprof，不過由於這個庫進行取樣時會stop the world ，所以其作者強烈建議如果go協程數量比較多時，將go版本升級到1.19再使用。後續有機會再來探討這個庫的實現吧，我們先回到如何解決settimer函式在選擇執行緒的公平性問題上。
取樣資料的公平性
為了解決公平性問題，golang在settimer的系統呼叫的基礎上增加了timer_create系統呼叫timer_create 可以單獨的為每一個執行緒都建立定時器，這樣每個執行執行緒都會取樣到自己的函式堆疊了。所以在go1.18版本對pprof.StartCPUProfile內部建立定時器的程式碼進行了改造。剛才有提到pprof.StartCPUProfile 底層其實是呼叫setcpuprofilerate 這個方法去設定的定時器，所以我們來看看go1.18和go1.17版本在這個方法的實現上主要是哪裡不同。
// go1.17 版本 src/runtime/proc.go:4563
func setcpuprofilerate(hz int32) {
if hz < 0 {
hz = 0
}
_g_ := getg()
_g_.m.locks++
setThreadCPUProfiler(0)
for !atomic.Cas(&prof.signalLock, 0, 1) {
osyield()
}
if prof.hz != hz {
// 設定程式維度的 SIGPROF 訊號傳送器
setProcessCPUProfiler(hz)
prof.hz = hz
}
atomic.Store(&prof.signalLock, 0)
lock(&sched.lock)
sched.profilehz = hz
unlock(&sched.lock)
if hz != 0 {
// 設定執行緒維度的SIGPROF 訊號定時器
setThreadCPUProfiler(hz)
}
_g_.m.locks--
}
上述是go1.17版本的setcpuprofilerate 程式碼，如果你再去看 go1.18版本的程式碼，會發現他們在這個方法上是一模一樣的，都是呼叫了setProcessCPUProfiler 和setThreadCPUProfiler，setProcessCPUProfiler 設定程式維度的傳送SIGPROF訊號定時器，setThreadCPUProfiler設定執行緒維度的傳送SIGPROF訊號的定時器，但其實setThreadCPUProfiler 在go1.17的實現上並不完整。
// go 1.17 src/runtime/signal_unix.go:314
func setThreadCPUProfiler(hz int32) {
getg().m.profilehz = hz
}
go1.17版本上僅僅是為協程裡代表執行緒的m變數設定了一個profilehz(取樣的頻率)，並沒有真正實現執行緒維度的取樣。
// go 1.18 src/runtime/os_linux.go:605
....
// setThreadCPUProfiler 方法內部 timer_create的程式碼段
var timerid int32
var sevp sigevent
sevp.notify = _SIGEV_THREAD_ID
sevp.signo = _SIGPROF
sevp.sigev_notify_thread_id = int32(mp.procid)
ret := timer_create(_CLOCK_THREAD_CPUTIME_ID, &sevp, &timerid)
if ret != 0 {
return
}
....
在go1.18版本上的setThreadCPUProfiler則真正實現了這部分邏輯，由於go1.18版本它同時呼叫了setProcessCPUProfiler以及setThreadCPUProfiler，這樣在接收SIGPROF訊號時就會出現重複計數的問題。
所以go1.18在處理SIGPROF訊號的時候也做了去重處理，所以在golang訊號處理的方法sighandler 內部有這樣一段邏輯。
func sighandler(sig uint32, info *siginfo, ctxt unsafe.Pointer, gp *g) {
_g_ := getg()
c := &sigctxt{info, ctxt}
if sig == _SIGPROF {
mp := _g_.m
// Some platforms (Linux) have per-thread timers, which we use in
// combination with the process-wide timer. Avoid double-counting.
if validSIGPROF(mp, c) {
sigprof(c.sigpc(), c.sigsp(), c.siglr(), gp, mp)
}
return
}
.....
如果發現訊號是_SIGPROF 那麼會透過validSIGPROF 去檢測此次的_SIGPROF訊號是否應該被統計。validSIGPROF的檢測邏輯這裡就不展開了。
總結
cpu的統計原理與前面所講的指標統計的原理稍微複雜點，涉及到了linux訊號處理相關的內容，cpu統計的原理，簡而言之，就是透過設定一個傳送SIGPROF訊號的定時器，然後使用者程式透過接收作業系統定時傳送的SIGPROF訊號來對使用者程式正在執行的堆疊函式進行統計。在取樣時間內，同一個函式被統計的越多，說明該函式佔用的cpu工作時長就越長。