Go语言性能分析工具 | 青训营笔记

YanLien
213 阅读5分钟

说明

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

pprof功能简介

分析-Profile

  • 网页
  • 可视化终端

工具-Tool

  • runtime/pprof
  • net/http/pprof

展示-View

  • Top
  • 调用图-Graph
  • 火焰图-Flame Graph
  • Peek
  • 源码-Source
  • 反汇编-Disassemble

采样-Sample

  • CPU
  • 堆内存-Heap
  • 协程-Goroutine
  • 锁-Mutex
  • 阻塞-Block
  • 线程创建-ThreadCreate

在WSL2环境下，分析工具使用简单示例

终端里运行git clone便可获取示例源代码，接着编译一下源代码并运行，该示例无需担心依赖问题，程序没有任何外部依赖:

git clone https://github.com/wolfogre/go-pprof-practice.git
cd go-pprof-practice
go build
./go-pprof-practice

终端会一直输出日志，可以通过这些日志来判断程序是否在运行

go_practice.png

保持程序运行，打开浏览器访问http://localhost:6060/debug/pprof/，可以看到如下界面:

web.png

查看CPU的占用情况

通过运行go tool pprof http://localhost:6060/debug/pprof/profile命令，进入一个交互式终端，也可以通过参数 seconds 指定采样时间。 go tool pprof http://localhost:6060/debug/pprof/profile\?seconds=60，查看CPU的占用情况:

profile.png

输入top命令会对函数的CPU耗时和百分比排序后输出

cputop.png

注：flat：给定函数上运行耗时；flat%：同上的CPU运行耗时总比例；sum%：给定函数累积使用CPU总比例；cum：当前函数加上它之上的调用运行总耗时；cum%：同上的CPU运行耗时总比例。

输入list 函数名，可以列出函数最耗时的代码部分

profile_list.png

很明显，CPU占用过高是github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat造成的。

终端运行go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/profile"，在浏览器使用http://localhost:8080/ui/进行可视化分析：

web_cpu.png

堆上内存使用情况的采样信息

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

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

再一次使用 top、list 来定问问题代码：

heap.png

终端运行go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/heap"，在浏览器使用http://localhost:8080/ui/进行可视化分析：

heap_web.png

可以看到这次出问题的地方在 github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal。

内存分配情况的采样信息

运行使用pprof命令，注意这次使用的URL的结尾是allocs:

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

同样使用 top、list 来定位问题代码：

allocs.png

终端运行go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/allocs"，在浏览器使用http://localhost:8080/ui/进行可视化分析：

web_allocs.png

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

当前所有协程的堆栈信息

运行使用pprof命令，注意这次使用的URL的结尾是goroutine:

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

使用 top、list 来定位问题代码：

goroutine.png

终端运行go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/goroutine"，在浏览器使用http://localhost:8080/ui/进行可视化分析：

web_goroutine.png

可以看出问题在于 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink 在不停地创建没有实际作用的协程

锁争用情况的采样信息

运行使用pprof命令，注意这次使用的URL的结尾是mutex:

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

使用 top、list 来定位问题代码：

Mutex.png

终端运行go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/mutex"，在浏览器使用http://localhost:8080/ui/进行可视化分析：

web_mutex.png

可以看出来这问题出在 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl。但要知道，在代码中使用锁是无可非议的，并不是所有的锁都会被标记有问题。

阻塞操作情况的采样信息

运行使用pprof命令，注意这次使用的URL的结尾是block:

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

使用 top、list 来定位问题代码：

block.png

终端运行go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/block"，在浏览器使用http://localhost:8080/ui/进行可视化分析：

web_block.png

可以看到，阻塞操作位于 github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee

pprof的采样过程和原理

CPU采样

  • 采样对象：函数调用和他们占用的时间

  • 采样率：100次/秒，固定值

  • 采样时间：从手动启动到手动结束

  • 采样结果：每个函数的调用次数和占用CPU时间

  • 操作系统

    • 每10ms向进程发送一次SIGPROF信号

  • 进程

    • 每次接收到SIGPROF信号时，记录当前的调用栈

  • 写缓冲

    • 每100ms读取已经记录的调用栈并写入输出流

堆内存

  • 采样程序通过内存分配器在堆上分配和释放的内存，记录分配/释放的堆内存大小
  • 采样率：每分配512KB记录一次，可在运行开头修改，1为每次分配均记录
  • 采样时间：从程序运行开始到采样时
  • 采样指标：alloc_space, alloc_objects, inuse_space, inuse_objects
  • 计算方式：inuse_space = alloc_space - free_space

Goroutine-协程 & ThreadCreate-线程创建

  • Goroutine-协程
    • 记录所有用户发起且在运行中的goroutine(既非入口runtime开头的)runtime.main的调用栈信息
  • ThreadCreate-线程创建
    • 记录程序创建的所有系统线程的信息

Block-阻塞 & Mutex-锁

  • 阻塞操作
    • 采样阻塞操作的次数和耗时
    • 采样率：阻塞耗时超过阈值的才会被记录，1为每次阻塞均记录

锁竞争

  • 采样争抢锁的次数和耗时
  • 采样率：只记录固定比例的锁操作，1为每次加锁均记录
avatar
文章
阅读
粉丝