β

使用 pprof 和 Flame-Graph 调试 Golang 应用

The UPYUN Engineering Blog 79 阅读

前言

最近用 Golang 实现了一个日志搜集上报程序(内部称 logger 项目),线上灰度测试过程发现 logger 占用 CPU 非常高(80% - 100%)。而此项目之前就在线上使用,用于消费 NSQ 任务, CPU 占用一直在 1%,最近的修改只是添加了基于磁盘队列的生产者消费者服务,生产者使用 go-gin 实现了一个 httpserver,接收数据后写入磁盘队列;消费者为单个 goroutine 循环 POST 数据。而 httpserver 压力不大(小于 100 QPS),不至于占用如此高的 CPU,大致 review 代码后未发现异常,借助 pprof flame-graph 来分析定位问题。

pprof

pprof 我理解是 program profile(即程序性能剖析之意),Golang 提供的两个官方包 runtime/pprof net/http/pprof 能方便的采集程序运行的堆栈、goroutine、内存分配和占用、io 等信息的 .prof 文件,然后可以使用 go tool pprof 分析 .prof 文件。两个包的作用是一样的,只是使用方式的差异。

runtime/pprof

如果程序为非 httpserver 类型,使用此方式;在 main 函数中嵌入如下代码:

import "runtime/pprof"

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile `file`")
var memprofile = flag.String("memprofile", "", "write memory profile to `file`")

func main() {
    flag.Parse()
    if *cpuprofile != "" {
        f, err := os.Create(*cpuprofile)
        if err != nil {
            log.Fatal("could not create CPU profile: ", err)
        }
        if err := pprof.StartCPUProfile(f); err != nil {
            log.Fatal("could not start CPU profile: ", err)
        }
        defer pprof.StopCPUProfile()
    }

    // ... rest of the program ...

    if *memprofile != "" {
        f, err := os.Create(*memprofile)
        if err != nil {
            log.Fatal("could not create memory profile: ", err)
        }
        runtime.GC() // get up-to-date statistics
        if err := pprof.WriteHeapProfile(f); err != nil {
            log.Fatal("could not write memory profile: ", err)
        }
        f.Close()
    }
}

运行程序

./logger -cpuprofile cpu.prof -memprofile mem.prof

可以得到 cpu.prof 和 mem.prof 文件,使用 go tool pprof 分析。

go tool pprof logger cpu.prof
go tool pprof logger mem.prof

net/http/pprof

如果程序为 httpserver 类型, 则只需要导入该包:

import _ "net/http/pprof"

如果 httpserver 使用 go-gin 包,而不是使用默认的 http 包启动,则需要手动添加 /debug/pprof 对应的 handler,github 有 封装好的模版 :

import "github.com/DeanThompson/ginpprof"
...
router := gin.Default()
ginpprof.Wrap(router)
...

导入包重新编译程序后运行,在浏览器中访问 http://host:port/debug/pprof 可以看到如下信息,这里 host port 是程序绑定的 host port ,例如我自己的 logger 程序,访问如下地址:

http://127.0.0.1:4500/debug/pprof/

/debug/pprof/

profiles:
	block
	goroutine
	heap
	mutex
	threadcreate

full goroutine stack dump

点击对应的 profile 可以查看具体信息,通过浏览器查看的数据不能直观反映程序性能问题, go tool pprof 命令行工具提供了丰富的工具集:

查看 heap 信息

go tool pprof http://127.0.0.1:4500/debug/pprof/heap

查看 30s 的 CPU 采样信息

go tool pprof http://127.0.0.1:4500/debug/pprof/profile

其他功能使用参见 官方 net/http/pprof 库

pprof CPU 分析

采集 profile 数据之后,可以分析 CPU 热点代码。 执行下面命令:

go tool pprof http://127.0.0.1:4500/debug/pprof/profile

会采集 30s 的 profile 数据,之后进入终端交互模式,输入 top 指令。

~ # go tool pprof http://127.0.0.1:4500/debug/pprof/profile
Fetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/profile
Saved profile in /home/vagrant/pprof/pprof.logger.samples.cpu.012.pb.gz
File: logger
Type: cpu
Time: Jan 19, 2018 at 2:01pm (CST)
Duration: 30s, Total samples = 390ms ( 1.30%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 360ms, 92.31% of 390ms total
Showing top 10 nodes out of 74
      flat  flat%   sum%        cum   cum%
ms 30.77% 30.77%      180ms 46.15%  compress/flate.(*compressor).findMatch /usr/local/go/src/compress/flate/deflate.go
ms 25.64% 56.41%      310ms 79.49%  compress/flate.(*compressor).deflate /usr/local/go/src/compress/flate/deflate.go
ms 15.38% 71.79%       60ms 15.38%  compress/flate.matchLen /usr/local/go/src/compress/flate/deflate.go
ms  5.13% 76.92%       20ms  5.13%  compress/flate.(*huffmanBitWriter).indexTokens /usr/local/go/src/compress/flate/huffman_bit_writer.go
ms  2.56% 79.49%       10ms  2.56%  compress/flate.(*huffmanBitWriter).writeTokens /usr/local/go/src/compress/flate/huffman_bit_writer.go
ms  2.56% 82.05%       10ms  2.56%  hash/adler32.update /usr/local/go/src/hash/adler32/adler32.go
ms  2.56% 84.62%       10ms  2.56%  runtime.futex /usr/local/go/src/runtime/sys_linux_amd64.s
ms  2.56% 87.18%       10ms  2.56%  runtime.memclrNoHeapPointers /usr/local/go/src/runtime/memclr_amd64.s
ms  2.56% 89.74%       10ms  2.56%  runtime.pcvalue /usr/local/go/src/runtime/symtab.go
ms  2.56% 92.31%       10ms  2.56%  runtime.runqput /usr/local/go/src/runtime/runtime2.go
(pprof)

从统计可以 top5 操作全是数据压缩操作, logger 程序本身开启了压缩等级为 9 的 gzip 压缩,如果希望减少压缩 CPU 占用,可以调整压缩等级。

pprof mem 分析

同时 pprof 也支持内存相关数据分析

--inuse_space 分析常驻内存

go tool pprof -alloc_space http://127.0.0.1:4500/debug/pprof/heap
~ # go tool pprof -alloc_space http://127.0.0.1:4500/debug/pprof/heap
Fetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/heap
Saved profile in /home/vagrant/pprof/pprof.logger.alloc_objects.alloc_space.inuse_objects.inuse_space.006.pb.gz
File: logger
Type: alloc_space
Time: Jan 19, 2018 at 2:21pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 47204.90MB, 99.16% of 47606.01MB total
Dropped 230 nodes (cum <= 238.03MB)
Showing top 10 nodes out of 39
      flat  flat%   sum%        cum   cum%
0.79MB 59.43% 59.43% 28290.79MB 59.43%  bytes.makeSlice /usr/local/go/src/bytes/buffer.go
.78MB 18.29% 77.72% 10082.12MB 21.18%  compress/flate.NewWriter /usr/local/go/src/compress/flate/deflate.go
.74MB 17.98% 95.70%  8559.74MB 17.98%  github.com/nsqio/go-diskqueue.(*diskQueue).readOne /home/vagrant/go/src/github.com/nsqio/go-diskqueue/diskqueue.go
.78MB  2.82% 98.52%  1343.78MB  2.82%  compress/flate.(*compressor).init /usr/local/go/src/compress/flate/deflate.go
.81MB  0.63% 99.15%   298.81MB  0.63%  github.com/nsqio/go-nsq.ReadResponse /home/vagrant/go/src/github.com/nsqio/go-nsq/protocol.go
MB 0.0042% 99.15% 12097.28MB 25.41%  main.(*PostPublisher).Publish /home/vagrant/logger/src/handler.go
.50MB 0.0032% 99.15% 26358.53MB 55.37%  io/ioutil.readAll /usr/local/go/src/io/ioutil/ioutil.go
MB 0.0021% 99.16% 26378.74MB 55.41%  github.com/gin-gonic/gin.LoggerWithWriter.func1 /home/vagrant/go/src/github.com/gin-gonic/gin/logger.go
.50MB 0.0011% 99.16% 26434.42MB 55.53%  net/http.(*conn).serve /usr/local/go/src/net/http/server.go
     0% 99.16% 26357.03MB 55.36%  bytes.(*Buffer).ReadFrom /usr/local/go/src/bytes/buffer.go
(pprof)

--alloc_objects 分析临时内存

 go tool pprof -inuse_space http://127.0.0.1:4500/debug/pprof/heap
~ # go tool pprof -inuse_space http://127.0.0.1:4500/debug/pprof/heap
Fetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/heap
Saved profile in /home/vagrant/pprof/pprof.logger.alloc_objects.alloc_space.inuse_objects.inuse_space.007.pb.gz
File: logger
Type: inuse_space
Time: Jan 19, 2018 at 2:24pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 20441.23kB, 100% of 20441.23kB total
Showing top 10 nodes out of 35
      flat  flat%   sum%        cum   cum%
1.75kB 88.41% 88.41% 18071.75kB 88.41%  bytes.makeSlice /usr/local/go/src/bytes/buffer.go
.27kB  3.99% 92.40%   815.27kB  3.99%  github.com/nsqio/go-diskqueue.(*diskQueue).readOne /home/vagrant/go/src/github.com/nsqio/go-diskqueue/diskqueue.go
.17kB  2.58% 94.98%   528.17kB  2.58%  regexp.(*bitState).reset /usr/local/go/src/regexp/backtrack.go
kB  2.51% 97.50%      514kB  2.51%  net/http.newBufioWriterSize /usr/local/go/src/bufio/bufio.go
.05kB  2.50%   100%   512.05kB  2.50%  net/http.(*persistConn).roundTrip /usr/local/go/src/net/http/transport.go
     0%   100%   528.17kB  2.58%  _/home/vagrant/logger/src/parser.ParserLogForMarco /home/vagrant/logger/src/parser/parser.go
     0%   100%   528.17kB  2.58%  bytes.(*Buffer).ReadFrom /usr/local/go/src/bytes/buffer.go
     0%   100% 17543.58kB 85.82%  bytes.(*Buffer).Write /usr/local/go/src/bytes/buffer.go
     0%   100% 17543.58kB 85.82%  bytes.(*Buffer).grow /usr/local/go/src/bytes/buffer.go
     0%   100%   528.17kB  2.58%  github.com/gin-gonic/gin.(*Context).Next /home/vagrant/go/src/github.com/gin-gonic/gin/context.go
(pprof)

通过常驻内存和临时内存分配 top 值,可以查看当前程序的内存占用情况和热点内存使用的代码,结合代码分析热点代码是否存在 bug、是否有优化的空间。

go-torch

通过上面的 go tool pprof 工具和 top 指令,我们能定位出程序的热点代码,但缺乏对程序运行情况的整体感知,能不能有类似 火焰图 的效果让我们对整个堆栈统计信息有个一目了然的效果呢?这里要感谢 uber 开源的工具 go-torch ,能让我们将 profile 信息转换成火焰图,具体安装和使用过程见项目的介绍。

安装好 go-torch 后,运行

go-torch -u http://127.0.0.1:4500

生成 CPU 火焰图

CPU 火焰图

从图中能一眼看到 publish 函数中的压缩操作占了 70% 左右的 CPU。

CPU 火焰图

而 gin httpserver 只占用了 2% 左右的 CPU, 和我们使用 go tool pprof 的 top 命令分析的结果一致。

默认情况下 go-torch 采集的是 CPU 的 profile, 这里介绍下 mem 火焰图的采集。

inuse_space 火焰图

go-torch -inuse_space http://127.0.0.1:4500/debug/pprof/heap --colors=mem

火焰图

alloc_space 火焰图

go-torch -alloc_space http://127.0.0.1:4500/debug/pprof/heap --colors=mem

火焰图

logger 100% CPU 分析

前面介绍了 go tool pprof 和火焰图的使用方法,这里使用火焰图复现 logger 100% CPU 问题。

先看现象, 用 wrk 压测 logger

wrk -t1 -c100 -d30 --script=post.lua 'http://127.0.0.1:4500/marco/log'

查看 CPU 占用情况

CPU

采集 30s 的 CPU profile 火焰图

火焰图

图中红色标记部分 startSink 函数中 runtime.selectgo 消耗了大量 CPU, 而 runtime.selectgo 上面只有 runtime.sellock runtime.selunlock 两个操作,即大量 CPU 耗费在 select 操作上,火焰图呈秃顶状态,即瓶颈所在。

查看 startSink 实现

    for {
        if exit == true {
            return
        }

        if moveforward {
            fakeRead = readChan
        } else {
            fakeRead = nil
        }

        select {
        case read := <-fakeRead:
            count++
            buf.Write(read)
        case <-done:
            DiskQueue.Close()
            exit = true
        default:
            //pass
        }

        if count == GlobalConf.CntBatch || exit == true {
            hostPoolResponse := pool.Get()
            addr := hostPoolResponse.Host()
            err := handler.Publish(fmt.Sprintf("%s%s", addr, SinkConf.Uri), buf.Bytes())
            hostPoolResponse.Mark(err)

            if err != nil {
                Log.Error("%s", err.Error())
                moveforward = false
                time.Sleep(1 * time.Second)
                continue
            } else {
                moveforward = true
            }

            buf.Reset()
            count = 0
        }
    }

本希望通过 moveforward 来控制 fakeRead 是否取值,而如果 fakeRead 为 nil 时, 整个 select 会一直阻塞,所以加上了 default 操作,让 select 变成非阻塞,但因为一直没有读取内容,count 没有增加而不会触发 sleep 操作。 最终导致非阻塞的 select 一直空转循环,类似一个空 while 循环,占用了大量 CPU

优化

改用其他方法实现这部分逻辑,这里不再贴出来了,重在分享发现问题的过程,改进后的火焰图在前面已给出。

总结

Golang 应用通常只要能编译通过,很少有运行时问题;而当应用遇到高CPU 、高内存占用或者作为 http 服务端响应时间长,QPS 上不去等,且不能 code review 解决时,可以尝试使用 pprof Flame-Graph 来分析定位问题,有奇效。当然 Golang 程序的调试及调优还有很多方法,比如直接结合 go test benchmark 通过测用例分析热点代码、使用 go pprof 分析汇编代码等。

作者:The UPYUN Engineering Blog
Information from UPYUN's engineering team about our technology, tools and events.
原文地址:使用 pprof 和 Flame-Graph 调试 Golang 应用, 感谢原作者分享。

发表评论