快捷導(dǎo)航

Golang?pprof監(jiān)控之cpu占用率統(tǒng)計(jì)原理詳解

更新時(shí)間：2023年04月10日 11:40:47 作者：藍(lán)胖子的編程夢

經(jīng)過前面的幾節(jié)對pprof的介紹，對pprof統(tǒng)計(jì)的原理算是掌握了七八十了，但唯獨(dú)還沒有分析pprof?工具是如何統(tǒng)計(jì)cpu使用情況的，今天我們來分析下這部分

經(jīng)過前面的幾節(jié)對pprof的介紹，對pprof統(tǒng)計(jì)的原理算是掌握了七八十了，我們對memory,block,mutex,trace,goroutine,threadcreate這些維度的統(tǒng)計(jì)原理都進(jìn)行了分析，但唯獨(dú)還沒有分析pprof 工具是如何統(tǒng)計(jì)cpu使用情況的，今天我們來分析下這部分。

http 接口暴露的方式

還記得 golang pprof監(jiān)控系列（2） —— memory，block，mutex 使用里我們啟動(dòng)了一個(gè)http服務(wù)來暴露各種性能指標(biāo)信息。讓我們再回到當(dāng)時(shí)啟動(dòng)http服務(wù)看到的網(wǎng)頁圖。

當(dāng)點(diǎn)擊上圖中profile鏈接時(shí)，便會(huì)下載一個(gè)關(guān)于cpu指標(biāo)信息的二進(jìn)制文件。這個(gè)二進(jìn)制文件同樣可以用go tool pprof 工具去分析，同樣，關(guān)于go tool pprof的使用不是本文的重點(diǎn)，網(wǎng)上的資料也相當(dāng)多，所以我略去了這部分。

緊接著，我們來快速看下如何用程序代碼的方式生成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 則開始統(tǒng)計(jì) cpu使用情況，pprof.StopCPUProfile則停止統(tǒng)計(jì)cpu使用情況，將程序使用cpu的情況寫入cpu.out文件。cpu.out文件我們則可以用go tool pprof去分析了。

好的，在快速的看完如何在程序中暴露cpu性能指標(biāo)后，我們來看看golang是如何統(tǒng)計(jì)各個(gè)函數(shù)cpu使用情況的。接下來，正戲開始。

cpu 統(tǒng)計(jì)原理分析

首先要明白，我們究竟要統(tǒng)計(jì)的是什么內(nèi)容？我們需要知道cpu的使用情況，換言之就是cpu的工作時(shí)間花在了哪些函數(shù)上，最后是不是就是看函數(shù)在cpu上的工作時(shí)長。

那么函數(shù)的在cpu上工作時(shí)長應(yīng)該如何去進(jìn)行統(tǒng)計(jì)？

golang還是采用部分采樣的方式，通過settimmer 系統(tǒng)調(diào)用設(shè)置了發(fā)送SIGPROF 的定時(shí)器，當(dāng)達(dá)到runtime.SetCPUProfileRate設(shè)置的周期間隔時(shí)，操作系統(tǒng)就會(huì)向進(jìn)程發(fā)送SIGPROF 信號，默認(rèn)情況下是100Mz(10毫秒)。

一旦設(shè)置了發(fā)送SIGPROF信號的定時(shí)器，操作系統(tǒng)便會(huì)定期向進(jìn)程發(fā)送SIGPROF信號。

設(shè)置定時(shí)器的代碼便是在我們調(diào)用pprof.StartCPUProfile方法開啟cpu信息采樣的時(shí)候。代碼如下，

// 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
}

在倒數(shù)第三行的時(shí)候調(diào)用了設(shè)置采樣的周期，并且緊接著profileWriter 就是用一個(gè)協(xié)程啟動(dòng)后去不斷的讀取cpu的采樣數(shù)據(jù)寫到文件里。而調(diào)用settimer的地方就是在runtime.SetCPUProfileRate里，runtime.SetCPUProfileRate最終會(huì)調(diào)用 setcpuprofilerate方法，setcpuprofilerate 又會(huì)去調(diào)用setProcessCPUProfiler方法設(shè)置settimer 定時(shí)器。

// 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)
....

經(jīng)過上述步驟后，cpu的采樣就真正開始了，之后就是定時(shí)器被觸發(fā)送SIGPROF信號，進(jìn)程接收到這個(gè)信號后，會(huì)對當(dāng)前函數(shù)的調(diào)用堆棧進(jìn)行記錄，由于默認(rèn)的采樣周期設(shè)置的是100Mz，所以，你可以理解為每10ms，golang就會(huì)統(tǒng)計(jì)下當(dāng)前正在運(yùn)行的是哪個(gè)函數(shù)，在采樣的這段時(shí)間內(nèi)，哪個(gè)函數(shù)被統(tǒng)計(jì)的次數(shù)越多，是不是就能說明這個(gè)函數(shù)在這段時(shí)間內(nèi)占用cpu的工作時(shí)長就越多了。

由于golang借助了linux的信號機(jī)制去進(jìn)行cpu執(zhí)行函數(shù)的采樣，這里有必要額外介紹下linux 進(jìn)程與信號相關(guān)的知識(shí)。首先來看下線程處理信號的時(shí)機(jī)在什么時(shí)候。

線程處理信號的時(shí)機(jī)

線程對信號的處理時(shí)機(jī)一般是在由內(nèi)核態(tài)返回到用戶態(tài)之前，也就是說，當(dāng)線程由于系統(tǒng)調(diào)用或者中斷進(jìn)入內(nèi)核態(tài)后，當(dāng)系統(tǒng)調(diào)用結(jié)束或者中斷處理完成后，在返回到用戶態(tài)之前，操作系統(tǒng)會(huì)檢查這個(gè)線程是不是有未處理的信號，如果有的話，那么會(huì)先切回到用戶態(tài)讓線程會(huì)首先處理信號，信號處理完畢后又返回內(nèi)核態(tài)，內(nèi)核此時(shí)才會(huì)將調(diào)用棧設(shè)置為中斷或者系統(tǒng)調(diào)用時(shí) 用戶進(jìn)程中斷的地方 ，然后切換到用戶態(tài)后就繼續(xù)在用戶進(jìn)程之前中斷的地方繼續(xù)執(zhí)行程序邏輯了。由于進(jìn)程幾乎每時(shí)每刻都在進(jìn)行諸如系統(tǒng)調(diào)用的工作，可以認(rèn)為，信號的處理是幾乎實(shí)時(shí)的。如下是線程內(nèi)核態(tài)與用戶態(tài)切換的過程，正式信號處理檢查的地方。整個(gè)過程可以用下面的示意圖表示。

知道了信號是如何被線程處理的，還需要了解下，內(nèi)核會(huì)如何發(fā)送信號給進(jìn)程。

內(nèi)核發(fā)送信號的方式

內(nèi)核向進(jìn)程發(fā)信號的方式是對進(jìn)程中的一個(gè)線程發(fā)送信號，而通過settimmer 系統(tǒng)調(diào)用設(shè)置定時(shí)器發(fā)送SIGPROF 信號的方式就是隨機(jī)的對進(jìn)程中的一個(gè)運(yùn)行中線程去進(jìn)行發(fā)送。而運(yùn)行中線程接收到這個(gè)信號后，就調(diào)用自身的處理函數(shù)對這個(gè)信號去進(jìn)行處理，對于SIGPROF 信號而言，則是將線程中斷前的函數(shù)棧記錄下來，用于后續(xù)分析函數(shù)占用cpu的工作時(shí)長。

由于只是隨機(jī)的向一個(gè)運(yùn)行中的線程發(fā)送SIGPROF 信號，這里涉及到了兩個(gè)問題？

第一因?yàn)橥粋€(gè)進(jìn)程中只有一個(gè)線程在進(jìn)行采樣，所以在隨機(jī)選擇運(yùn)行線程發(fā)送SIGPROF信號時(shí)，要求選擇線程時(shí)的公平性，不然可能會(huì)出現(xiàn)A,B兩個(gè)線程，A線程接收到SIGPROF信號的次數(shù)遠(yuǎn)遠(yuǎn)大于B 線程接收SIGPROF信號的次數(shù)，這樣對A線程進(jìn)行采樣的次數(shù)將會(huì)變多，影響了我們采樣的結(jié)果。

而golang用settimmer 設(shè)置定時(shí)器發(fā)送SIGPROF 信號的方式的確被證實(shí)在linux上存在線程選擇公平性問題(但是mac os上沒有這個(gè)問題) 關(guān)于這個(gè)問題的討論在github上有記錄，這是鏈接這個(gè)問題已經(jīng)在go1.18上得到了解決，解決方式我會(huì)在下面給出，我們先來看隨機(jī)的向一個(gè)運(yùn)行中的線程發(fā)送SIGPROF 信號引發(fā)的第二個(gè)問題。

第二因?yàn)槭窍蛞粋€(gè)運(yùn)行中的線程去發(fā)送信號，所以我們只能統(tǒng)計(jì)到采樣時(shí)間段內(nèi)在cpu上運(yùn)行的函數(shù)，而那些io阻塞的函數(shù)將不能被統(tǒng)計(jì)到，關(guān)于這點(diǎn)業(yè)內(nèi)已經(jīng)有開源庫幫助解決，https://github.com/felixge/fgprof，不過由于這個(gè)庫進(jìn)行采樣時(shí)會(huì)stop the world ，所以其作者強(qiáng)烈建議如果go協(xié)程數(shù)量比較多時(shí)，將go版本升級到1.19再使用。后續(xù)有機(jī)會(huì)再來探討這個(gè)庫的實(shí)現(xiàn)吧，我們先回到如何解決settimer函數(shù)在選擇線程的公平性問題上。

采樣數(shù)據(jù)的公平性

為了解決公平性問題，golang在settimer的系統(tǒng)調(diào)用的基礎(chǔ)上增加了timer_create系統(tǒng)調(diào)用timer_create 可以單獨(dú)的為每一個(gè)線程都創(chuàng)建定時(shí)器，這樣每個(gè)運(yùn)行線程都會(huì)采樣到自己的函數(shù)堆棧了。所以在go1.18版本對pprof.StartCPUProfile內(nèi)部創(chuàng)建定時(shí)器的代碼進(jìn)行了改造。剛才有提到pprof.StartCPUProfile 底層其實(shí)是調(diào)用setcpuprofilerate 這個(gè)方法去設(shè)置的定時(shí)器，所以我們來看看go1.18和go1.17版本在這個(gè)方法的實(shí)現(xiàn)上主要是哪里不同。

// 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 {
	   // 設(shè)置進(jìn)程維度的 SIGPROF 信號發(fā)送器
		setProcessCPUProfiler(hz)
		prof.hz = hz
	}
	atomic.Store(&prof.signalLock, 0)
	lock(&sched.lock)
	sched.profilehz = hz
	unlock(&sched.lock)
	if hz != 0 {
	   // 設(shè)置線程維度的SIGPROF 信號定時(shí)器
		setThreadCPUProfiler(hz)
	}
	_g_.m.locks--
}

上述是go1.17版本的setcpuprofilerate 代碼，如果你再去看 go1.18版本的代碼，會(huì)發(fā)現(xiàn)他們在這個(gè)方法上是一模一樣的，都是調(diào)用了setProcessCPUProfiler 和setThreadCPUProfiler，setProcessCPUProfiler 設(shè)置進(jìn)程維度的發(fā)送SIGPROF信號定時(shí)器，setThreadCPUProfiler設(shè)置線程維度的發(fā)送SIGPROF信號的定時(shí)器，但其實(shí)setThreadCPUProfiler 在go1.17的實(shí)現(xiàn)上并不完整。

// go 1.17  src/runtime/signal_unix.go:314
func setThreadCPUProfiler(hz int32) {
	getg().m.profilehz = hz
}

go1.17版本上僅僅是為協(xié)程里代表線程的m變量設(shè)置了一個(gè)profilehz(采樣的頻率)，并沒有真正實(shí)現(xiàn)線程維度的采樣。

// go 1.18 src/runtime/os_linux.go:605 
....
// setThreadCPUProfiler 方法內(nèi)部 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則真正實(shí)現(xiàn)了這部分邏輯，由于go1.18版本它同時(shí)調(diào)用了setProcessCPUProfiler以及setThreadCPUProfiler，這樣在接收SIGPROF信號時(shí)就會(huì)出現(xiàn)重復(fù)計(jì)數(shù)的問題。

所以go1.18在處理SIGPROF信號的時(shí)候也做了去重處理，所以在golang信號處理的方法sighandler 內(nèi)部有這樣一段邏輯。

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
	}
	.....

如果發(fā)現(xiàn)信號是_SIGPROF 那么會(huì)通過validSIGPROF 去檢測此次的_SIGPROF信號是否應(yīng)該被統(tǒng)計(jì)。validSIGPROF的檢測邏輯這里就不展開了。

總結(jié)

cpu的統(tǒng)計(jì)原理與前面所講的指標(biāo)統(tǒng)計(jì)的原理稍微復(fù)雜點(diǎn)，涉及到了linux信號處理相關(guān)的內(nèi)容，cpu統(tǒng)計(jì)的原理，簡而言之，就是通過設(shè)置一個(gè)發(fā)送SIGPROF信號的定時(shí)器，然后用戶程序通過接收操作系統(tǒng)定時(shí)發(fā)送的SIGPROF信號來對用戶程序正在執(zhí)行的堆棧函數(shù)進(jìn)行統(tǒng)計(jì)。在采樣時(shí)間內(nèi)，同一個(gè)函數(shù)被統(tǒng)計(jì)的越多，說明該函數(shù)占用的cpu工作時(shí)長就越長。

到此這篇關(guān)于Golang pprof監(jiān)控之cpu占用率統(tǒng)計(jì)原理詳解的文章就介紹到這了,更多相關(guān)Golang pprof cpu占用率統(tǒng)計(jì)內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

您可能感興趣的文章: