万字长文讲解 Golang pprof 的使用-51CTO.COM

大家好，我是蓝胖子，说到golang的性能分析，不得不提的就是其自身拥有的pprof，它提供了从cpu，内存，阻塞情况，协程，线程，乃至程序运行轨迹trace的分析，可以说相当强大了。

今天我将会用较长的篇幅阐述应该如何使用pprof工具来对cpu，内存，阻塞情况，协程，线程这几个维度去进行分析。

其实总结出来Golang pprof的使用方式，可以用下面的思维导图来表示。

图片

要么在程序中通过http接口的方式暴露相应的pprof的采集控制界面，要么就是在程序中通过代码开启对应指标的采集样本功能，采集一段时间的样本后生成二进制文件，最后通过 go tool pprof 命令去对样本的数据进行分析。

分析的方式也有两种，

通过命令行开启一个交互终端
通过浏览器将二进制文件的信息展示出来

我们可以通过下述的代码通过http接口的方式暴露相应的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)  
}

接着访问下http://localhost:8080/debug/pprof/ 便会出现各种维度指标，可以点击进去查看具体的指标信息。如下所示：

图片

接下来我们来分析下各个指标在 http接口或者生成的二进制文件输出的各种信息究竟代表什么含义。

在下面的分析中我会分别的从http接口暴露指标的方式和二进制文件的方式分别介绍如何看懂各种指标的输出信息。

cpu

cpu在http接口暴露的分析界面中有个profile的链接，点击后，应用程序会采集30s的cpu运行信息后然后生成一个二进制文件，所以本质上对cpu的分析都是通过一个二进制文件进行的。

除了上述提到http接口暴露出cpu指标外，我们还可以通过下面的代码，在程序中显示的开启cpu指标的采集。在这个例子中，我通过busyCpu 方法不断的进行加法运算来模拟频繁的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  
}

启动终端分析

在得到二进制文件后，我们可以使用如下命令来启动一个交互终端来分析cpu的使用情况。

go tool  pprof cpuprofile/cpu.pprof

输入top命令得到如下结果：

(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

每个列的含义如下:

flat：函数自身的运行耗时（排除了子函数的调用耗时）

flat%：flat运行耗时占用总的采集样本的时间和的比例，这里所有节点运行的flat时间和为200ms。

sum%：命令行返回结果中函数自身和其之上的函数运行的flat时间占所有采集样本时间总和的比例。

cum：当前函数和其子函数的调用耗时总的运行时间

cum%：cum耗时占总的采集样本的时间和的比例。

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

在命令行中可以输入svg，来输出cpu性能剖析的profile 图。

(pprof) svg 
Generating report in profile001.svg

图片

图中显示了函数的调用关系，函数框中显示了函数自身的运行时长flat和其自身及其子函数运行时长cum，箭头上的时间则是其子函数的cum运行时长，时间越大，箭头越粗。

将二进制文件信息输出到浏览器上

可以通过如下命令来启动浏览器查看cpu使用情况，

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

火焰图分析性能问题

通过web界面，我们除了按刚才的top和调用耗时图像外，甚至还能通过火焰图的方式，来查看cpu调用耗时，火焰图上，函数的调用顺序是从上往下，函数占用cpu越长，那么在火焰图上的区块就会越大。火焰图中显示的是cum值。

图片

peek

图片

除了像top那样输出函数的耗时情况，还会输出调用函数和被调用函数，调用顺序从上到下。

source

Pasted image 20240304175712.png

在web界面可以通过source视图去查看函数节点的耗时以及它的子调用函数中耗时的地方，第一栏时间是flat耗时，第二栏时间是cum耗时。耗时百分比是cum耗时占样本总和的百分比。

内存

http接口暴露的控制台查看

通过点击heap或者allocs 链接可以查看内存的分配情况，它们的输出都是一致的。

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

下面来讲下网页输出内容的含义：

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

输出的第一行含义分别是:

7 代表当前活跃的对象个数

5536 代表当前活跃对象占用的字节数

110 代表所有(包含历史的对象)对象个数

2178080 代表所有对象(包含历史的对象)占用的对象字节数

1048576 控制了内存采样的频率，1048576 是两倍的内存采样频率的大小，默认采样频率是512kb 即平均每512kb就会采样一次，注意这个值512kb不是绝对的达到512kb就会进行采样，而是从一段时间内的采样来看的一个平均值。

接下来就是函数调用堆栈信息，来看第一行。

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

从左往右看：

2 代表在该函数栈上当前活跃的对象个数

2304 代表在该函数栈上当前活跃的对象所占用的字节数

方括号内的2 代表在该函数栈上所有(包含历史的对象)对象个数

方括号内的2304 代表在该函数栈上所有(包含历史的对象)对象所占用的字节数

然后是栈上pc寄存器的值。再往后就是具体的栈函数名信息了。

通过二进制文件查看

我们可以使用如下代码生成一个关于内存使用情况的二进制profile文件，下述代码中我用 allocMem 函数不断对一个字节数组进行append操作来模拟内存不断增大的情况。

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

生成的二进制文件，和cpu分析一致，可以通过启动交互终端或者web浏览器去进行查看，所以启动终端的方式我这里就暂时略去了，讲讲不同点，针对于内存，pprof在web 浏览器界面提供了几个维度去分析。

inuse_space: 正在使用，尚未释放的空间

inuse_object: 正在使用，尚未释放的对象

alloc_space: 所有分配的空间，包含已释放的

alloc_objects: 所有分配的对象，包含已释放的

拿inuse_object举例，性能剖析图是这样的，箭头显示了正在使用的对象个数，其中 main.allocMem函数自身有一个4MB多的对象，其子函数有4个对象。

图片

我们可以根据source 选项也能得到同样的分析结果。

图片

block

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

但是block通常是关闭的，需要通过下面代码进行开启。

runtime.SetBlockProfileRate(1)

其中,SetBlockProfileRate 的参数名为rate，rate不同，对block事件的采样频率不同。

1 代表始终对阻塞事件进行采样
<= 0 代表关闭阻塞事件的采样
除了上述两种情况，SetBlockProfileRate 的参数传递的将会是一个纳秒值。

如果阻塞的时间大于了rate值则直接进行采样，如果阻塞的时间小于rate，那么阻塞事件将会有(阻塞时间)/rate 的可能性被采集到。

📢📢📢 注意下block事件的记录时机为获取锁资源或者channel 资源时，进行记录，也就是发生在lock函数中。

http接口暴露的控制台查看

通过点击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 是为这个profile文本信息取的名字，总之中文翻译是争用。

cycles/second 是cpu时钟每秒钟的周期数，用它来表示时间也是为了更精确，其实你可以发现在我的机器上每秒是10的9次方个周期，换算成纳秒就是1ns一个周期时间了。

接着的180001216583 是阻塞的周期数，其实周期就是cputicks，那么180001216583除以 cycles/second 即1000000000得到的就是阻塞的秒数了。

接着 1 代表阻塞的次数。

无论是阻塞周期时长还是次数，都是一个累加值，即在相同的地方阻塞会导致这个值变大，并且次数会增加。剩下的部分就是函数堆栈信息了。

使用二进制文件查看

可以通过如下代码生成block的二进制文件，通过在主协程中使用lock方法后，不释放锁资源，启动子协程，让子协程同样使用lock方法模拟系统阻塞的情况。

import (  
    "fmt"  
    "github.com/pkg/profile"   
    "runtime"    
    "sync"    
    "time")  
  
/*  
*  
每次程序锁阻塞发生时，select 阻塞，channel通道阻塞,  
wait group 产生阻塞时就会记录一次阻塞行为  
*/  
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文件，同样可以通过命令行和web浏览器的方式进行查看。

这里我直接采样浏览器的方式浏览。

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

block提供了两个维度去观察阻塞事件，contention 发生阻塞的事件个数，delay 发生阻塞的时间。

contention 生成的profile图如下，可以看到发生阻塞的函数是main.mockBlock ，其自身包括其调用子函数的阻塞次数是2次。

图片

delay生成的profile 图如下所示，main.mockBlock其自身包括其调用子函数的阻塞时间是4s。

图片

📢📢📢 无论是阻塞次数还是阻塞时间，如果同一个函数发生了阻塞，那么次数和阻塞时间都会累加上去。

使用阻塞时间/阻塞次数能得到平均每次阻塞多长时间。

mutex

mutex 记录的是持有锁的时间，注意下它和block的区别，block记录的是在获取锁之前阻塞的时间。并且block还可以记录channel。

mutex 的采集默认情况下也是关闭的，需要用以下代码进行开启。

runtime.SetMutexProfileFraction(1)

其中,SetMutexProfileFraction 的参数名为rate，rate不同，对block事件的采样频率不同。

1 代表始终对持有锁事件进行采样
= 0 代表关闭阻塞事件的采样
< 0 将会把当前的rate值读取出来
> 1 将会有1/rate 的持有锁事件被采集

http接口暴露的控制台查看

通过点击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文本信息的名称了，同样也和block一样，采用cpu周期数计时，但是多了一个sampling period ，这个就是我们设置的采用频率。

接下来的数据都和block类似，180001727833就是锁持有的周期， 1为解锁的次数。然后是解锁的堆栈信息。

使用二进制文件查看

我们可以通过如下代码生成mutex的二进制文件，模拟阻塞的情况和block一致，代码不同的点是将样本采集的对象从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提供了两个维度去观察阻塞事件，contention 发生持有锁的事件个数，delay 持有锁的时间。

以下是contention 维度的图，可以看到在main方法中进行中持有了一次锁，在mockBlock方法中也持有了一次锁。

图片

通过delay 维度可以发现main方法以及其子调用函数，持有锁的时间一共是2s。

图片

goroutine

http接口暴露的控制台查看

点击控制界面的goroutine链接，我们会看到在程序中goroutine正在执行的函数堆栈信息，界面如下：

图片

首先地址栏 /debug/pprof/goroutine?debug= 1 代表这是在访问goroutine指标信息，debug =1 代表访问的内容将会以文本可读的形式展现出来。 debug=0 则是会下载一个goroutine指标信息的二进制文件。 debug = 2 将会把当前所有协程的堆栈信息以文本可读形式展示在网页上。如下图所示:

图片

debug =2 时的如上图所示，41代表协程的id，方括号内running代表了协程的状态是运行中，接着就是该协程此时的堆栈信息了。

让我们再回到debug = 1的分析上面去，刚才分析完了地址栏里的debug参数，接着，我们看输出的第一行。

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 表明了这个profile的类型。

total 6 代表此时一共有6个协程。

接着是下面一行，1 代表了在这个堆栈上，只有一个协程在执行。但其实在计算出数字1时，并不仅仅按堆栈去做区分，还依据了协程labels值，也就是协程的堆栈和lebels标签值共同构成了一个key，而数字1就是在遍历所有协程信息时，对相同key进行累加计数得来的。

我们可以通过下面的方式为协程设置labels。

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

通过上述代码，我可以为当前协程设置了两个标签值，分别是name和age，设置label值之后，再来看debug=1后的网页输出，可以发现设置的labels出现了。

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

而数字1之后，就是协程正在执行的函数堆栈信息了。

使用二进制文件查看

我们可以通过如下代码生成profile的二进制文件，在下述代码中，我生成了两个协程，然后开启对goroutine指标的采集。

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二进制文件后，查看goroutine 方式也和其他profile指标一致，这里我直接放上通过web浏览器查看的graph。显示的堆栈信息为当前程序中协程正在执行的堆栈，可以看到main.mockGo 函数中有两个协程在执行这个方法，main方法中一个协程在执行。

图片

thread

http接口暴露的控制台查看

介绍完goroutine指标的输出信息后，再来看看threadcreate 线程创建指标的输出信息。先来看下在控制台中通过点击thread链接看到的输出。

图片

老规矩，先看地址栏，debug=1代表输出的是文本可读的信息，threadcreate 就没有debug=2的特别输出了，debug=0时同样也会下载一个可供go tool pprof分析的二进制文件。

接着threadcreate pfofile表明了profile的类型。

total 12 代表了此时总共有12个线程被创建。

11 代表了在这个总共有11个线程是在这个堆栈的代码段上被创建的，注意这里后面没有堆栈内容，说明runtime在创建线程时，并没有把此时的堆栈记录下来，原因有可能是这个线程是runtime自己使用的，堆栈没有必要展示给用户，所以干脆不记录了，具体原因这里就不深入研究了。

上面输出的内容可以看到在main方法里面创建了一个线程，runtime.newm 方法内部，runtime会启动一个系统线程。

使用二进制文件查看

在代码中开始采集thread的信息，生成二进制文件可以采用以下代码，和goroutine示例代码类似，不同的是改变采集的指标对象，改成了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("获取锁")  
}

生成的二进制文件通过 go tool pprof -http=:8083 ../profile/threadcreation.pprof 启动浏览器窗口查看其graph，如下是线程的graph，图中的堆栈信息是创建线程时的堆栈信息。

图片