pprof 的使用

基本介绍

pprof 是在做性能优化前的性能分析工具。

安装: go get -u github.com/google/pprof

分析工具

go tool pprof 是命令行指令,用于分析 Profiling 数据,源数据可以是 http 地址,也可以是已经 dump 下当 profile 文件;查看模式可以命令行交互模式,也可以是浏览器模式(-http 参数)。

两种应用

  • 服务型应用 _ "net/http/pprof" 包,专用于采集 web 服务 运行数据的分析。即在运行的服务中通过 API 调用取数据。
  • 工具型应用 "runtime/pprof" 包,专用于采集 应用程序 运行数据的分析。通过代码手动添加收集命令。

服务型应用场景中因为应用要一直提供服务。所以 pprof 是通过 API 访问来获取,pprof 使用了默认的 http.DefaultServeMux 挂在这些 API 接口。开发者也可以手动注册路由规则挂载 API,如 r.HandleFunc("/debug/pprof/debugopen", openFunc)

工具性应用是一个提供特定功能使用的工具,使用完就会退出进程的应用。开发者手动控制把 profile 文件保存到报告文件中。

封装了接口可以调用,如要进行 CPU Profiling,则调用 pprof.StartCPUProfile(w io.Writer) 写入到 w 中,停止时调用 StopCPUProfile();要获取内存数据,直接使用 pprof.WriteHeapProfile(w io.Writer) 函数则可。

可以做?

可以做( $host/debug/pprof/$type, $type 即下方列表的英文单词):

  • CPU 分析(profile): 你可以在 url 上用 seconds 参数指定抽样持续时间(默认 30s),你获取到概览文件后可以用 go tool pprof 命令调查这个概览
  • 内存分配(allocs): 所有内存分配的抽样
  • 阻塞(block): 堆栈跟踪导致阻塞的同步原语
  • 命令行调用(cmdline): 命令行调用的程序
  • goroutine: 当前 goroutine 的堆栈信息
  • 堆(heap): 当前活动对象内存分配的抽样,完全也可以指定 gc 参数在对堆取样前执行 GC
  • 互斥锁(mutex): 堆栈跟踪竞争状态互斥锁的持有者
  • 系统线程的创建(threadcreate): 堆栈跟踪系统新线程的创建
  • trace: 追踪当前程序的执行状况. 你可以用 seconds 参数指定抽样持续时间. 你获取到 trace 概览后可以用 go tool pprof 命令调查这个 trace

基本使用

(初学,以下暂时均以 net/http/pprof 使用为例)

  1. 编写 Demo 文件 demo.go,运行这个文件
package main

import (
    "log"
    "net/http"
    _ "net/http/pprof"
)

func main() {
    go func() {
        for {
            log.Println(Add("Hello world"))
        }
    }()

    http.ListenAndServe("0.0.0.0:6060", nil)
}

var datas []string

func Add(str string) string {
    data := []byte(str)
    sData := string(data)
    datas = append(datas, sData)

    return sData
}

通过 Web API 分析

  • 访问 http://localhost:6060/debug/pprof/ 页面,可以看到总览
  • 点击其中的链接,可以看到各部分的概览

注:网页点击一些链接会下载文件,这些文件应该是需要专用工具才能打开查看分析,如 profile;而且默认采样时长 30s

通过 dump 文件进行分析

通过 dump 文件进行分析可以在命令行中交互式分析,也可以通过浏览器进行可视化分析。

  • 通过执行命令 go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60 会进行 60s 内进行采样(默认 30s),并进入 命令行交互模式

    $ go tool pprof http://localhost:6060/debug/pprof/profile
    Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile
    Saved profile in C:\Users\xxxxxx\pprof\pprof.samples.cpu.003.pb.gz
    Type: cpu
    Time: Jun 17, 2020 at 3:25pm (CST)
    Duration: 30.14s, Total samples = 31.64s (104.96%)
    Entering interactive mode (type "help" for commands, "o" for options)
    (pprof)
    

可输入 help 查看可用命令,输入 o 查看可用选项。没多用这里就不再介绍。

CPU profile 的 top 命令

在 CPU profile 交互页面输入 topN 可以查看 top N 的概况(N 可省略,默认为 10)

(pprof) top
Showing nodes accounting for 29.92s, 94.56% of 31.64s total
Dropped 117 nodes (cum <= 0.16s)
Showing top 10 nodes out of 33
      flat  flat%   sum%        cum   cum%
    28.52s 90.14% 90.14%     28.58s 90.33%  runtime.cgocall
     0.81s  2.56% 92.70%      0.82s  2.59%  runtime.stdcall1
     0.24s  0.76% 93.46%      0.25s  0.79%  runtime.stdcall3
     0.16s  0.51% 93.96%     29.10s 91.97%  internal/poll.(*FD).writeConsole
     0.05s  0.16% 94.12%     29.28s 92.54%  internal/poll.(*FD).Write
     0.04s  0.13% 94.25%      0.18s  0.57%  runtime.findrunnable
     0.03s 0.095% 94.34%      0.18s  0.57%  runtime.mallocgc
     0.03s 0.095% 94.44%      0.25s  0.79%  runtime.mcall
     0.02s 0.063% 94.50%     29.49s 93.20%  log.(*Logger).Output
     0.02s 0.063% 94.56%     29.71s 93.90%  log.Println
(pprof)

信息:

  • 显示的节点在总共 31.64s 的抽样中,占 29.92s,比例 94.56%
  • 在 33 个样本中显示了 top 10
  • 列表解释(cum: cumulative 堆积的)
    • flat: 在给定函数上运行耗时
    • flat%: 在给定函数上运行耗时总比例
    • sum%: 给定函数 累计 使用 CPU 总比例
    • cum: 当前函数 以及包含子函数 的调用运行总耗时
    • cum%: 同上的 CPU 运行耗时总比例
    • 最后一列为函数名称

heap profile 的 top 命令

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 C:\Users\xxxxxx\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
Type: inuse_space
Time: Jun 17, 2020 at 3:52pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
(pprof) top
Showing nodes accounting for 10.04GB, 100% of 10.04GB total
      flat  flat%   sum%        cum   cum%
   10.04GB   100%   100%    10.04GB   100%  main.Add
         0     0%   100%    10.04GB   100%  main.main.func1
(pprof)

  • inuse_space: 常驻内存占用情况
  • alloc_objects: 内存临时分配情况

启用可视化界面进行分析

需要安装 graphviz,参考:Graphviz安装及简单使用

  • 方式一: go tool pprof -http=:8080 cpu.prof,通过 -http 参数
  • 方式二: go tool pprof cpu.prof,然后在交互页面输入 web [funcName] 命令(函数调用图生成 svg 文件并用浏览器查看)

看懂这些菜单中的信息很重要,你可以知道中这个页面能做到什么,本人中调查过程中就没有注意这个问题,浪费了很多时间,到后面才后知后觉。

pprof菜单项
- VIEW 看各种视图
  - Top:主要看占用内存当排名信息
  - Graph:主要看调用关系图,并且通过框框的粗细、颜色当深浅、线的实虚、以及数字信息包括执行时间和占比
  - Flame Graph:火焰图,要看宽度和深度,heap 中宽度表明内存占用大小,
  - Peek
  - Source
  - Disassemble
- SAMPLE:采样信息,包括申请对象、申请空间、占用对象、占用空间的信息
- REFINE:可以精细化视图中的信息
  - Focus:聚焦在选中元素的上下游元素
  - Ignore:忽略选中当元素,包含其后继元素
  - Hide:隐藏选中当元素,但不会隐藏其后继元素
  - Show:只显示选中的元素,不包含后继元素
  - Show from:从选中当某一个元素开始,只列出其后继元素
- CONFIG:能将当前已精细化的页面保存起来

对比两个文件差异

可以使用 go tool pprof -http=:9092 -base 0713_1544_heap 0715_1439_heap 对比两个文件,并通过浏览器打开。很实用。

火焰图🔥

火焰图,调用顺序是从上到下(有些是从下到上,如火焰一般),每一块代表一个函数,越大代表占用 CPU 时间越长。

点击块深入分析。

刨析火焰图,参考如何读懂火焰图?

  • 火焰图是对系统调用栈进行抽样调查
  • 一般采样记录信息有三个参数:采样的进程号、采样的频率(每秒采样多少次,通常 99 次)、采样持续时间
  • 如,对某 一个进程调用栈 进行采样,每秒 99 次(Hz)、持续 30s。如果这个服务器有 16 个 CPU,就能采集到 99 * 30 * 16 = 47520 个调用栈信息
  • 将调用栈信息组装成火焰图
  • 火焰图 Y 轴表示调用栈,每一个 都是一个函数。调用栈越深,火焰越高。火焰顶端是正在执行的函数,底端是父函数(有些火焰是正的,有些是倒的)
  • 火焰图 X 轴表示抽样次数。如果一个函数越宽,就表示被抽到的次数越多,执行时间越长。
  • 注意:X 轴不表示时间先后顺序,而是所有调用栈合并后,按字母顺序排列的。
  • 火焰图的颜色表示 CPU 的繁忙程度。
  • 火焰图就是看顶层那个函数最宽。若有“平顶”(plateaus),就很有可能存在性能问题。
  • 火焰图是 SVG 图(Scalable Vector Graphics 可伸缩的矢量图形参考),可以很方便得进行互动。

火焰图局限:

  • 调用栈过深时,某些系统只返回前面一部分(如前 10 层)
  • 函数名缺失时,只能用内存地址来表示(如匿名函数)

通过 test 用例也可以生产 profile 文件

编写 test 用例,demo_test.go:

package main

import "testing"

const url = "hello world"

func TestAdd(t *testing.T) {
    s := Add(url)
    if s == "" {
        t.Errorf("Test.Add error")
    }
}

func BenchmarkAdd(b *testing.B) {
    for i := 0; i < b.N; i++ {
        Add(url)
    }
}

执行测试 go test -bench=. -cpuprofile=cpu.prof 及输出:

$ go test -bench=. -cpuprofile=cpu.prof
goos: windows
goarch: amd64
pkg: awesomeProject/pprof
BenchmarkAdd-12         13364784                88.3 ns/op
PASS
ok      awesomeProject/pprof    1.828s

参数解释:

  • -bench: 通过 go help testflag 查看,按通配运行 benchmarks
  • -cpuprofile: 指定 CPU profiling 的保存文件
  • -memprofile: 指定 Memory profiling 的保存文件

结果在本目录生成了 cpu.prof 文件

参考

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 157,373评论 4 361
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 66,732评论 1 290
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 107,163评论 0 238
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 43,700评论 0 202
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,036评论 3 286
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,425评论 1 211
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,737评论 2 310
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,421评论 0 194
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,141评论 1 239
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,398评论 2 243
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,908评论 1 257
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,276评论 2 251
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,907评论 3 233
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,018评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,772评论 0 192
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,448评论 2 269
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,325评论 2 261

推荐阅读更多精彩内容

  • golang 的 pprof 是性能分析的神器,包括交互命令行和 UI 图像化的分析。主要来看看 pprof 支持...
    咔叽咔叽_阅读 17,272评论 0 4
  • 一、前言 业务方反馈引入jaeger后,cpu load飙升,无奈只能分析一波。 二、PPROF环境 pprof ...
    huiwq1990阅读 279评论 0 0
  • 原文地址:Golang 大杀器之性能剖析 PProf 前言 写了几吨代码,实现了几百个接口。功能测试也通过了,终于...
    EDDYCJY阅读 71,954评论 7 78
  • 转自:http://lihaoquan.me/2017/1/1/Profiling-and-Optimizing-...
    鲸息_Leon阅读 7,622评论 0 11
  • 久违的晴天,家长会。 家长大会开好到教室时,离放学已经没多少时间了。班主任说已经安排了三个家长分享经验。 放学铃声...
    飘雪儿5阅读 7,397评论 16 21