Golang pprof 性能问题分析优化和实战经验

简介: Golang pprof 性能问题分析优化和实战经验

Golang pprof 性能问题分析优化和实战经验

go pprof 中各种 profiler 介绍

Go 自带了一个 pprof 的性能优化和分析的工具,这个工具包括 cpuprof 、memprof ,并且还提供了 Lookup 功能用于获取堆状态信息、线程状态信息、 goroutine 状态信息等。官方的博客有一篇文章介绍用法:《Profiling Go Programs》[1]

CPU profiler

CPU 的主频,即 CPU 内核工作的时钟频率(CPU Clock Speed)[2],主频的基本单位是赫兹(Hz),但更多的是以兆赫兹(MHz)或吉赫兹(GHz)为单位。时钟频率的倒数即为时钟周期,时钟周期的基本单位为秒(s),但更多的是以毫秒(ms)、微妙(us)或纳秒(ns)为单位。在一个时钟周期内,CPU 会执行一条运算指令;在 1000 Hz 的 CPU 主频下,每 1毫秒可以执行一条CPU运算指令;在1 MHz的CPU主频下,每1微妙可以执行一条CPU运算指令,以此类推。

在默认情况下,Go 语言的运行时系统会以 100 Hz 的的频率对 CPU 的使用情况进行取样,也就是说每秒取样 100 次,为什么使用这个频率呢?因为 100 Hz 既足够产生有用的数据,又不至于让系统产生停顿。在启动 CPU 使用情况记录操作之后,运行时系统就会以每秒100次的频率将取样数据写入到 CPU 概要文件中,通过pprof.StopCPUProfile 函数可以把 CPU 使用情况取样的频率设置为 0 从而来停止取样操作。

Memory profiler

Go 语言运行时系统会对用户应用程序运行期间的所有的堆内存分配进行记录,不管在取样的时候堆内存已用字节数是否有增长,只要有字节被分配且数量足够,内存分析器就会对其进行取样。runtime/pprof.WriteHeapProfile[3] 里面记录了相关使用方法。

Blocking Profile

goroutine 阻塞 profiler 展示 goroutine 阻塞等待同步原语(包括定时器channel),出现在代码中哪些地方。阻塞剖析器默认没有被开启,goroutine 阻塞的情况,可以通过 pprof 工具来查看,使用 net/http/pprof, runtime/pprof包,然后手动开启,程序中调用 runtime.SetBlockProfileRate,开启阻塞剖析器,SetBlockProfileRate 控制 blocking profile 中阻塞时间的报告粒度。

goroutine 阻塞的情况要根据业务的实际应用场景去分析,如果业务场景下就是那种需要耗时很久的逻辑,那么就是正常的,比如一些异步定时处理的耗时的任务。一般下线实时请求的服务,goroutine 阻塞的情况就要特别引起重视,避免因为是阻塞而导致协程泄漏,或者因为阻塞而消耗掉过多的 CPU 时间,从而使得正常服务逐步开始响应变慢。

Goroutine Profiler

goroutine 分析器可以分析并查看到进程里面所有活跃 goroutine 的当前堆栈,这个对于线上调试尤其是是阻塞、死锁等问题会十分方便。

关于 Goroutine Profiler 的分析结果,这里需要说明一下,只有显示 “syscall" 状态的 goroutine 才会消费掉我们的操作系统级别的线程,其他的状态比如 ”io wait“ 状态的 goroutine,或者其他状态的协程都不会消费掉我们的操作系统级别的线程,”io wait“ 状态的goroutine 是依附于非阻塞的网络轮询器上的。

go pprof 相关操作和命令介绍

go tool pprof

go pprof 支持在本地运行,但是一般我们很少这样使用,更多的通过 pprof 去分析线上环境的服务情况,也就是应用程序的真实的实时情况。

pprof 工具并不是用 Go 语言编写的,而是由 Perl 语言编写的, go tool pprof 命令会分析指定的概要文件并使得我们能够以交互式的方式访问其中的信息。但是光有概要文件还不够,我们还需要概要文件中信息的来源——命令源码文件的可执行文件。毕竟,概要文件中的信息是对在运行期间的用户程序取样的结果。而可以运行的Go语言程序只能是编译命令源码文件后生成的可执行文件。比如:

$ go tool pprof cpupprof cpupprof.prof
File: cpupprof
Type: cpu
Time: Dec 6, 2019 at 10:57am (CST)
Duration: 3s, Total samples = 0
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top 10
  • • cpupprof 就是我们的应用程序的二进制程序
  • • cpupprof.prof 就是这个程序所生成的 cpu prof 文件

更详细的用法和使用示例,可以继续往下看下面的演示过程。

net/http/pprof【推荐使用】

最常见的方法是使用 net/http/pprof,在我们的代码中运行一个 http server,然后远程通过 http 的请求来访问获取到相关数据,比如可以在浏览器里输入 http://localhost:6060/debug/pprof/goroutine?debug=2,就会看到 goroutine 的一些情况

svg 矢量图

通过 pprof 工具可以生成一个 svg 的矢量图,查看 svg 矢量图可以帮助我们确认代码的执行流程和调用情况。

svg 是使用 graphviz 生成的,我一般都是用 mac 电脑,在 mac 下可以直接通过 brew install graphviz 命令来安装;其他的系统,比如 centos下,我们可以通过 yum -y install graphviz来安装。

pprof 实战验证和验证

runtime/pprof【CPU profiling】

代码示例

cpupprof.go 源文件如下:

package main
import (
    "flag"
    "log"
    "os"
    "runtime/pprof"
    "sync"
    "time"
)
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")
func main() {
    flag.Parse()
    if *cpuprofile != "" {
        f, err := os.Create(*cpuprofile)
        if err != nil {
            log.Fatal(err)
        }
        pprof.StartCPUProfile(f)
        defer pprof.StopCPUProfile()
    }
    var wg sync.WaitGroup
    wg.Add(10)
    for i := 0; i < 10; i++ {
        go work(&wg)
    }
    time.Sleep(3 * time.Second)
    wg.Wait()
}
func work(wg *sync.WaitGroup) {
    var counter int
    for i := 0; i < 1000; i++ {
        time.Sleep(time.Millisecond * 100)
        counter++
    }
    wg.Done()
}

编译和 go tool pprof 运行分析

先编译 cpupprof.go 源文件:go build cpupprof.go ,得到 cpupprof 二进制文件

然后,运行 ./cpupprof -cpuprofile=cpupprof.prof

最后,再在同一个目录,执行 go tool pprof cpupprof cpupprof.prof 开始分析:

  • • top N :表示采样时间间隔内,耗时最长的 top N
  • • top5 -cum :cum 表示按第4和第5列排序
  • • web: 表示生成 svg 图
$ go tool pprof cpupprof cpupprof.prof
File: cpupprof
Type: cpu
Time: Dec 6, 2019 at 10:57am (CST)
Duration: 1.70mins, Total samples = 340ms ( 0.33%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top 10
Showing nodes accounting for 340ms, 100% of 340ms total
Showing top 10 nodes out of 34
      flat  flat%   sum%        cum   cum%
     100ms 29.41% 29.41%      100ms 29.41%  runtime.pthread_cond_wait
      60ms 17.65% 47.06%       60ms 17.65%  runtime.nanotime
      60ms 17.65% 64.71%       60ms 17.65%  runtime.pthread_cond_signal
      50ms 14.71% 79.41%       50ms 14.71%  runtime.pthread_cond_timedwait_relative_np
      20ms  5.88% 85.29%       30ms  8.82%  runtime.notetsleep
      20ms  5.88% 91.18%       20ms  5.88%  runtime.usleep
      10ms  2.94% 94.12%       10ms  2.94%  runtime.pthread_mutex_unlock
      10ms  2.94% 97.06%      160ms 47.06%  runtime.semasleep
      10ms  2.94%   100%       10ms  2.94%  time.Sleep
         0     0%   100%       10ms  2.94%  main.work
(pprof) top5 -cum
Showing nodes accounting for 10ms, 2.94% of 340ms total
Showing top 5 nodes out of 34
      flat  flat%   sum%        cum   cum%
      10ms  2.94%  2.94%      160ms 47.06%  runtime.semasleep
         0     0%  2.94%      130ms 38.24%  runtime.mstart
         0     0%  2.94%      120ms 35.29%  runtime.mcall
         0     0%  2.94%      120ms 35.29%  runtime.park_m
         0     0%  2.94%      120ms 35.29%  runtime.schedule
(pprof) web
(pprof)


实战说明

一般而言,如果代码没有上线,那么可以在本地调试,然后我们可以本地编译、本地运行、本地调优。但是,如果代码已经上线运行,那么当然不能这样调试了,因此就需要用到 net/http/pprof包,通过 http 远程访问来调试

net/http/pprof

代码示例

package main
import (
    "flag"
    "log"
    "net/http"
    _ "net/http/pprof"
    "sync"
    "time"
)
func main() {
    flag.Parse()
    //这里实现了远程获取pprof数据的接口
    go func() {
        log.Println(http.ListenAndServe("localhost:6060", nil))
    }()
    var wg sync.WaitGroup
    wg.Add(10)
    for i := 0; i < 10; i++ {
        go work(&wg)
    }
    wg.Wait()
    // Wait to see the global run queue deplete.
    time.Sleep(3 * time.Second)
}
func work(wg *sync.WaitGroup) {
    time.Sleep(time.Second)
    mem := make([]int, 10000)
    log.Println(mem)
    var counter int
    for i := 0; i < 1e10; i++ {
        time.Sleep(time.Millisecond * 100)
        counter++
    }
    wg.Done()
}

http 访问查看和分析 pprof

通过网络访问来查看相关信息 http://localhost:6060/debug/pprof/

go tool pprof 运行分析

go tool pprof 查看 CPU 信息

go tool pprof http://localhost:6060/debug/pprof/profile 查看 CPU 信息:

$ go tool pprof http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile
Saved profile in /Users/wudebao/pprof/pprof.samples.cpu.002.pb.gz
Type: cpu
Time: Dec 6, 2019 at 11:22am (CST)
Duration: 30s, Total samples = 90ms (  0.3%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top 5
Showing nodes accounting for 90ms, 100% of 90ms total
Showing top 5 nodes out of 25
      flat  flat%   sum%        cum   cum%
      50ms 55.56% 55.56%       50ms 55.56%  runtime.pthread_cond_wait
      10ms 11.11% 66.67%       10ms 11.11%  runtime.nanotime
      10ms 11.11% 77.78%       10ms 11.11%  runtime.pthread_cond_signal
      10ms 11.11% 88.89%       10ms 11.11%  runtime.pthread_cond_timedwait_relative_np
      10ms 11.11%   100%       10ms 11.11%  runtime.usleep
(pprof) top5 -cum
Showing nodes accounting for 0, 0% of 90ms total
Showing top 5 nodes out of 25
      flat  flat%   sum%        cum   cum%
         0     0%     0%       60ms 66.67%  runtime.findrunnable
         0     0%     0%       60ms 66.67%  runtime.mcall
         0     0%     0%       60ms 66.67%  runtime.park_m
         0     0%     0%       60ms 66.67%  runtime.schedule
         0     0%     0%       60ms 66.67%  runtime.semasleep
(pprof)
(pprof)

go tool pprof 查看内存堆栈信息

go tool pprof http://localhost:6060/debug/pprof/heap 查看内存堆栈信息:

$ go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /Users/wudebao/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb.gz
Type: inuse_space
Time: Dec 6, 2019 at 11:33am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3692.74kB, 100% of 3692.74kB total
Showing top 10 nodes out of 17
      flat  flat%   sum%        cum   cum%
 1562.15kB 42.30% 42.30%  1562.15kB 42.30%  fmt.(*buffer).WriteByte
 1106.08kB 29.95% 72.26%  3180.24kB 86.12%  main.work
  512.50kB 13.88% 86.13%   512.50kB 13.88%  sync.(*Pool).pinSlow
  512.01kB 13.87%   100%   512.01kB 13.87%  reflect.packEface
         0     0%   100%  2074.16kB 56.17%  fmt.(*pp).doPrintln
         0     0%   100%  2074.16kB 56.17%  fmt.(*pp).printArg
         0     0%   100%  2074.16kB 56.17%  fmt.(*pp).printValue
         0     0%   100%  2074.16kB 56.17%  fmt.Sprintln
         0     0%   100%  2074.16kB 56.17%  log.Println
         0     0%   100%   512.50kB 13.88%  net/http.(*conn).readRequest
(pprof)
(pprof) list FindLoops
Total: 3.61MB
(pprof)

go tool pprof http://localhost:6060/debug/pprof/block

go tool pprof http://localhost:6060/debug/pprof/block 查看 goroutine blocking profile

go pprof 实战经验

常见 Profile 性能分析经验

关于 Profile 分析结果的一些经验,参考 Golang 核心开发者关于性能剖析[4]

  1. 1. 如果在 Profile 分析中,看到有大量时间花费在 runtime.mallocgc 函数中,那么我们的应用程序可能做了过多的小内存分配,并且 profile 还会告诉我们这些分配来自哪里,那么我们就可以根据这些结果来定位并优化我们的应用程序
  2. 2. 如果在 Profile 分析中,看到有大量时间花费在 channel sync.Mutex 、或者其他同步原语,或者系统组件上,那么我们的应用程序可能存在资源的竞争。这个时候,我们就需要去优化我们的代码架构,减少共享资源的访问。
  3. 3. 如果在 Profile 分析中,看到有大量时间花费在 syscall.Read/Write,那么我们的应用程序可能产生了太多小数据量读写操作,可考虑使用 bufio 来代替 os.File or net.Conn。
  4. 4. 如果在 Profile 分析中,看到有大量时间花费在 GC 上,要么是程序分配了太多的临时对象,要么是堆内存太小,导致垃圾收集操作运行频繁。

引入 net/http/pprof,暴露详细信息并采集

在我们的应用程序中,通过引入 net/http/pprof,然后可以提供详细的信息,包括堆栈信息,goroutine 数量等,这个在线上运行时,可以实时观察,并且最好能够结合 Prometheus 数据进行采集和监控。

对外暴露相关接口,示例使用如下:

// PProf
    profGroup := debugGroup.Group("/pprof")
    profGroup.GET("/", func(c *gin.Context) {
        pprof.Index(c.Writer, c.Request)
    })
    profGroup.GET("/goroutine", gin.WrapH(pprof.Handler("goroutine")))
    profGroup.GET("/block", gin.WrapH(pprof.Handler("block")))
    profGroup.GET("/heap", gin.WrapH(pprof.Handler("heap")))
    profGroup.GET("/threadcreate", gin.WrapH(pprof.Handler("threadcreate")))
    profGroup.GET("/profile", func(c *gin.Context) {
        pprof.Profile(c.Writer, c.Request)
    })
    profGroup.GET("/symbol", func(c *gin.Context) {
        pprof.Symbol(c.Writer, c.Request)
    })
    profGroup.GET("/trace", func(c *gin.Context) {
        pprof.Trace(c.Writer, c.Request)
    })

这些信息,有助于观察线上环境的运行时情况,比如 goroutine 当前数量、goroutine 有没有泄漏、内存有没有泄漏 or 暴增、CPU 最耗时的是哪个函数等。

引入 https://github.com/google/gops

gops 是由 Google 官方出品的一个命令行工具,与 ps 命令的功能类似,能够查看并诊断当前系统中 Go 程序的运行状态及内部情况。如果我们的应用程序引用了 gops 包,那么就可以针对 golang 的程序进行特定的分析,包括 CPU、MEM、 堆栈、Goroutine 、runtime、GC 等都可以搞定。

gops 和 http/pprof 我们可以任选一样来使用。

引用链接

[1] 《Profiling Go Programs》: https://blog.golang.org/profiling-go-programs

[2] CPU 的主频,即 CPU 内核工作的时钟频率(CPU Clock Speed): https://baike.baidu.com/item/%E4%B8%BB%E9%A2%91/103191

[3] runtime/pprof.WriteHeapProfile: https://golang.org/pkg/runtime/pprof/#WriteHeapProfile

[4] Golang 核心开发者关于性能剖析: https://my.oschina.net/evilunix/blog/371958


相关文章
|
1月前
|
Go
Golang生成随机数案例实战
关于如何使用Go语言生成随机数的三个案例教程。
183 91
Golang生成随机数案例实战
|
2月前
|
JSON Go 数据格式
Golang 对象深拷贝的方案以及性能比较
文章探讨了在Go语言中实现对象深拷贝的三种方法:使用gob序列化、JSON序列化和定制化拷贝,并对比了它们在性能和代码复杂度方面的优劣,建议根据具体需求选择最适合的方法。
31 0
|
5月前
|
NoSQL 测试技术 Go
【Golang】国密SM2公钥私钥序列化到redis中并加密解密实战_sm2反编(1)
【Golang】国密SM2公钥私钥序列化到redis中并加密解密实战_sm2反编(1)
|
1月前
|
Linux Go 开发工具
Golang各平台环境搭建实战
这篇文章详细介绍了如何在Windows、Linux和Mac平台上搭建Golang开发环境,包括下载和安装Go SDK、配置环境变量、安装开发工具如Visual Studio Code和Go扩展,以及如何编写和运行第一个Go程序。
53 3
|
2月前
|
NoSQL Java 测试技术
Golang内存分析工具gctrace和pprof实战
文章详细介绍了Golang的两个内存分析工具gctrace和pprof的使用方法,通过实例分析展示了如何通过gctrace跟踪GC的不同阶段耗时与内存量对比,以及如何使用pprof进行内存分析和调优。
55 0
Golang内存分析工具gctrace和pprof实战
|
2月前
|
人工智能 缓存 安全
Golang 搭建 WebSocket 应用(七) - 性能、可用性
Golang 搭建 WebSocket 应用(七) - 性能、可用性
41 1
|
2月前
|
监控 Java 测试技术
|
2月前
|
Go
golang对遍历目录操作的优化
【8月更文挑战第7天】在Golang中优化目录遍历能提升性能。可通过缓冲读取减少系统调用、使用协程并发处理大量文件、按需跳过不必要目录及仅获取所需文件信息等方式实现。示例代码展示了如何运用协程并行遍历子目录以加快处理速度。实际应用时需依据场景选择合适策略。
|
2月前
|
测试技术 Go
在Golang中优化你的代码以提高性能的5个技巧
在Golang中优化你的代码以提高性能的5个技巧
|
2月前
|
JSON Go 数据格式
Golang 对象深拷贝的方案以及性能比较
文章讨论了Golang中实现对象深拷贝的三种方案:gob序列化反序列化、json序列化反序列化和定制化拷贝,并进行了性能比较,结论是在性能要求高时推荐使用定制化拷贝,性能要求不高时可以使用gob方法,而json方法在性能和代码复杂度之间提供了一个折中方案。
83 0
下一篇
无影云桌面