pprof笔记，切勿转载

wwayne
2,031 阅读6分钟

pprof介绍

pprof 是golang自带的一种用于可视化和分析性能分析数据的工具

支持的模式

Report generation：报告生成

Interactive terminal use：交互式终端使用

Web interface：Web 界面

ps：一般来讲报告生成我们都是用来进行性能改造比对使用，直接上手分析还是主要以web和交互终端

能做什么

常规的性能，内存，线程/协程，CPU，堆栈...

列名 含义
falt 本函数的执行耗时
flat% flat 占 CPU 总时间的比例。程序总耗时 16.22s, Eat 的 16.19s 占了 99.82%
sum% 前面每一行的 flat 占比总和
cum 累计量。指该函数加上该函数调用的函数总耗时
cum% cum 占 CPU 总时间的比例

ps：直接上手案例分析即可

示例

示例1

package main

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

var datas []string

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

	return sData
}

func main() {
	go func() {
		for {
			Add("hello")
		}
	}()

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

首先我们能判断问题应该是出在Add函数上，接下来用pprof验证一下。

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

首先我们要用这种方式来避免go的依赖检查造成Unused import

go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10

这里由于预先知道存在的问题，所以seconds=10设置比较短，建议是稍长一点，其实这个命令就是下载一段生产/测试环境下后台的数据，然后生辰本地的profile文件

go tool pprof http://localhost:6060/debug/pprof/heap
go tool pprof http://localhost:6060/debug/pprof/goroutine
go tool pprof http://localhost:6060/debug/pprof/block
go tool pprof http://localhost:6060/debug/pprof/mutex
...

可以用一下help查看都有那些命令

(pprof) help  // 使用help打印所有可用命令
  Commands:
    callgrind        Outputs a graph in callgrind format
    comments         Output all profile comments
    disasm           Output assembly listings annotated with samples
    dot              Outputs a graph in DOT format
    eog              Visualize graph through eog
    evince           Visualize graph through evince
    gif              Outputs a graph image in GIF format
    gv               Visualize graph through gv
    kcachegrind      Visualize report in KCachegrind
    list             Output annotated source for functions matching regexp
    pdf              Outputs a graph in PDF format
    peek             Output callers/callees of functions matching regexp
    png              Outputs a graph image in PNG format
    proto            Outputs the profile in compressed protobuf format
    ps               Outputs a graph in PS format
    raw              Outputs a text representation of the raw profile
    svg              Outputs a graph in SVG format
    tags             Outputs all tags in the profile
    text             Outputs top entries in text form
    top              Outputs top entries in text form
    topproto         Outputs top entries in compressed protobuf format
    traces           Outputs all profile samples in text form
    tree             Outputs a text rendering of call graph
    web              Visualize graph through web browser
    weblist          Display annotated source in a web browser
    o/options        List options and their current values
    quit/exit/^D     Exit pprof

分析步骤（个人习惯）

  • 生成profile文件
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10
  • 用web看一下总览分析
D:\project\go\src\awesomeProject2\fabric\case>go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=10
Saved profile in C:\Users\hufan\pprof\pprof.samples.cpu.004.pb.gz
Type: cpu
Time: Jun 5, 2020 at 3:51pm (CST)
Duration: 10.10s, Total samples = 15.70s (155.38%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web

这里输入web后会出现一个web窗口，但是前提是你得安装了graphviz

这里没必要每个都看得很仔细，根据线的粗细即可，比如我们预先知道这个Add函数应该是有问题的，这里看到的确指向的也略长，也就进一步验证了我们的预设观点。

  • 再用top确认一下
(pprof) top
Showing nodes accounting for 13490ms, 85.92% of 15700ms total
Dropped 68 nodes (cum <= 78.50ms)
Showing top 10 nodes out of 55
      flat  flat%   sum%        cum   cum%
    6090ms 38.79% 38.79%     6090ms 38.79%  runtime.memclrNoHeapPointers
    2480ms 15.80% 54.59%     5510ms 35.10%  runtime.scanobject
    1340ms  8.54% 63.12%     2390ms 15.22%  runtime.findObject
    1190ms  7.58% 70.70%     1190ms  7.58%  runtime.procyield
     710ms  4.52% 75.22%      880ms  5.61%  runtime.spanOf
     590ms  3.76% 78.98%      590ms  3.76%  runtime.memmove
     350ms  2.23% 81.21%      560ms  3.57%  runtime.greyobject
     280ms  1.78% 82.99%      280ms  1.78%  runtime.heapBits.bits
     260ms  1.66% 84.65%      630ms  4.01%  runtime.wbBufFlush1
     200ms  1.27% 85.92%     8940ms 56.94%  main.Add

用list来针对性的深究哪边的问题

(pprof) list main.Add
Total: 15.70s
ROUTINE ======================== main.Add in D:\project\go\src\test\pprof\d.go
     200ms      8.94s (flat, cum) 56.94% of Total
         .          .      6:)
         .          .      7:
         .          .      8:var datas []string
         .          .      9:
         .          .     10:func Add(str string) string {
      20ms      170ms     11:   data := []byte(str)
      20ms      2.20s     12:   sData := string(data)
     160ms      6.57s     13:   datas = append(datas, sData)
         .          .     14:
         .          .     15:   return sData
         .          .     16:}
         .          .     17:
         .          .     18:func main() {
(pprof)

可以看到问题主要的地方在

datas = append(datas, sData)
  • 分析问题原因 这个很简单了，因为我们是一个for循环的append，这个datas很快就会变成不能在栈上分配的“大对象”，所以去了每次都要去堆上的话，肯定会造成问题。

示例2

import (
    "fmt"
    "net/http"
    _ "net/http/pprof"
    "os"
    "time"
)

// 运行一段时间：fatal error: runtime: out of memory
func main() {
    // 开启pprof
    go func() {
        ip := "0.0.0.0:6060"
        if err := http.ListenAndServe(ip, nil); err != nil {
            fmt.Printf("start pprof failed on %s\n", ip)
            os.Exit(1)
        }
    }()

    tick := time.Tick(time.Second / 100)
    var buf []byte
    for range tick {
        buf = append(buf, make([]byte, 1024*1024)...)
    }
}

很明显的内存泄露，这里换一个思路处理，我们取两个时间段的profile对比分析。

将上面代码运行起来，执行以下命令获取profile文件，Ctrl-D退出，1分钟后再获取1次。

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

得到两个profile文件，在windows下查找还是建议使用everything工具来操作，毕竟最好是拉到项目里来用终端分析比较方便一点。至于文件名字，你在捕获生成后会提示的。

E:\awesomeProject\practice\pprof>go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=10
Saved profile in C:\Users\Administrator\pprof\pprof.samples.cpu.001.pb.gz

生成的两个文件

pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz

按照一个001为基准来对比分析

$ go tool pprof -base pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz

File: demo2
Type: inuse_space
Time: May 14, 2019 at 2:33pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
(pprof)
(pprof) top
Showing nodes accounting for 970.34MB, 32.30% of 3003.99MB total
      flat  flat%   sum%        cum   cum%
  970.34MB 32.30% 32.30%   970.34MB 32.30%  main.main   // 看这
         0     0% 32.30%   970.34MB 32.30%  runtime.main
(pprof)
(pprof)
(pprof) list main.main
Total: 2.93GB
ROUTINE ======================== main.main in /home/ubuntu/heap/demo2.go
  970.34MB   970.34MB (flat, cum) 32.30% of Total
         .          .     20:    }()
         .          .     21:
         .          .     22:    tick := time.Tick(time.Second / 100)
         .          .     23:    var buf []byte
         .          .     24:    for range tick {
  970.34MB   970.34MB     25:        buf = append(buf, make([]byte, 1024*1024)...) // 看这
         .          .     26:    }
         .          .     27:}
         .          .     28:

问题再次确定

示例3

goroutine泄露的代码

// goroutine泄露导致内存泄露
package main

import (
    "fmt"
    "net/http"
    _ "net/http/pprof"
    "os"
    "time"
)

func main() {
    // 开启pprof
    go func() {
        ip := "0.0.0.0:6060"
        if err := http.ListenAndServe(ip, nil); err != nil {
            fmt.Printf("start pprof failed on %s\n", ip)
            os.Exit(1)
        }
    }()

    outCh := make(chan int)
    // 死代码，永不读取
    go func() {
        if false {
            <-outCh
        }
        select {}
    }()

    // 每s起100个goroutine，goroutine会阻塞，不释放内存
    tick := time.Tick(time.Second / 100)
    i := 0
    for range tick {
        i++
        fmt.Println(i)
        alloc1(outCh)
    }
}

func alloc1(outCh chan<- int) {
    go alloc2(outCh)
}

func alloc2(outCh chan<- int) {
    func() {
        defer fmt.Println("alloc-fm exit")
        // 分配内存，假用一下
        buf := make([]byte, 1024*1024*10)
        _ = len(buf)
        fmt.Println("alloc done")

        outCh <- 0 // 53行
    }()
}

步骤（可以按文件对比的方式，也可以直接按照web来动态的观察，这里采用第二种）

打开浏览器，访问

http://localhost:6060/debug/pprof/

可以看到goroutine较多，个人习惯是刷新一下窗口，会发现gorutine的增长减少状态，如果持续在很大数目的基础上还处于上升趋势，多半是因为goroutine泄露。

进入可以定位到一个具体的位置，当然这里只是一个比较上层的原因，但是给了我们分析一个入口和方向。

分析后可以发现我们的协程卡在一个地方没法释放。

每个goroutine占用2KB内存，泄露1百万goroutine至少泄露2KB * 1000000 = 2GB，还是要留意这部分的使用。

示例n

...可以自行补充

可视化pprof

这个就是针对一些生成profile来进行分析了，可视化的话我们更容易发现问题。

package main

import "testing"

const url = "https://github.com"

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

步骤

  • 获取profile文件

最直接的我们可以进行一些基准测试。

$ go test -bench=. -cpuprofile=cpu.prof
  • 分析profile文件
$ go tool pprof cpu.prof 
$ (pprof) web

pprof集成火焰图

目前版本的golang是已经将火焰图集成进来了，使用也很方便

步骤

  • 首先生成profile文件，这里不再重复
  • 打开一个web界面
go tool pprof --http=:8080 ~/Downloads/profile
  • 分析

调用顺序是从上到下，每一个块代表一个函数，越大代表占用的CPU的时间越长，也支持点进去更深入分析。

同时，我们还可以分析top等，会发现其实这个做的有点功能冗余。

golang在自定义的https服务器中启用pprof接口

这里如果不手动注册是没法使用的

package main

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

func main() {
	// 启动一个自定义mux的http服务器
	mux := http.NewServeMux()
	mux.HandleFunc("/debug/pprof/", pprof.Index)
	mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
	mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
	mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
	mux.HandleFunc("/debug/pprof/trace", pprof.Trace)

	mux.HandleFunc("/hello", func(w http.ResponseWriter, r *http.Request) {
		w.Write([]byte("hello"))
	})

	http.ListenAndServe(":6066", mux)
}

结合fabric测试

  • 开启peer和orderer的PROFILE端口服务

    • 编辑fabric-samples/first-network/base/peer-base.yaml 如下

  • 我们使用fabric-sample中的并发测试，具体如何启动使用可以参考官方文档

  • 获取docker的ipaddress，这里示例orderer

docker inspect $(docker ps | grep "orderer.example.com" | awk '{print $1}')

  • 根据ip进行性能文件的捕获，要先运行容器内的并发脚本
go tool pprof http://172.21.0.6:6060/debug/pprof/profile?seconds=10

这样就是捕获成功，我们可以直接将这个生成的性能文件拿到外部去测试。

  • 在外部终端web端查看分析
pprof --http=:8080 pprof.peer.samples.cpu.002.pb.gz

输入上面命令后会自动的弹出web界面

初始是一个Graph，我们可以看一下哪部分的调用消耗较多。也可以直接用火焰图。

top

这里的是并发的一个平均值，也就是展示的是一次调用的整个过程消耗时间和过程中的步骤占比。

小结

Golang开发重做性能分析，简单高效，这里只是介绍了最简单的一些使用方式，还有trace，benchstat等分析可以自行查找资源学习。

avatar
文章
阅读
粉丝