首页 > 其他分享 >万字长文讲解Golang pprof 的使用

万字长文讲解Golang pprof 的使用

时间:2024-03-07 17:58:05浏览次数:16  
标签:profile src main pprof Golang 字长 go runtime

往期好文推荐 ⭐️⭐️⭐️:

# golang pprof 监控系列(1) —— go trace 统计原理与使用

# golang pprof监控系列(2) —— memory,block,mutex 使用

# golang pprof 监控系列(3) —— memory,block,mutex 统计原理

# golang pprof 监控系列(4) —— goroutine thread 统计原理

# golang pprof 监控系列(5) —— cpu 占用率 统计原理

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

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

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

Pasted image 20240307144806.png

要么在程序中通过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/ 便会出现各种维度指标,可以点击进去查看具体的指标信息。如下所示,

Pasted image 20240307150346.png

接下来我们来分析下各个指标在 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

Pasted image 20240304155555.png

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

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

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

go tool pprof -http=:8082  cpuprofile/cpu.pprof 
火焰图分析性能问题

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

Pasted image 20240304163822.png

peek

Pasted image 20240304165203.png

除了像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个对象

Pasted image 20240306163756.png

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

Pasted image 20240306164117.png

block

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

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

runtime.SetBlockProfileRate(1)

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

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

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

标签:profile,src,main,pprof,Golang,字长,go,runtime
From: https://www.cnblogs.com/hobbybear/p/18059425

相关文章

  • Golang 执行shell命令
    Golang执行shell命令参考:golang执行shell命令大全https://saucer-man.com/backend_development/571.html1.执行命令并获得输出结果CombinedOutput()  返回standardoutputandstandarderrorfuncmain(){cmd:=exec.Command("ls","-lah")out,err:=......
  • golang 时间比对时,time.Now()与time.Parse()的使用注意
    在11:28时执行以下代码nowTime:=time.Now()t1,err:=time.Parse("2006-01-0215:04","2024-03-0708:00:00")result:=nowTime.Before(t1)本以为result应该是false,结果竟然是true。  调试下看看两者的区别发现:time.Parse()是UTC时间,无时区信息,如:time.Time(2024-0......
  • [转]Golang atomic.CompareAndSwapInt64()实例讲解
     原文: http://www.manongjc.com/detail/30-anadyrrwgsoebxp.html-------------- 在Go语言中,原子包提供lower-level原子内存,这对实现同步算法很有帮助。Go语言中的CompareAndSwapInt64()函数用于对int64值执行比较和交换操作。此函数在原子包下定义。在这里,您需要导入“syn......
  • Golang使用Goroutine实现筛素数
    //Copyright2009TheGoAuthors.Allrightsreserved.//UseofthissourcecodeisgovernedbyaBSD-style//licensethatcanbefoundintheLICENSEfile.packagemainpackagemainimport"fmt"//Sendthesequence2,3,4,...tochannel&......
  • golang进阶之接口
    目录一、接口二、为什么要使用接口三、接口的定义四、实现接口的条件五、接口类型的变量1.值接收者实现接口2.指针类型接收者实现接口3.接口进阶示例六、同一个类型实现多个接口七、多个类型实现同一个接口八、类型中的嵌套去实现接口九、接口嵌套十、空接口1.空接口的定义2.......
  • Golang(Go语言)字符串转时间格式封装以及填坑
    先看代码:packagemainimport( "fmt" "time")funcmain(){ timeStr:="2021-05-2100:00:00" utcTime,_:=time.Parse(time.DateTime,timeStr) fmt.Println(utcTime)fmt.Println(utcTime.Local())}执行结果:从这里可以看出,字符串转换为时......
  • 应用监控 eBPF 版:实现 Golang 微服务的无侵入应用监控
    作者:古琦在现代软件架构中,微服务已成为构建可扩展和灵活应用程序的流行方式。每个微服务负责应用程序的一部分功能,它们共同工作以提供完整的服务。由于微服务架构的分散特性,监控变得至关重要,有效的微服务监控是确保高可用性、可靠性和服务质量的关键组成部分,它支撑了整个系统的健......
  • golang标准库之 fmt
    目录fmt库1.获取输入(1)fmt.Scan(常用)(2)fmt.Scanln(常用)(3)fmt.Scanf2.print、println、printf输出3.Sprint(了解即可)4.Errorf(了解即可)5.格式化占位符(1)通用占位符(2)布尔型占位符(3)整型占位符(4)浮点数与复数占位符(5)字符串和[]byte占位符(6)指针占位符(7)宽度标识符(8)其他fmt库fmt包实现了......
  • golang标准库之 flag、strconv
    目录一、flag库1.flag的简单替代2.flag的参数类型3.flag参数的定义(1)flag.Type()(2)flag.TypeVar()4.flag解析命令行参数5.flag其他方法二、strconv库1.string转换为int类型2.int转换为string类型3.Parse系列函数(1)ParseBool()(2)ParseInt()(3)ParseUnit()(4)ParseFloat()(5)示例4.Fo......
  • golang标准库之 time
    目录time库1.时间类型2.时间戳(1)时间格式转化为时间戳(2)时间戳转换为时间格式3.时间间隔类型4.时间的操作(1)时间格式化(2)解析字符串类型的时间(3)时间加时间间隔(4)两个时间之差(5)时间是否相同(6)判断时间前后(7)定时器time库time库是Go语言内置的库,用来定义和操作时间、日期time.Sl......