使用性能分析工具pprof调优实战 | 豆包MarsCode AI刷题

用户355197679256
224 阅读9分钟

2.1 简介

性能调优原则

  • 要依靠数据不是猜测
  • 要定位最大瓶颈而不是细枝末节
  • 不要过早优化
  • 不要过度优化

2.2 性能分析工具 pprof

说明

  • 希望知道应用在什么地方耗费了多少CPU、Memory
  • pprof是用于可视化和分析性能分析数据的工具

image.png

搭建pprof实践项目

  • 项目地址:github.com/wolfogre/go…

  • 该项目提前埋入一些炸弹代码，产生可观测的性能问题

    • 程序会占用2G内存；
    • 程序占用CPU最高约100%（总量按“核数” * 100%来算）；
    • 程序不涉及网络或文件读写；
    • 程序除了吃资源以外没有任何其他危险操作。

  • 也可在终端中运行go get便可获取，注意加上-d参数，避免下载后自动安装

     go get -d github.com/wolfogre/go-pprof-practice
 cd $GOPATH/src/github.com/wolfogre/go-pprof-practice

    接着编译一下这个程序并运行，你不必担心依赖问题，这个程序没有任何外部依赖。

     go build
 ./go-pprof-practice

    该项目的结构如下：

image.png

运行其中的main.go程序，运行后注意查看一下资源是否吃紧，机器能否抗的住，坚持一分钟，如果没问题，咱们再进行下一步。

main.go文件的内容如下：

package main

import (
	// 略
	_ "net/http/pprof" // 会自动注册 handler 到 http server，方便通过 http 接口获取程序运行采样报告
	// 略
)

func main() {
	// 略

	runtime.GOMAXPROCS(1) // 限制 CPU 使用数，避免过载
	runtime.SetMutexProfileFraction(1) // 开启对锁调用的跟踪
	runtime.SetBlockProfileRate(1) // 开启对阻塞操作的跟踪

	go func() {
		// 启动一个 http server，注意 pprof 相关的 handler 已经自动注册过了
		if err := http.ListenAndServe(":6060", nil); err != nil {
			log.Fatal(err)
		}
		os.Exit(0)
	}()

	// 略
}

控制台里在不停的打印日志，都是一些“猫狗虎鼠在不停地吃喝拉撒”之类的，不用细看。

2.2.1.1 排查CPU占用过高

在任务管理器中查看go-pprof-practice的资源使用情况

image.png

  • 当CPU占用的比较高时，可以使用go tool pprof命令来排查一下：
 go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=10"

等待一会儿后进入一个交互式终端

image.png

  • 输入top命令，查看CPU占用较高的调用：

image.png

上图中的数字越大占用情况越严重，可以看出是github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat造成的CPU占用过高。

并且从上图中可以看到flat与cum的值有时相同有时不同，那什么时候相同什么时候不同呢？

当flat == cum时，函数中没有调用其他函数；当flat == 0时，函数中只有其他函数的调用。

  • 输入list Eat，查看问题具体出现在代码的哪一个位置：
    • list 根据指定的正则表达式查找代码行

image.png

可以看出是第24行的一百亿次空循环花费了大量时间，

接下来有一个扩展操作，图形化显示调用栈信息，但是需要事先在机器上安装graphviz：

 brew install graphviz # for macos
 apt install graphviz # for ubuntu
 yum install graphviz # for centos

Windows操作系统则可以去官网下载.exe安装包，自行安装。

安装完成后，在上文的终端中输入web。这个命令虽然叫“web”，但它实际上是产生一个.svg文件，并用你机器中默认打开.svg的程序打开它，浏览器之类的也能打开，放心使用。

image.png

(为什么我的图跟示例中的图不一样？)

至此，这一小节使用pprof定位CPU占用的实验就结束了，在终端中输入exit就可退出pprof。

为了方便后面的实验，我们修复一下这个问题，不用太麻烦，注释掉go-pprof-practice/animal/felidae/tiger/tiger.go中的一百亿次空循环的代码即可。

 func (t *Tiger) Eat() {
     log.Println(t.Name(), "eat")
     //loop := 10000000000
     //for i := 0; i < loop; i++ {
     //  // do nothing
     //}
 }

2.2.1.2 排查内存占用过高

再次运行该代码，可以看到CPU的占用率下来了，但是内存的占用率依然很高。

image.png

我们再次运行使用 pprof 命令，注意这次使用的 URL 的结尾是 heap：

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

image.png

再次运行top命令查看谁的CPU占用率高

image.png

是github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal占用内存最高

使用list Steal查看问题具体出现在代码的哪一个位置：

image.png 可以看出，问题出现在go-pprof-practice-master\animal\muridae\mouse\mouse.go的第60行中，使用1.2CB内存。

第60行所属的方法如下：

 func (m *Mouse) Steal() {
     log.Println(m.Name(), "steal")
     max := constant.Gi
     for len(m.buffer)*constant.Mi < max {
         m.buffer = append(m.buffer, [constant.Mi]byte{})
     }
 }

可以看到，这里有个循环会一直向 m.buffer 里追加长度为 1 MiB 的数组，直到总容量到达 1 GiB 为止，且一直不释放这些内存，这就难怪会有这么高的内存占用了。

使用 web 来查看图形化展示，可以再次确认问题确实出在这里：

image.png

现在同样注释掉相关代码来解决这个问题。

 func (m *Mouse) Steal() {
     log.Println(m.Name(), "steal")
     //max := constant.Gi
     //for len(m.buffer)*constant.Mi < max {
     //  m.buffer = append(m.buffer, [constant.Mi]byte{})
     //}
 }

再次运行，查看内存占用：

image.png

可以看出mouse.go占用的内存确实少了不少，但是整体的内存怎么升上去了？？？

继续使用top、list、web命令。

image.png

mouse.go中还有一个slowBuffer在不断增加，

image.png

继续注释掉重新运行

image.png

现在看到整体使用的内存下降不少，但还是mouse.go使用的内存多

2.2.1.3 排查频繁内存回收

由于内存的申请与释放频度是需要一段时间来统计的，所有我们保证炸弹程序已经运行了几分钟之后，再运行命令：

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

再次使用go tool pprof http://localhost:6060/debug/pprof/allocs命令，再来一套top、list、web组合拳

image.png

image.png

image.png

可以看到github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run (inline)会进行毫无意义的内存申请，而且这个函数又会被频繁调用，这才导致程序不停地进行GC：

 func (d *Dog) Run() {
     log.Println(d.Name(), "run")
     _ = make([]byte, 16*constant.Mi)
 }

这里有个小插曲，你可尝试一下将 16 * constant.Mi 修改成一个较小的值，重新编译运行，会发现并不会引起频繁 GC，原因是在 golang 里，对象是使用堆内存还是栈内存，由编译器进行逃逸分析并决定，如果对象不会逃逸，便可在使用栈内存，但总有意外，就是对象的尺寸过大时，便不得不使用堆内存。所以这里设置申请 16 MiB 的内存就是为了避免编译器直接在栈上分配，如果那样得话就不会涉及到 GC 了。

我们同样注释掉问题代码，重新编译执行，可以看到这一次，程序的 GC 频度要低很多，以至于短时间内都看不到 GC 日志了：

2.2.1.4 排查协程泄露

由于 golang 自带内存回收，所以一般不会发生内存泄露。但凡事都有例外，在 golang 中，协程本身是可能泄露的，或者叫协程失控，进而导致内存泄露。

在浏览器中可以看到，有115条协程，虽然 115条并不算多，但对于这样一个小程序来说，似乎还是不正常的。为求安心，我们再次是用 pprof 来排查一下：

image.png 再次使用top、list、web流程

image.png

image.png 是wolf.go中的第34行有个休眠。

第34行内容所属方法如下所示，其在不停的创建没用的协程。

 func (w *Wolf) Drink() {
     log.Println(w.Name(), "drink")
     for i := 0; i < 10; i++ {
         go func() {
             time.Sleep(30 * time.Second)
         }()
     }
 }

可以看到，Drink 函数每次会释放 10 个协程出去，每个协程会睡眠 30 秒再退出，而 Drink 函数又会被反复调用，这才导致大量协程泄露，试想一下，如果释放出的协程会永久阻塞，那么泄露的协程数便会持续增加，内存的占用也会持续增加，那迟早是会被操作系统杀死的。

我们注释掉问题代码，重新编译运行可以看到，协程数已经降到 15条了：

image.png

2.2.1.5 排查锁的争用

到目前为止，我们已经解决这个炸弹程序的所有资源占用问题，但是事情还没有完，我们需要进一步排查那些会导致程序运行慢的性能问题，这些问题可能并不会导致资源占用，但会让程序效率低下，这同样是高性能程序所忌讳的。

我们首先想到的就是程序中是否有不合理的锁的争用，我们倒一倒，回头看看上一张图，虽然协程数已经降到 15 条，但还显示有一个 mutex 存在争用问题。

在终端中运行go tool pprof http://localhost:6060/debug/pprof/mutex

top、list、web

image.png

image.png

可以看出是go-pprof-practice-master\animal\canidae\wolf\wolf.go第58行使用到了锁，但要知道，在代码中使用锁是无可非议的，并不是所有的锁都会被标记有问题，我们看看这个有问题的锁那儿触雷了。

 func (w *Wolf) Howl() {
     log.Println(w.Name(), "howl")
 ​
     m := &sync.Mutex{}
     m.Lock()
     go func() {
         time.Sleep(time.Second)
         m.Unlock()
     }()
     m.Lock()
 }

可以看到，这个锁由主协程 Lock，并启动子协程去 Unlock，主协程会阻塞在第二次 Lock 这儿等待子协程完成任务，但由于子协程足足睡眠了一秒，导致主协程等待这个锁释放足足等了一秒钟。虽然这可能是实际的业务需要，逻辑上说得通，并不一定真的是性能瓶颈，但既然它出现在原作者写的“炸弹”里，就肯定不是什么“业务需要”啦。

所以，我们注释掉这段问题代码，重新编译执行，继续。

image.png

可以看到那一个锁没有了，协程也减少了。

2.2.1.6 排查阻塞操作(block)

我们开始排查最后一个问题。在程序中，除了锁的争用会导致阻塞之外，很多逻辑都会导致阻塞。

可以看到上图中有一个阻塞操作(block)，虽然不一定是有问题的，但我们保证程序性能，我们还是要老老实实排查确认一下才对。

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

image.png

有两个，咱们挨个看

image.png

 func (c *Cat) Live() {
     c.Eat()
     c.Drink()
     c.Shit()
     c.Pee()
     c.Climb()
     c.Sneak()
 }

Cat.go中的Live方法好像没问题，再看下一个Pee方法。

image.png

 func (c *Cat) Pee() {
     log.Println(c.Name(), "pee")
 ​
     <-time.After(time.Second)
 }

不同于睡眠一秒，这里是从一个 channel 里读数据时，发生了阻塞，直到这个 channel 在一秒后才有数据读出，这就导致程序阻塞了一秒而非睡眠了一秒。

看看web生成的图像

image.png

注释掉相关代码后再次运行

image.png

可以看到阻塞也为0。

avatar
文章
阅读
粉丝