pprof课程实践记录 | 青训营

LiLas
102 阅读8分钟

Golang pprof 使用实践

一、前言

  1. 先克隆此地址的实验代码
  2. 查看golang pprof 实战介绍
  3. 查看Go性能分析工具
  4. 程序启动后会模拟CPU、内存占用高的程序，建议在资源充足的机器上运行

二、实验代码

2.1 main.go代码

package main

import (
	"log"
	"net/http"
	_ "net/http/pprof"
	"os"
	"runtime"
	"time"

	"github.com/wolfogre/go-pprof-practice/animal"
)

func main() {
	log.SetFlags(log.Lshortfile | log.LstdFlags)
	log.SetOutput(os.Stdout)

	runtime.GOMAXPROCS(1)
	runtime.SetMutexProfileFraction(1)
	runtime.SetBlockProfileRate(1)

	go func() {
		if err := http.ListenAndServe(":6060", nil); err != nil {
			log.Fatal(err)
		}
		os.Exit(0)
	}()

	for {
		for _, v := range animal.AllAnimals {
			v.Live()
		}
		time.Sleep(time.Second)
	}
}

其他部分代码暂时不用看，是作者设置的模拟“逻辑复杂“的问题程序，本次就利用pprof来找出问题。

2.2 运行代码

  1. 在终端编译并运行此程序：

    >go build
>./go-pprof-practice

    或者直接点击IDE的编译并运行。

    跑起来后终端会不断打印日志信息，确保你的机器运行一分钟左右还没崩溃即可继续。

    image-20230801154716322.png

  2. 保持程序运行，打开浏览器访问http://localhost:6060/debug/pprof/可以看到：

    image-20230801154917366.png

    上面的各个选项可以看到程序运行时的各种采样数据，它们的含义是：

    类型描述
    allocs内存分配情况的采样信息
    blocks阻塞操作情况的采样信息
    cmdline显示程序启动命令及参数
    goroutine当前所有协程的堆栈信息
    heap堆上内存使用情况的采样信息
    mutex锁争用情况的采样信息
    profileCPU 占用情况的采样信息
    threadcreate系统线程创建情况的采样信息
    trace程序运行跟踪信息

    实验程序的作者写的”炸弹程序“主要涉及allocs、blocks、goroutine、heap、mutex、profile方面的隐藏性能问题，本次实验就在这几个方面实际使用下pprof。

  3. 直接点进浏览器上对应的连接就可以看到对应的采样信息，如allocs查看下内存分配情况：

    image-20230801155851592.png

    可读性太差。

    因此我们需要借助go tool pprof命令来排查问题，此命令为go原生自带。

三、利用pprof排查各项问题

3.1 排查CPU占用过高问题

  1. 运行起程序，查看任务管理器

    image-20230801173453046.png

    可以看到，程序占用CPU还是很大的。

  2. 保持程序运行，在终端执行命令go tool pprof http://localhost:6060/debug/pprof/profile

    然后会出现一个交互式终端，如下图：

    image-20230801174237414.png

  3. 在交互式终端输入top命令

    image-20230801174325606.png

    默认显示了CPU占用前10的调用，会对一些耗时较少的调用函数进行过滤。

    这里我们看到/animal/felidae/tiger.(*Tiger).Eat方法占用CPU最高，达到了91.95%。

  4. 在交互式终端输入list Eat命令

    image-20230801174417049.png

    list命令可以根据指定的正则表达式查找代码行，并显示耗时高的代码行，这里发现时间大多花在了Eat()方法的for循环里。这样就定位到了问题所在的代码行！

  5. 在交互式终端输入web命令

    web命令可以用web页面可视化分析，图形化显示调用栈信息。实际是产生一个.svg文件，并调用你系统里设置的默认打开.svg的程序来打开它（我的是浏览器）。

    image-20230801174455629.png

    框越大、小箭头越粗代表耗时越长。这里也可以看出tiger.(*Tiger).Eat方法耗时最多。

    注意：需要先安装graphviz，可以访问 graphviz 官网 来找到适合自己操作系统的安装方法。

  6. 看到tiger.(*Tiger).Eat方法的代码：

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

    发现里面执行了100亿次无意义的循环，我们将循环注释掉，再编译运行该程序，执行top命令，看到此时各函数的CPU占用时间就正常了：

    image-20230801165400272.png

  7. CPU占用过高的问题解决了，在交互式终端输入exit退出pprof交互式终端。

3.2 排查内存占用过高问题

  1. 运行起程序，查看任务管理器

    image-20230801173821834.png

    image-20230801173750535.png

    可以看到CPU占用已经降下来了，但是内存占用还是非常高，因为我还开了其他后台应用，所以看起来快占满了，但是确实比运行前高了很多。

  2. 保持程序运行，在终端执行命令go tool pprof http://localhost:6060/debug/pprof/heap，这次的URL结尾是heap。

    然后继续用list、top命令查看内存占用情况

    image-20230801192402091.png

    发现问题出在github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal方法，它内存占用很高。

  3. 也可执行web命令发现问题确实在这里

    image-20230801193427988.png

  4. 看到mouse.(*Mouse).Steal方法的代码：

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

    原来是因为for循环不断向buffer追加长度1MB的byte数组，直到buffer达到1GB为止，且一直没有释放内存。将其注释掉可解决内存占用过高的问题。

3.3 排查频繁内存回收问题

频繁的GC对程序性能也有很大的影响。为了获取程序运行过程中 GC 日志，我们需要先退出实验程序，再在重新启动前赋予一个环境变量（设置GODEBUG=gctrace=1），同时为了避免其他日志的干扰，使用 grep 筛选出 GC 日志查看。

  1. linux下执行以下指令（windows上用什么命令我暂时没找到）：

    GODEBUG=gctrace=1 ./go-pprof-practice | grep gc

    打印信息如下：

    image-20230801205230213.png

    可以看到基本每隔3秒gc一次，每次从16MB清理到0MB，说明程序不断地在请求内存并很快又释放。

  2. 运行炸弹程序几分钟后再执行命令go tool pprof http://localhost:6060/debug/pprof/allocs

    但是我的linux虚拟机分配的内存太小，运行了一分钟不到就系统强制杀死进程了。这部分测试我就先不做了。

  3. 用pprof的top、list、web命令继续排查。最后问题是出在dog.(*Dog).Run方法，它里面一直在进行无意义的内存申请，申请完后面没再使用引起自动gc，而该函数又被频繁调用，因此就表现为频繁gc。

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

3.4 排查协程泄漏问题

虽然 golang 自带内存回收，一般不会发生内存泄露。但协程本身是可能泄露的，或进而可能导致内存泄露。

  1. 运行炸弹程序

    在浏览器页面可以看到起的协程数

    image-20230801211209786.png

  2. 保持程序运行，在终端执行命令go tool pprof http://localhost:6060/debug/pprof/goroutine

    同样地，top、list、web

    image-20230801211635986.png

    image-20230801211717481.png

    image-20230801211736770.png

    这个问题看web页面会比较好发现，问题在于github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink方法。

    看到这部分代码：

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

    Drink方法每次被调用都会起10个协程，每个协程sleep30秒才退出。当Drink方法被调用多次时，就导致起了很多协程，如果起的协程内部逻辑较复杂出现一直阻塞的情况，协程不能退出，内存无法释放，那么就会造成协程泄漏。

3.5 排查锁的争用问题

排查了上面的资源占用问题后，goroutine数也降下去了，但是发现存在1个mutex争用问题：

image-20230801212822419.png

  1. 保持程序运行，在终端执行命令go tool pprof http://localhost:6060/debug/pprof/mutex

    同样地，top、list、web

    image-20230801213245283.png

    image-20230801213333809.png

    可以看到，问题在于github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl方法。

  2. wolf.(*Wolf).Howl代码如下

    func (w *Wolf) Howl() {
   log.Println(w.Name(), "howl")

   m := &sync.Mutex{}
   m.Lock()
   go func() {
      time.Sleep(time.Second)
      m.Unlock()
   }()
   m.Lock()
}

    主协程先持有锁，然后启动子协程，主协程在下面的m.Lock()等待锁，但是子协程sleep了1秒才解锁，主协程才能请求到锁。这不一定是错误，可能是具体业务的需要，但在这里肯定是没必要的。pprof可以帮助我们找到可能的锁争用位置，但是具体是否真的存在问题，还需要自己去辨别。

3.6 排查阻塞操作

除了锁的争用可能导致阻塞之外，还有程序逻辑也可呢个导致阻塞。

image-20230801214345025.png

  1. 保持程序运行，在终端执行命令go tool pprof http://localhost:6060/debug/pprof/mutex

    同样地，top、list、web

    image-20230801214600636.png

    image-20230801214620166.png

    虽然Live方法也阻塞，但归根结底是由于Live方法调用了Pee方法，实际是阻塞在了Pee。

  2. cat.(*Cat).Pee代码如下

    func (c *Cat) Pee() {
	log.Println(c.Name(), "pee")

	<-time.After(time.Second)
}

    该方法里面，要从channel中读数据，但得阻塞1秒后time.After才会向它的channel中放数据，才能从channel中读到数据。

四、总结

之前在做一个lab时由于涉及到了很多锁和并发，导致很容易出现难以察觉的死锁，当时在网上搜资料时看到别人推荐用pprof分析定位阻塞。那次是我第一次接触pprof。此次借助青训营的机会比较全面地了解了pprof这一工具的强大之处，以后在学习工作中可以多多利用来debug或优化程序。

avatar
文章
阅读
粉丝