萬(wàn)字長(zhǎng)文講解 Golang pprof 的使用

作者：藍(lán)胖子的編程夢(mèng) 2024-03-07 18:11:39

cpu在http接口暴露的分析界面中有個(gè)profile的鏈接，點(diǎn)擊后，應(yīng)用程序會(huì)采集30s的cpu運(yùn)行信息后然后生成一個(gè)二進(jìn)制文件，所以本質(zhì)上對(duì)cpu的分析都是通過(guò)一個(gè)二進(jìn)制文件進(jìn)行的。

大家好，我是藍(lán)胖子，說(shuō)到golang的性能分析，不得不提的就是其自身?yè)碛械膒prof，它提供了從cpu，內(nèi)存，阻塞情況，協(xié)程，線(xiàn)程，乃至程序運(yùn)行軌跡trace的分析，可以說(shuō)相當(dāng)強(qiáng)大了。

今天我將會(huì)用較長(zhǎng)的篇幅闡述應(yīng)該如何使用pprof工具來(lái) 對(duì)cpu，內(nèi)存，阻塞情況，協(xié)程，線(xiàn)程這幾個(gè)維度去進(jìn)行分析。

其實(shí)總結(jié)出來(lái)Golang pprof的使用方式，可以用下面的思維導(dǎo)圖來(lái)表示。

圖片

要么在程序中通過(guò)http接口的方式暴露相應(yīng)的pprof的采集控制界面，要么就是在程序中通過(guò)代碼開(kāi)啟對(duì)應(yīng)指標(biāo)的采集樣本功能，采集一段時(shí)間的樣本后生成二進(jìn)制文件，最后通過(guò) go tool pprof 命令去對(duì)樣本的數(shù)據(jù)進(jìn)行分析。

分析的方式也有兩種，

通過(guò)命令行開(kāi)啟一個(gè)交互終端
通過(guò)瀏覽器將二進(jìn)制文件的信息展示出來(lái)

我們可以通過(guò)下述的代碼通過(guò)http接口的方式暴露相應(yīng)的pprof的采集控制界面。

import (  
    "log"  
    "net/http"    
    "net/http/pprof"    
    "time")  
  
func main() {  
    mux := http.NewServeMux()  
    mux.HandleFunc("/debug/pprof/", pprof.Index)  
    mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)  
    mux.HandleFunc("/debug/pprof/profile", pprof.Profile)  
    mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)  
    mux.HandleFunc("/debug/pprof/trace", pprof.Trace)  
    go func() { log.Fatal(http.ListenAndServe(":8080", mux)) }()  
    time.Sleep(time.Hour)  
}

接著訪(fǎng)問(wèn)下http://localhost:8080/debug/pprof/ 便會(huì)出現(xiàn)各種維度指標(biāo)，可以點(diǎn)擊進(jìn)去查看具體的指標(biāo)信息。如下所示：

圖片

接下來(lái)我們來(lái)分析下各個(gè)指標(biāo)在 http接口或者生成的二進(jìn)制文件輸出的各種信息究竟代表什么含義。

在下面的分析中我會(huì)分別的從http接口暴露指標(biāo)的方式和二進(jìn)制文件的方式分別介紹如何看懂各種指標(biāo)的輸出信息。

cpu

除了上述提到http接口暴露出cpu指標(biāo)外，我們還可以通過(guò)下面的代碼，在程序中顯示的開(kāi)啟cpu指標(biāo)的采集。在這個(gè)例子中，我通過(guò)busyCpu 方法不斷的進(jìn)行加法運(yùn)算來(lái)模擬頻繁的cpu操作。

import (  
    "github.com/pkg/profile"  
    "log"  
    "os"    
    "os/signal"    
    "syscall")  
func main() {  
    p := profile.Start(profile.CPUProfile,  
       profile.ProfilePath("profile"),  
       profile.NoShutdownHook,  
    )  
    defer p.Stop()  
    go busyCpu()  
    c := make(chan os.Signal, 1)  
    signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)  
    defer signal.Stop(c)  
    <-c  
}  
  
func busyCpu() {  
    i := uint(1000000)  
    for {  
       log.Println("sum number", i, Add(i, i+1))  
       i++  
    }  
}  
  
func Add(a, b uint) uint {  
    return a + b  
}

啟動(dòng)終端分析

在得到二進(jìn)制文件后，我們可以使用如下命令來(lái)啟動(dòng)一個(gè)交互終端來(lái)分析cpu的使用情況。

go tool  pprof cpuprofile/cpu.pprof

輸入top命令得到如下結(jié)果：

(base) ?  cpu go tool  pprof cpuprofile/cpu.pprof
Type: cpu
Time: Mar 4, 2024 at 3:14pm (CST)
Duration: 4.35s, Total samples = 200ms ( 4.60%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 200ms, 100% of 200ms total
Showing top 10 nodes out of 16
      flat  flat%   sum%        cum   cum%
     190ms 95.00% 95.00%      190ms 95.00%  syscall.syscall
      10ms  5.00%   100%       10ms  5.00%  runtime.pthread_cond_signal
         0     0%   100%      190ms 95.00%  internal/poll.(*FD).Write
         0     0%   100%      190ms 95.00%  internal/poll.ignoringEINTRIO (inline)
         0     0%   100%      190ms 95.00%  log.(*Logger).output
         0     0%   100%      190ms 95.00%  log.Println (inline)
         0     0%   100%      190ms 95.00%  main.busyCpu
         0     0%   100%      190ms 95.00%  os.(*File).Write
         0     0%   100%      190ms 95.00%  os.(*File).write (inline)
         0     0%   100%       10ms  5.00%  runtime.exitsyscallfast.func1

每個(gè)列的含義如下:

flat：函數(shù)自身的運(yùn)行耗時(shí)（排除了子函數(shù)的調(diào)用耗時(shí)）

flat%：flat運(yùn)行耗時(shí)占用總的采集樣本的時(shí)間和的比例，這里所有節(jié)點(diǎn)運(yùn)行的flat時(shí)間和為200ms。

sum%：命令行返回結(jié)果中函數(shù)自身和其之上的函數(shù)運(yùn)行的flat時(shí)間占所有采集樣本時(shí)間總和的比例。

cum：當(dāng)前函數(shù)和其子函數(shù)的調(diào)用耗時(shí)總的運(yùn)行時(shí)間

cum%：cum耗時(shí)占總的采集樣本的時(shí)間和的比例。

分析中可以看出主要是打印日志占用了比較大的cpu。

在命令行中可以輸入svg，來(lái)輸出cpu性能剖析的profile 圖。

(pprof) svg 
Generating report in profile001.svg

圖片

圖中顯示了函數(shù)的調(diào)用關(guān)系，函數(shù)框中顯示了函數(shù)自身的運(yùn)行時(shí)長(zhǎng)flat和其自身及其子函數(shù)運(yùn)行時(shí)長(zhǎng)cum，箭頭上的時(shí)間則是其子函數(shù)的cum運(yùn)行時(shí)長(zhǎng)，時(shí)間越大，箭頭越粗。

將二進(jìn)制文件信息輸出到瀏覽器上

可以通過(guò)如下命令來(lái)啟動(dòng)瀏覽器查看cpu使用情況，

go tool pprof -http=:8082  cpuprofile/cpu.pprof

火焰圖分析性能問(wèn)題

通過(guò)web界面，我們除了按剛才的top和調(diào)用耗時(shí)圖像外，甚至還能通過(guò)火焰圖的方式，來(lái)查看cpu調(diào)用耗時(shí)，火焰圖上，函數(shù)的調(diào)用順序是從上往下，函數(shù)占用cpu越長(zhǎng)，那么在火焰圖上的區(qū)塊就會(huì)越大。火焰圖中顯示的是cum值。

圖片

peek

圖片

除了像top那樣輸出函數(shù)的耗時(shí)情況，還會(huì)輸出調(diào)用函數(shù)和被調(diào)用函數(shù)，調(diào)用順序從上到下。

source

Pasted image 20240304175712.png

在web界面可以通過(guò)source視圖去查看函數(shù)節(jié)點(diǎn)的耗時(shí)以及它的子調(diào)用函數(shù)中耗時(shí)的地方，第一欄時(shí)間是flat耗時(shí)，第二欄時(shí)間是cum耗時(shí)。耗時(shí)百分比是cum耗時(shí)占樣本總和的百分比。

內(nèi)存

http接口暴露的控制臺(tái)查看

通過(guò)點(diǎn)擊heap或者allocs 鏈接可以查看內(nèi)存的分配情況，它們的輸出都是一致的。

heap profile: 7: 5536 [110: 2178080] @ heap/1048576
2: 2304 [2: 2304] @ 0x100d7e0ec 0x100d7ea78 0x100d7f260 0x100d7f78c 0x100d811cc 0x100d817d4 0x100d7d6dc 0x100d7d5e4 0x100daba20
# 0x100d7e0eb runtime.allocm+0x8b  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1881
# 0x100d7ea77 runtime.newm+0x37  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2207
# 0x100d7f25f runtime.startm+0x11f  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2491
# 0x100d7f78b runtime.wakep+0xab  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2590
# 0x100d811cb runtime.resetspinning+0x7b /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:3222
# 0x100d817d3 runtime.schedule+0x2d3  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:3383
# 0x100d7d6db runtime.mstart1+0xcb  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1419
# 0x100d7d5e3 runtime.mstart0+0x73  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1367
# 0x100daba1f runtime.mstart+0xf  /Users/lanpangzi/goproject/src/go/src/runtime/asm_arm64.s:117

下面來(lái)講下網(wǎng)頁(yè)輸出內(nèi)容的含義：

heap profile: 7: 5536 [110: 2178080] @ heap/1048576

輸出的第一行含義分別是:

7 代表當(dāng)前活躍的對(duì)象個(gè)數(shù)

5536 代表當(dāng)前活躍對(duì)象占用的字節(jié)數(shù)

110 代表所有(包含歷史的對(duì)象)對(duì)象個(gè)數(shù)

2178080 代表所有對(duì)象(包含歷史的對(duì)象)占用的對(duì)象字節(jié)數(shù)

1048576 控制了內(nèi)存采樣的頻率，1048576 是兩倍的內(nèi)存采樣頻率的大小，默認(rèn)采樣頻率是512kb 即平均每512kb就會(huì)采樣一次，注意這個(gè)值512kb不是絕對(duì)的達(dá)到512kb就會(huì)進(jìn)行采樣，而是從一段時(shí)間內(nèi)的采樣來(lái)看的一個(gè)平均值。

接下來(lái)就是函數(shù)調(diào)用堆棧信息，來(lái)看第一行。

2: 2304 [2: 2304] @ 0x100d7e0ec 0x100d7ea78 0x100d7f260 0x100d7f78c 0x100d811cc 0x100d817d4 0x100d7d6dc 0x100d7d5e4 0x100daba20

從左往右看：

2 代表在該函數(shù)棧上當(dāng)前活躍的對(duì)象個(gè)數(shù)

2304 代表在該函數(shù)棧上當(dāng)前活躍的對(duì)象所占用的字節(jié)數(shù)

方括號(hào)內(nèi)的2 代表在該函數(shù)棧上所有(包含歷史的對(duì)象)對(duì)象個(gè)數(shù)

方括號(hào)內(nèi)的2304 代表在該函數(shù)棧上所有(包含歷史的對(duì)象)對(duì)象所占用的字節(jié)數(shù)

然后是棧上pc寄存器的值。再往后就是具體的棧函數(shù)名信息了。

通過(guò)二進(jìn)制文件查看

我們可以使用如下代碼生成一個(gè)關(guān)于內(nèi)存使用情況的二進(jìn)制profile文件，下述代碼中我用 allocMem 函數(shù)不斷對(duì)一個(gè)字節(jié)數(shù)組進(jìn)行append操作來(lái)模擬內(nèi)存不斷增大的情況。

package main  
  
import (  
    "github.com/pkg/profile"  
    "log"   
     "os"    
     "os/signal"    
     "syscall"    
     "time")  
  
func main() {  
    p := profile.Start(profile.MemProfile,  
       profile.ProfilePath("profile"),  
       profile.NoShutdownHook,  
    )  
    defer p.Stop()  
    go allocMem()  
    c := make(chan os.Signal, 1)  
    signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)  
    defer signal.Stop(c)  
    <-c  
  
}  
  
func allocMem() {  
    buf := []byte{}  
    mb := 1024 * 1024  
  
    for {  
       buf = append(buf, make([]byte, mb)...)  
       log.Println("total allocated memory", len(buf))  
       time.Sleep(time.Second)  
    }  
}

生成的二進(jìn)制文件，和cpu分析一致，可以通過(guò)啟動(dòng)交互終端或者web瀏覽器去進(jìn)行查看，所以啟動(dòng)終端的方式我這里就暫時(shí)略去了，講講不同點(diǎn)，針對(duì)于內(nèi)存，pprof在web 瀏覽器界面提供了幾個(gè)維度去分析。

inuse_space: 正在使用，尚未釋放的空間

inuse_object: 正在使用，尚未釋放的對(duì)象

alloc_space: 所有分配的空間，包含已釋放的

alloc_objects: 所有分配的對(duì)象，包含已釋放的

拿inuse_object舉例，性能剖析圖是這樣的，箭頭顯示了正在使用的對(duì)象個(gè)數(shù)，其中 main.allocMem函數(shù)自身有一個(gè)4MB多的對(duì)象，其子函數(shù)有4個(gè)對(duì)象。

圖片

我們可以根據(jù)source 選項(xiàng)也能得到同樣的分析結(jié)果。

圖片

block

block可用于分析程序鎖mutex，select ，channel通道, wait group 的阻塞行為。

但是block通常是關(guān)閉的，需要通過(guò)下面代碼進(jìn)行開(kāi)啟。

runtime.SetBlockProfileRate(1)

其中,SetBlockProfileRate 的參數(shù)名為rate，rate不同，對(duì)block事件的采樣頻率不同。

1 代表始終對(duì)阻塞事件進(jìn)行采樣
<= 0 代表關(guān)閉阻塞事件的采樣
除了上述兩種情況，SetBlockProfileRate 的參數(shù)傳遞的將會(huì)是一個(gè)納秒值。

如果阻塞的時(shí)間大于了rate值則直接進(jìn)行采樣，如果阻塞的時(shí)間小于rate，那么阻塞事件將會(huì)有(阻塞時(shí)間)/rate 的可能性被采集到。

?????? 注意下block事件的記錄時(shí)機(jī)為獲取鎖資源或者channel 資源時(shí)，進(jìn)行記錄，也就是發(fā)生在lock函數(shù)中。

http接口暴露的控制臺(tái)查看

通過(guò)點(diǎn)擊http接口暴露的pprof控制的block鏈接，可以查看程序中block的情況，瀏覽器輸出如下：

--- contention:
cycles/secnotallow=1000000000
180001216583 1 @ 0x1002a1198 0x1005159b8 0x100299fc4
# 0x1002a1197 sync.(*Mutex).Lock+0xa7 /Users/lanpangzi/goproject/src/go/src/sync/mutex.go:81
# 0x1005159b7 main.main.func2+0x27 /Users/lanpangzi/goproject/src/go/main/main.go:33

contention 是為這個(gè)profile文本信息取的名字，總之中文翻譯是爭(zhēng)用。

cycles/second 是cpu時(shí)鐘每秒鐘的周期數(shù)，用它來(lái)表示時(shí)間也是為了更精確，其實(shí)你可以發(fā)現(xiàn)在我的機(jī)器上每秒是10的9次方個(gè)周期，換算成納秒就是1ns一個(gè)周期時(shí)間了。

接著的180001216583 是阻塞的周期數(shù)，其實(shí)周期就是cputicks，那么180001216583除以 cycles/second 即1000000000得到的就是阻塞的秒數(shù)了。

接著 1 代表阻塞的次數(shù)。

無(wú)論是阻塞周期時(shí)長(zhǎng)還是次數(shù)，都是一個(gè)累加值，即在相同的地方阻塞會(huì)導(dǎo)致這個(gè)值變大，并且次數(shù)會(huì)增加。剩下的部分就是函數(shù)堆棧信息了。

使用二進(jìn)制文件查看

可以通過(guò)如下代碼生成block的二進(jìn)制文件，通過(guò)在主協(xié)程中使用lock方法后，不釋放鎖資源，啟動(dòng)子協(xié)程，讓子協(xié)程同樣使用lock方法模擬系統(tǒng)阻塞的情況。

import (  
    "fmt"  
    "github.com/pkg/profile"   
    "runtime"    
    "sync"    
    "time")  
  
/*  
*  
每次程序鎖阻塞發(fā)生時(shí)，select 阻塞，channel通道阻塞,  
wait group 產(chǎn)生阻塞時(shí)就會(huì)記錄一次阻塞行為  
*/  
func main() {  
  
    runtime.SetBlockProfileRate(1)  
    p := profile.Start(profile.BlockProfile,  
       profile.ProfilePath("profile"),  
       profile.NoShutdownHook)  
    defer p.Stop()  
    mLock := sync.Mutex{}  
    mLock.Lock()  
    go mockBlock(&mLock)  
    go mockBlock(&mLock)  
    time.Sleep(time.Second * 2)  
    mLock.Unlock()  
    time.Sleep(time.Second)  
    fmt.Println("End")  
}  
  
func mockBlock(l *sync.Mutex) {  
    l.Lock()  
    defer l.Unlock()  
    fmt.Println("獲取鎖")  
}

生成的profile文件，同樣可以通過(guò)命令行和web瀏覽器的方式進(jìn)行查看。

這里我直接采樣瀏覽器的方式瀏覽。

go tool pprof -http=:8083  ./profile/block.pprof

block提供了兩個(gè)維度去觀察阻塞事件，contention 發(fā)生阻塞的事件個(gè)數(shù)，delay 發(fā)生阻塞的時(shí)間。

contention 生成的profile圖如下，可以看到發(fā)生阻塞的函數(shù)是main.mockBlock ，其自身包括其調(diào)用子函數(shù)的阻塞次數(shù)是2次。

圖片

delay生成的profile 圖如下所示，main.mockBlock其自身包括其調(diào)用子函數(shù)的阻塞時(shí)間是4s。

圖片

?????? 無(wú)論是阻塞次數(shù)還是阻塞時(shí)間，如果同一個(gè)函數(shù)發(fā)生了阻塞，那么次數(shù)和阻塞時(shí)間都會(huì)累加上去。

使用阻塞時(shí)間/阻塞次數(shù) 能得到平均每次阻塞多長(zhǎng)時(shí)間。

mutex

mutex 記錄的是持有鎖的時(shí)間，注意下它和block的區(qū)別，block記錄的是在獲取鎖之前阻塞的時(shí)間。并且block還可以記錄channel。

mutex 的采集默認(rèn)情況下也是關(guān)閉的，需要用以下代碼進(jìn)行開(kāi)啟。

runtime.SetMutexProfileFraction(1)

其中,SetMutexProfileFraction 的參數(shù)名為rate，rate不同，對(duì)block事件的采樣頻率不同。

1 代表始終對(duì)持有鎖事件進(jìn)行采樣
= 0 代表關(guān)閉阻塞事件的采樣
< 0 將會(huì)把當(dāng)前的rate值讀取出來(lái)
> 1 將會(huì)有1/rate 的持有鎖事件被采集

http接口暴露的控制臺(tái)查看

通過(guò)點(diǎn)擊http接口暴露的pprof控制的mutex鏈接，可以查看程序中鎖持有的的情況，瀏覽器輸出如下：

--- mutex:
cycles/secnotallow=1000000812
sampling period=1
180001727833 1 @ 0x100b9175c 0x100e05840 0x100b567ec 0x100b89fc4
# 0x100b9175b sync.(*Mutex).Unlock+0x8b /Users/lanpangzi/goproject/src/go/src/sync/mutex.go:190
# 0x100e0583f main.main+0x19f   /Users/lanpangzi/goproject/src/go/main/main.go:39
# 0x100b567eb runtime.main+0x25b  /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:255

第一行mutex就是profile文本信息的名稱(chēng)了，同樣也和block一樣，采用cpu周期數(shù)計(jì)時(shí)，但是多了一個(gè)sampling period ，這個(gè)就是我們?cè)O(shè)置的采用頻率。

接下來(lái)的數(shù)據(jù)都和block類(lèi)似，180001727833就是鎖持有的周期， 1為解鎖的次數(shù)。然后是解鎖的堆棧信息。

使用二進(jìn)制文件查看

我們可以通過(guò)如下代碼生成mutex的二進(jìn)制文件，模擬阻塞的情況和block一致，代碼不同的點(diǎn)是將樣本采集的對(duì)象從block替換成了mutex。

package main  
  
import (  
    "fmt"  
    "github.com/pkg/profile"    
    "runtime"    
    "sync"    
    "time")  
  
func main() {  
  
    runtime.SetMutexProfileFraction(1)  
    p := profile.Start(profile.MutexProfile,  
       profile.ProfilePath("profile"),  
       profile.NoShutdownHook)  
    defer p.Stop()  
    mLock := sync.Mutex{}  
    mLock.Lock()  
    go mockBlock(&mLock)  
    go mockBlock(&mLock)  
    time.Sleep(time.Second * 2)  
    mLock.Unlock()  
    time.Sleep(time.Second)  
    fmt.Println("End")  
}  
  
func mockBlock(l *sync.Mutex) {  
    l.Lock()  
    defer l.Unlock()  
    fmt.Println("獲取鎖")  
}

這里我同樣采用web瀏覽器的方式去查看mutext的剖析grapgh，mutex提供了兩個(gè)維度去觀察阻塞事件，contention 發(fā)生持有鎖的事件個(gè)數(shù)，delay 持有鎖的時(shí)間。

以下是contention 維度的圖，可以看到在main方法中進(jìn)行中持有了一次鎖，在mockBlock方法中也持有了一次鎖。

圖片

通過(guò)delay 維度可以發(fā)現(xiàn)main方法以及其子調(diào)用函數(shù)，持有鎖的時(shí)間一共是2s。

圖片

goroutine

http接口暴露的控制臺(tái)查看

點(diǎn)擊控制界面的goroutine鏈接，我們會(huì)看到在程序中g(shù)oroutine正在執(zhí)行的函數(shù)堆棧信息，界面如下：

圖片

首先地址欄 /debug/pprof/goroutine?debug= 1 代表這是在訪(fǎng)問(wèn)goroutine指標(biāo)信息，debug =1 代表訪(fǎng)問(wèn)的內(nèi)容將會(huì)以文本可讀的形式展現(xiàn)出來(lái)。 debug=0 則是會(huì)下載一個(gè)goroutine指標(biāo)信息的二進(jìn)制文件。 debug = 2 將會(huì)把當(dāng)前所有協(xié)程的堆棧信息以文本可讀形式展示在網(wǎng)頁(yè)上。如下圖所示:

圖片

debug =2 時(shí)的如上圖所示，41代表協(xié)程的id，方括號(hào)內(nèi)running代表了協(xié)程的狀態(tài)是運(yùn)行中，接著就是該協(xié)程此時(shí)的堆棧信息了。

讓我們?cè)倩氐絛ebug = 1的分析上面去，剛才分析完了地址欄里的debug參數(shù)，接著，我們看輸出的第一行。

goroutine profile: total 6 1 @ 0x102ad6c60 0x102acf7f4 0x102b04de0 0x102b6e850 0x102b6e8dc 0x102b6f79c 0x102c27d04 0x102c377c8 0x102d0fc74 0x102bea72c 0x102bebec0 0x102bebf4c 0x102ca4af0 0x102ca49dc 0x102d0b084 0x102d10f30 0x102d176a4 0x102b09fc4 # 0x102b04ddf internal/poll.runtime_pollWait+0x5f  /Users/xiongchuanhong/goproject/src/go/src/runtime/netpoll.go:303 # 0x102b6e84f internal/poll.(*pollDesc).wait+0x8f  /Users/xiongchuanhong/goproject/src/go/src/internal/poll/fd_poll_runtime.go:84 ......

goroutine profile 表明了這個(gè)profile的類(lèi)型。

total 6 代表此時(shí)一共有6個(gè)協(xié)程。

接著是下面一行，1 代表了在這個(gè)堆棧上，只有一個(gè)協(xié)程在執(zhí)行。但其實(shí)在計(jì)算出數(shù)字1時(shí)，并不僅僅按堆棧去做區(qū)分，還依據(jù)了協(xié)程labels值，也就是協(xié)程的堆棧和lebels標(biāo)簽值共同構(gòu)成了一個(gè)key，而數(shù)字1就是在遍歷所有協(xié)程信息時(shí)，對(duì)相同key進(jìn)行累加計(jì)數(shù)得來(lái)的。

我們可以通過(guò)下面的方式為協(xié)程設(shè)置labels。

pprof.SetGoroutineLabels(pprof.WithLabels(context.Background(), pprof.Labels("name", "lanpangzi", "age", "18")))

通過(guò)上述代碼，我可以為當(dāng)前協(xié)程設(shè)置了兩個(gè)標(biāo)簽值，分別是name和age，設(shè)置label值之后，再來(lái)看debug=1后的網(wǎng)頁(yè)輸出，可以發(fā)現(xiàn) 設(shè)置的labels出現(xiàn)了。

1 @ 0x104f86c60 0x104fb7358 0x105236368 0x104f867ec 0x104fba024 # labels: {"age":"18", "name":"lanpangzi"} # 0x104fb7357 time.Sleep+0x137 /Users/xiongchuanhong/goproject/src/go/src/runtime/time.go:193 # 0x105236367 main.main+0x437  /Users/xiongchuanhong/goproject/src/go/main/main.go:46 # 0x104f867eb runtime.main+0x25b /Users/xiongchuanhong/goproject/src/go/src/runtime/proc.go:255

而數(shù)字1之后，就是協(xié)程正在執(zhí)行的函數(shù)堆棧信息了。

使用二進(jìn)制文件查看

我們可以通過(guò)如下代碼生成profile的二進(jìn)制文件，在下述代碼中，我生成了兩個(gè)協(xié)程，然后開(kāi)啟對(duì)goroutine指標(biāo)的采集。

package main  
  
import (  
    "fmt"  
    "github.com/pkg/profile"    
    "time")  
  
func main() {  
    go mockGo()  
    go mockGo()  
    p := profile.Start(profile.GoroutineProfile,  
       profile.ProfilePath("profile"),  
       profile.NoShutdownHook)  
    p.Stop()  
}  
  
func mockGo() {  
    time.Sleep(time.Second * 3)  
    fmt.Println("獲取鎖")  
}

生成的goroutine二進(jìn)制文件后，查看goroutine 方式也和其他profile指標(biāo)一致，這里我直接放上通過(guò)web瀏覽器查看的graph。顯示的堆棧信息為當(dāng)前程序中協(xié)程正在執(zhí)行的堆棧，可以看到main.mockGo 函數(shù)中有兩個(gè)協(xié)程在執(zhí)行這個(gè)方法，main方法中一個(gè)協(xié)程在執(zhí)行。

圖片

thread

http接口暴露的控制臺(tái)查看

介紹完goroutine指標(biāo)的輸出信息后，再來(lái)看看threadcreate 線(xiàn)程創(chuàng)建指標(biāo)的輸出信息。先來(lái)看下在控制臺(tái)中通過(guò)點(diǎn)擊thread鏈接看到的輸出。

圖片

老規(guī)矩，先看地址欄，debug=1代表輸出的是文本可讀的信息，threadcreate 就沒(méi)有debug=2的特別輸出了，debug=0時(shí) 同樣也會(huì)下載一個(gè)可供go tool pprof分析的二進(jìn)制文件。

接著threadcreate pfofile表明了profile的類(lèi)型。

total 12 代表了此時(shí)總共有12個(gè)線(xiàn)程被創(chuàng)建。

11 代表了在這個(gè)總共有11個(gè)線(xiàn)程是在這個(gè)堆棧的代碼段上被創(chuàng)建的，注意這里后面沒(méi)有堆棧內(nèi)容，說(shuō)明runtime在創(chuàng)建線(xiàn)程時(shí)，并沒(méi)有把此時(shí)的堆棧記錄下來(lái)，原因有可能是這個(gè)線(xiàn)程是runtime自己使用的，堆棧沒(méi)有必要展示給用戶(hù)，所以干脆不記錄了，具體原因這里就不深入研究了。

上面輸出的內(nèi)容可以看到在main方法里面創(chuàng)建了一個(gè)線(xiàn)程，runtime.newm 方法內(nèi)部，runtime會(huì)啟動(dòng)一個(gè)系統(tǒng)線(xiàn)程。

使用二進(jìn)制文件查看

在代碼中開(kāi)始采集thread的信息，生成二進(jìn)制文件可以采用以下代碼，和goroutine示例代碼類(lèi)似，不同的是改變采集的指標(biāo)對(duì)象，改成了ThreadcreationProfile。

package main  
  
import (  
    "fmt"  
    "github.com/pkg/profile"    
    "time")  
  
func main() {  
    go mockGo()  
    go mockGo()  
    p := profile.Start(profile.ThreadcreationProfile,  
       profile.ProfilePath("profile"),  
       profile.NoShutdownHook)  
    p.Stop()  
}  
  
func mockGo() {  
    time.Sleep(time.Second * 3)  
    fmt.Println("獲取鎖")  
}

生成的二進(jìn)制文件通過(guò) go tool pprof -http=:8083 ../profile/threadcreation.pprof 啟動(dòng)瀏覽器窗口查看其graph，如下是線(xiàn)程的graph，圖中的堆棧信息是創(chuàng)建線(xiàn)程時(shí)的堆棧信息。

圖片

責(zé)任編輯：武曉燕來(lái)源：藍(lán)胖子的編程夢(mèng)

Golang 采集鏈接