go pprof 採樣何時進行

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

import (_ "net/http/pprof")func main() {go func() {log.Println(http.ListenAndServe("localhost:6060", nil))}()}

這段代碼大家應該都很熟悉，go tool pprof工具的通用代碼，用來做效能等分析。我這兩天嘗試用了一下，不免有了一個疑問：pprof是要採樣的，這個採樣是何時進行的？是程式啟動就開始採樣還是當我curl localhost:$PORT/debug/pprof/$PROFILE_TYPE開始？

為什麼會考慮這個呢，主要是在看的架構裡整合了pprof，預設開啟，如果是程式一開始就採樣，那對於效能是有損耗的。這種問題別人回答你，你也不一定相信，我們還是來看看pprof的代碼吧。

標準庫的代碼是在$GOROOT/src下面，我們找一下pprof，在我的mac上路徑是/usr/local/Cellar/go/1.9.2/libexec/src/net/http/pprof/pprof.go

首先是init函數，註冊了我們用到的分析urls：

func init() {    http.Handle("/debug/pprof/", http.HandlerFunc(Index))    http.Handle("/debug/pprof/cmdline", http.HandlerFunc(Cmdline))    http.Handle("/debug/pprof/profile", http.HandlerFunc(Profile))    http.Handle("/debug/pprof/symbol", http.HandlerFunc(Symbol))    http.Handle("/debug/pprof/trace", http.HandlerFunc(Trace))}

這是在程式啟動就執行的，這也是我們感覺只要import就萬事大吉的原因。其實看到這裡應該就明白了，profile只是普通的函數調用而已，程式啟動只是註冊了handler，真正的採樣應該是在請求之後執行的。

但是來都來了，我們不妨往下看看，畢竟需要看標準庫的機會不多。我們來看一下cpu profile，也就是Profile函數：

// Profile responds with the pprof-formatted cpu profile.// The package initialization registers it as /debug/pprof/profile.func Profile(w http.ResponseWriter, r *http.Request) {    sec, _ := strconv.ParseInt(r.FormValue("seconds"), 10, 64)    if sec == 0 {        sec = 30    }    if durationExceedsWriteTimeout(r, float64(sec)) {        w.Header().Set("Content-Type", "text/plain; charset=utf-8")        w.Header().Set("X-Go-Pprof", "1")        w.WriteHeader(http.StatusBadRequest)        fmt.Fprintln(w, "profile duration exceeds server's WriteTimeout")        return    }    // Set Content Type assuming StartCPUProfile will work,    // because if it does it starts writing.    w.Header().Set("Content-Type", "application/octet-stream")    if err := pprof.StartCPUProfile(w); err != nil {        // StartCPUProfile failed, so no writes yet.        // Can change header back to text content        // and send error code.        w.Header().Set("Content-Type", "text/plain; charset=utf-8")        w.Header().Set("X-Go-Pprof", "1")        w.WriteHeader(http.StatusInternalServerError)        fmt.Fprintf(w, "Could not enable CPU profiling: %s\n", err)                return    }    sleep(w, time.Duration(sec)*time.Second)    pprof.StopCPUProfile()}

擷取了一個預設30秒的時間，執行StartCPUProfile，裡面應該是個goroutine，調用返回後sleep了一下，結束cpu profile。採樣應該是在StartCPUProfile，執行seconds時間。

再來看看StartCPUProfile

func StartCPUProfile(w io.Writer) error {    // The runtime routines allow a variable profiling rate,    // but in practice operating systems cannot trigger signals    // at more than about 500 Hz, and our processing of the    // signal is not cheap (mostly getting the stack trace).    // 100 Hz is a reasonable choice: it is frequent enough to    // produce useful data, rare enough not to bog down the    // system, and a nice round number to make it easy to    // convert sample counts to seconds. Instead of requiring    // each client to specify the frequency, we hard code it.    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}

注釋解釋了取樣頻率的由來，我們先看一下CPU主頻的概念：

CPU的主頻，即CPU核心工作的時鐘頻率（CPU Clock Speed）。CPU的主頻的基本單位是赫茲（Hz），但更多的是以兆赫茲（MHz）或吉赫茲（GHz）為單位。時鐘頻率的倒數即為刻度。刻度的基本單位為秒（s），但更多的是以毫秒（ms）、微妙（us）或納秒（ns）為單位。在一個刻度內，CPU執行一條運算指令。也就是說，在1000 Hz的CPU主頻下，每1毫秒可以執行一條CPU運算指令。在1 MHz的CPU主頻下，每1微妙可以執行一條CPU運算指令。而在1 GHz的CPU主頻下，每1納秒可以執行一條CPU運算指令。

在預設情況下，Go語言的運行時系統會以100 Hz的的頻率對CPU使用方式進行取樣。也就是說每秒取樣100次，即每10毫秒會取樣一次。為什麼使用這個頻率呢？因為100 Hz既足夠產生有用的資料，又不至於讓系統產生停頓。並且100這個數上也很容易做換算，比如把總取樣計數換算為每秒的取樣數。實際上，這裡所說的對CPU使用方式的取樣就是對當前的Goroutine的堆棧上的程式計數器的取樣。由此，我們就可以從樣本記錄中分析出哪些代碼是計算時間最長或者說最耗CPU資源的部分了。

代碼很容易理解，鎖住cpu，設定runtime的採樣頻率，profileWriter就是實際採樣了。

所以結論是，採樣在請求之後才會進行，線上開啟採樣的介面沒有問題。

參考資料

• Profiling Go Programs
• Profiling Go programs with pprof
• go tool pprof