Golang Pprof

Golang pprof指南

本篇记录 Golang Pprof 的开启、使用和解读等

Posted by LANG on October 14, 2019

开启

pprof 功能有两种开启方式，对应两种包：

net/http/pprof ：使用在 web 服务器的场景 runtime/pprof ：使用在非服务器应用程序的场景

这两个本质上是一致的，net/http/pporf 也只是在 runtime/pprof 上的一层 web 封装，通过程序的HTTP运行时提供服务，使用pprof可视化工具性能分析数据并提供期望的输出格式。

1. web方式

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

func main() {
    go http.ListenAndServe("localhost:8888", nil)
}

如果应用程序不启动http服务器，那么需要导入net/http和log包，如下所示：

go func() {
    log.Println(http.ListenAndServe("localhost:6060", nil))
}()

2. 非web方式

这种通常用于程序调优的场景，程序只是一个应用程序，跑一次就结束，想找到瓶颈点，那么通常会使用到这个方式。

import (
    "log"
    "os"
    "runtime/pprof"
)

func main() {
    // cpu pprof 文件路径
    f, err := os.Create("cpufile.pprof")
    if err != nil {
        log.Fatal(err)
    }
    // 开启 cpu pprof
    pprof.StartCPUProfile(f)
    defer pprof.StopCPUProfile()
}

使用

pprof有两种使用方式：

1. 通过访问pprof server进行诊断

通过访问pprof server来获取profile

# 追踪当前 goroutine
> curl http://localhost:19923/debug/pprof/goroutine?debug=1

# 堆内存 profile
> curl http://localhost:19923/debug/pprof/heap?debug=1

# 追踪当前goroutine的同步阻塞
> curl http://localhost:19923/debug/pprof/block?debug=1

2. 通过本地安装go tool进行pprof诊断

# cpu profile
> go tool pprof http://localhost:19923/debug/pprof/profile?seconds=30

# 堆内存 profile
> go tool pprof http://localhost:19923/debug/pprof/heap

# 追踪当前goroutine的同步阻塞
> go tool pprof http://localhost:19923/debug/pprof/block

# 开启本地图型界面，依赖graphviz
> go tool pprof -http=:8889 http://localhost:19923/debug/pprof/profile

3. 通过本地安装go tool访问profile文件进行pprof诊断

curl -o trace.out http://localhost:6060/debug/pprof/trace?seconds=5
go tool trace trace.out

curl -o heap.out http://localhost:6060/debug/pprof/heap
go tool pprof heap.out

curl -o goroutine.out http://localhost:6060/debug/pprof/goroutine
go tool pprof goroutine.out

pprof 可用诊断选项：

  • allocs：查看过去所有内存分配的样本
  • block：查看导致阻塞同步的堆栈跟踪
  • cmdline： 当前程序的命令行的完整调用路径
  • goroutine：查看当前所有运行的 goroutines 堆栈跟踪
  • heap：查看当前对象的内存分配情况
  • mutex：查看导致互斥锁的竞争持有者的堆栈跟踪
  • profile： 默认进行 30s 的 CPU Profiling，得到一个分析用的 profile 文件
  • threadcreate：查看创建新系统线程的堆栈跟踪
  • trace：CPU追踪

解析

示例：

package main

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

func main() {
	go func() {
		a := make([]string, 0, 1000000)
		sum := 0
		for {

			b := make([]int, 0, 1000000)
			time.Sleep(time.Minute)
			for _, i := range b {
				sum += i
			}
		}
		_ = a
	}()

	go func() {
		log.Println(http.ListenAndServe("localhost:6600", nil))
	}()

	for {
		time.Sleep(time.Minute)
	}
}

goroutine

profile：

goroutine profile: total 5     // goroutine 总数量
1 @ 0xca456a 0xd08aa9 0xd08978 0xd45bf8 0xd63e1e 0xd60c58 0xd619d8 0xe08a49 0xe14de5 0xec9f5f 0xd0bf21
#	0xd08aa8	syscall.SyscallN+0x108				G:/Go/go1.20.5/src/runtime/syscall_windows.go:557
#	0xd08977	syscall.Syscall9+0x77				G:/Go/go1.20.5/src/runtime/syscall_windows.go:507
#	0xd45bf7	syscall.WSARecv+0xb7				G:/Go/go1.20.5/src/syscall/zsyscall_windows.go:1295
#	0xd63e1d	internal/poll.(*FD).Read.func1+0x3d		G:/Go/go1.20.5/src/internal/poll/fd_windows.go:437
#	0xd60c57	internal/poll.execIO+0x77			G:/Go/go1.20.5/src/internal/poll/fd_windows.go:159
#	0xd619d7	internal/poll.(*FD).Read+0x2b7			G:/Go/go1.20.5/src/internal/poll/fd_windows.go:436
#	0xe08a48	net.(*netFD).Read+0x28				G:/Go/go1.20.5/src/net/fd_posix.go:55
#	0xe14de4	net.(*conn).Read+0x44				G:/Go/go1.20.5/src/net/net.go:183
#	0xec9f5e	net/http.(*connReader).backgroundRead+0x3e	G:/Go/go1.20.5/src/net/http/server.go:674

1 @ 0xccef56 0xd057e5 0xf16a75 0xf1688d 0xf1360b 0xf226e5 0xf23233 0xed13af 0xed2d49 0xed3d56 0xed0152 0xd0bf21
#	0xd057e4	runtime/pprof.runtime_goroutineProfileWithLabels+0x24	G:/Go/go1.20.5/src/runtime/mprof.go:844
#	0xf16a74	runtime/pprof.writeRuntimeProfile+0xb4			G:/Go/go1.20.5/src/runtime/pprof/pprof.go:734
#	0xf1688c	runtime/pprof.writeGoroutine+0x4c			G:/Go/go1.20.5/src/runtime/pprof/pprof.go:694
#	0xf1360a	runtime/pprof.(*Profile).WriteTo+0x14a			G:/Go/go1.20.5/src/runtime/pprof/pprof.go:329
#	0xf226e4	net/http/pprof.handler.ServeHTTP+0x4a4			G:/Go/go1.20.5/src/net/http/pprof/pprof.go:259
#	0xf23232	net/http/pprof.Index+0xf2				G:/Go/go1.20.5/src/net/http/pprof/pprof.go:376
#	0xed13ae	net/http.HandlerFunc.ServeHTTP+0x2e			G:/Go/go1.20.5/src/net/http/server.go:2122
#	0xed2d48	net/http.(*ServeMux).ServeHTTP+0x148			G:/Go/go1.20.5/src/net/http/server.go:2500
#	0xed3d55	net/http.serverHandler.ServeHTTP+0x315			G:/Go/go1.20.5/src/net/http/server.go:2936
#	0xed0151	net/http.(*conn).serve+0x611				G:/Go/go1.20.5/src/net/http/server.go:1995

1 @ 0xcdbd96 0xcd2477 0xd05be9 0xd602f2 0xd60cd7 0xd619d8 0xe08a49 0xe14de5 0xeca3d1 0xe7d77f 0xe7e30f 0xe7e567 0xe7ffd9 0xec6d9a 0xec6d9b 0xecb94a 0xecfe8b 0xd0bf21
#	0xd05be8	internal/poll.runtime_pollWait+0x88		G:/Go/go1.20.5/src/runtime/netpoll.go:306
#	0xd602f1	internal/poll.(*pollDesc).wait+0x31		G:/Go/go1.20.5/src/internal/poll/fd_poll_runtime.go:84
#	0xd60cd6	internal/poll.execIO+0xf6			G:/Go/go1.20.5/src/internal/poll/fd_windows.go:175
#	0xd619d7	internal/poll.(*FD).Read+0x2b7			G:/Go/go1.20.5/src/internal/poll/fd_windows.go:436
#	0xe08a48	net.(*netFD).Read+0x28				G:/Go/go1.20.5/src/net/fd_posix.go:55
#	0xe14de4	net.(*conn).Read+0x44				G:/Go/go1.20.5/src/net/net.go:183
#	0xeca3d0	net/http.(*connReader).Read+0x170		G:/Go/go1.20.5/src/net/http/server.go:782
#	0xe7d77e	bufio.(*Reader).fill+0xfe			G:/Go/go1.20.5/src/bufio/bufio.go:106
#	0xe7e30e	bufio.(*Reader).ReadSlice+0x2e			G:/Go/go1.20.5/src/bufio/bufio.go:372
#	0xe7e566	bufio.(*Reader).ReadLine+0x26			G:/Go/go1.20.5/src/bufio/bufio.go:401
#	0xe7ffd8	net/textproto.(*Reader).readLineSlice+0x98	G:/Go/go1.20.5/src/net/textproto/reader.go:56
#	0xec6d99	net/textproto.(*Reader).ReadLine+0xb9		G:/Go/go1.20.5/src/net/textproto/reader.go:39
#	0xec6d9a	net/http.readRequest+0xba			G:/Go/go1.20.5/src/net/http/request.go:1042
#	0xecb949	net/http.(*conn).readRequest+0x249		G:/Go/go1.20.5/src/net/http/server.go:990
#	0xecfe8a	net/http.(*conn).serve+0x34a			G:/Go/go1.20.5/src/net/http/server.go:1920

1 @ 0xcdbd96 0xcd2477 0xd05be9 0xd602f2 0xd60cd7 0xd62d6d 0xd630d6 0xe099e5 0xe1bbc5 0xe1acfd 0xed42c5 0xed3efd 0xf24425 0xf243f5 0xd0bf21
#	0xd05be8	internal/poll.runtime_pollWait+0x88	G:/Go/go1.20.5/src/runtime/netpoll.go:306
#	0xd602f1	internal/poll.(*pollDesc).wait+0x31	G:/Go/go1.20.5/src/internal/poll/fd_poll_runtime.go:84
#	0xd60cd6	internal/poll.execIO+0xf6		G:/Go/go1.20.5/src/internal/poll/fd_windows.go:175
#	0xd62d6c	internal/poll.(*FD).acceptOne+0x6c	G:/Go/go1.20.5/src/internal/poll/fd_windows.go:936
#	0xd630d5	internal/poll.(*FD).Accept+0x1d5	G:/Go/go1.20.5/src/internal/poll/fd_windows.go:970
#	0xe099e4	net.(*netFD).accept+0x64		G:/Go/go1.20.5/src/net/fd_windows.go:139
#	0xe1bbc4	net.(*TCPListener).accept+0x24		G:/Go/go1.20.5/src/net/tcpsock_posix.go:148
#	0xe1acfc	net.(*TCPListener).Accept+0x3c		G:/Go/go1.20.5/src/net/tcpsock.go:297
#	0xed42c4	net/http.(*Server).Serve+0x384		G:/Go/go1.20.5/src/net/http/server.go:3059
#	0xed3efc	net/http.(*Server).ListenAndServe+0x7c	G:/Go/go1.20.5/src/net/http/server.go:2988
#	0xf24424	net/http.ListenAndServe+0x44		G:/Go/go1.20.5/src/net/http/server.go:3242
#	0xf243f4	main.main.func1+0x14			G:/Projects/GolangProjects/awesomeProject/test/main.go:20

1 @ 0xcdbd96 0xd08c7a 0xf243cd 0xcdb977 0xd0bf21       // 每个goroutine包含调用栈，栈由下到上增长
#	0xd08c79	time.Sleep+0x139	G:/Go/go1.20.5/src/runtime/time.go:195
#	0xf243cc	main.main+0x6c		G:/Projects/GolangProjects/awesomeProject/test/main.go:24
#	0xcdb976	runtime.main+0x1f6	G:/Go/go1.20.5/src/runtime/proc.go:250

heap

profile：

heap profile: 1(inused_objects): 2688(inused_bytes) [2(allocated_objects): 16009856(allocated_bytes)] @ heap/1048576    // inused指当前使用内存，allcocated指总共分配内存
1: 2688 [1: 2688] @ 0x10c28b9 0x10c2852 0x10c283e 0x10c2d6e 0x10c19d9 0x10d81db 0x10d8d91 0x10d8d86 0x10ef8f7 0xec8d4b 0xec8c91 0xec8c91 0xebb938 0xeebf21
#	0x10c28b8	regexp/syntax.(*compiler).inst+0xd38		G:/Go/go1.20.5/src/regexp/syntax/compile.go:164
#	0x10c2851	regexp/syntax.(*compiler).cap+0xcd1		G:/Go/go1.20.5/src/regexp/syntax/compile.go:179
#	0x10c283d	regexp/syntax.(*compiler).compile+0xcbd		G:/Go/go1.20.5/src/regexp/syntax/compile.go:130
#	0x10c2d6d	regexp/syntax.(*compiler).compile+0x11ed	G:/Go/go1.20.5/src/regexp/syntax/compile.go:147
#	0x10c19d8	regexp/syntax.Compile+0x138			G:/Go/go1.20.5/src/regexp/syntax/compile.go:74
#	0x10d81da	regexp.compile+0x7a				G:/Go/go1.20.5/src/regexp/regexp.go:182
#	0x10d8d90	regexp.Compile+0x30				G:/Go/go1.20.5/src/regexp/regexp.go:137
#	0x10d8d85	regexp.MustCompile+0x25				G:/Go/go1.20.5/src/regexp/regexp.go:317
#	0x10ef8f6	internal/profile.init+0x216			G:/Go/go1.20.5/src/internal/profile/legacy_profile.go:39
#	0xec8d4a	runtime.doInit+0x12a				G:/Go/go1.20.5/src/runtime/proc.go:6507
#	0xec8c90	runtime.doInit+0x70				G:/Go/go1.20.5/src/runtime/proc.go:6484
#	0xec8c90	runtime.doInit+0x70				G:/Go/go1.20.5/src/runtime/proc.go:6484
#	0xebb937	runtime.main+0x1b7				G:/Go/go1.20.5/src/runtime/proc.go:233

0: 0 [0: 0] @ 0x10f19a5 0x10f1943 0xf4b67b 0x10f50b2 0x10f5818 0x10f5287 0x10f360b 0x11026e5 0x1103233 0x10b13af 0x10b2d49 0x10b3d56 0x10b0152 0xeebf21
#	0x10f19a4	text/tabwriter.(*Writer).append+0x184	G:/Go/go1.20.5/src/text/tabwriter/tabwriter.go:410
#	0x10f1942	text/tabwriter.(*Writer).Write+0x122	G:/Go/go1.20.5/src/text/tabwriter/tabwriter.go:533
#	0xf4b67a	fmt.Fprintf+0x9a			G:/Go/go1.20.5/src/fmt/print.go:225
#	0x10f50b1	runtime/pprof.printStackRecord+0x371	G:/Go/go1.20.5/src/runtime/pprof/pprof.go:501
#	0x10f5817	runtime/pprof.writeHeapInternal+0x4f7	G:/Go/go1.20.5/src/runtime/pprof/pprof.go:621
#	0x10f5286	runtime/pprof.writeHeap+0x26		G:/Go/go1.20.5/src/runtime/pprof/pprof.go:532
#	0x10f360a	runtime/pprof.(*Profile).WriteTo+0x14a	G:/Go/go1.20.5/src/runtime/pprof/pprof.go:329
#	0x11026e4	net/http/pprof.handler.ServeHTTP+0x4a4	G:/Go/go1.20.5/src/net/http/pprof/pprof.go:259
#	0x1103232	net/http/pprof.Index+0xf2		G:/Go/go1.20.5/src/net/http/pprof/pprof.go:376
#	0x10b13ae	net/http.HandlerFunc.ServeHTTP+0x2e	G:/Go/go1.20.5/src/net/http/server.go:2122
#	0x10b2d48	net/http.(*ServeMux).ServeHTTP+0x148	G:/Go/go1.20.5/src/net/http/server.go:2500
#	0x10b3d55	net/http.serverHandler.ServeHTTP+0x315	G:/Go/go1.20.5/src/net/http/server.go:2936
#	0x10b0151	net/http.(*conn).serve+0x611		G:/Go/go1.20.5/src/net/http/server.go:1995

0: 0 [1: 16007168] @ 0x1104427 0xeebf21     // 分配内存代码行
#	0x1104426	main.main.func1+0x26	G:/Projects/GolangProjects/awesomeProject/test/main.go:20


# runtime.MemStats
// 从OS申请的内存字节数，为以下 xxSys 的总和；虚拟空间大小，不一定全部映射成物理内存
# Sys = 30216456   
// HeapSys = HeapInuse + HeapIdle
# HeapSys = 20676608
# BuckHashSys = 1447184
# GCSys = 6482376
# OtherSys = 1233744
// Stack = StackInuse / StackSys
// StackSys基本就等于StackInuse，再加上系统线程级别的栈内存
# Stack = 294912 / 294912
// MSpan = MSpanInuse / MSpanSys
# MSpan = 64960 / 65280
// MCache = MCacheInuse / MCacheSys
# MCache = 14016 / 16352

// 还在使用的对象，以及不使用还没被GC释放的对象的字节数
# Alloc = 1625440
# HeapAlloc = 1625440
// 累计的`Alloc`
# TotalAlloc = 17695096
// 这部分内存可以被归还给OS，并且还包含了`HeapReleased`
// 可以被再次申请，甚至作为栈内存使用。
// `HeapIdle` - `HeapReleased`即GC保留的。
# HeapIdle = 18325504
// 正在使用的对象字节数
// `HeapInuse` - `HeapAlloc`是GC中保留用于快速分配内存
# HeapInuse = 2351104
// 已归还给OS的内存。没被堆再次申请的内存
# HeapReleased = 15261696

# Lookups = 0
// 累计分配的堆对象数
# Mallocs = 10718
// 累计释放的堆对象数
# Frees = 2798
// 存活的对象数
// HeapObjects = `Mallocs` - `Frees`
# HeapObjects = 7920

// GC次数
# NumGC = 1
// 应用程序强制GC次数
# NumForcedGC = 0
// GC总共占用的CPU资源。在0~1之间
# GCCPUFraction = 0
// 下次GC的触发阈值，当HeapAlloc达到这个值就要GC了
# NextGC = 4194304
// 最近一次GC的unix时间戳
# LastGC = 1702820582983157400
# DebugGC = false

# MaxRSS = 11759616
# PauseNs = [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# PauseEnd = [1702820582983157400 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]

cmd：

go tool pprof -alloc_space/-inuse_space http://localhost:6600/debug/pprof/heap

Type: alloc_space
Time: Dec 19, 2023 at 11:03pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 85.88MB, 100% of 85.88MB total
Showing top 10 nodes out of 25
      flat  flat%   sum%        cum   cum%
   83.96MB 97.77% 97.77%    83.96MB 97.77%  main.main.func1
    0.88MB  1.03% 98.80%     1.41MB  1.65%  compress/flate.NewWriter
    0.53MB  0.62% 99.42%     0.53MB  0.62%  compress/flate.(*compressor).init
    0.50MB  0.58%   100%     0.50MB  0.58%  regexp/syntax.(*compiler).inst (inline)
         0     0%   100%     1.41MB  1.65%  compress/gzip.(*Writer).Write
         0     0%   100%     0.50MB  0.58%  internal/profile.init
         0     0%   100%     1.41MB  1.65%  net/http.(*ServeMux).ServeHTTP
         0     0%   100%     1.41MB  1.65%  net/http.(*conn).serve
         0     0%   100%     1.41MB  1.65%  net/http.HandlerFunc.ServeHTTP
         0     0%   100%     1.41MB  1.65%  net/http.serverHandler.ServeHTTP
(pprof) top -cum
Showing nodes accounting for 86878.60kB, 98.80% of 87936.58kB total
Showing top 10 nodes out of 25
      flat  flat%   sum%        cum   cum%
85976.02kB 97.77% 97.77% 85976.02kB 97.77%  main.main.func1
  902.59kB  1.03% 98.80%  1447.25kB  1.65%  compress/flate.NewWriter
         0     0% 98.80%  1447.25kB  1.65%  compress/gzip.(*Writer).Write
         0     0% 98.80%  1447.25kB  1.65%  net/http.(*ServeMux).ServeHTTP
         0     0% 98.80%  1447.25kB  1.65%  net/http.(*conn).serve
         0     0% 98.80%  1447.25kB  1.65%  net/http.HandlerFunc.ServeHTTP
         0     0% 98.80%  1447.25kB  1.65%  net/http.serverHandler.ServeHTTP
         0     0% 98.80%  1447.25kB  1.65%  net/http/pprof.Index
         0     0% 98.80%  1447.25kB  1.65%  net/http/pprof.handler.ServeHTTP
         0     0% 98.80%  1447.25kB  1.65%  runtime/pprof.(*Profile).WriteTo
(pprof) list func1
Total: 85.88MB
ROUTINE ======================== main.main.func1 in G:\Projects\GolangProjects\awesomeProject\test\main.go
   83.96MB    83.96MB (flat, cum) 97.77% of Total
         .          .     19:   go func() {
   15.27MB    15.27MB     20:           a := make([]string, 0, 1000000)
         .          .     21:           sum := 0
         .          .     22:           for {
         .          .     23:
   68.70MB    68.70MB     24:                   b := make([]int, 0, 1000000)
         .          .     25:                   time.Sleep(time.Minute)
         .          .     26:                   for _, i := range b {
         .          .     27:                           sum += i
         .          .     28:                   }
         .          .     29:           }
(pprof)
  • flat：只统计当前方法的内存
  • cum：整个调用链的方法会向上累加内存

运行之后，还会生成profile文件保存在本地，后缀为 .pb.gz，此时可以使用 pprof 打开profile文件使用 graphviz 来查看图形化profile

安装 graphviz：

apt install graphviz

go tool pprof -http localhost:6700 [xxx.pb.gz]

或者直接pprof时查看图形化，此时也同样会生成profile文件保存在本地：

go tool pprof -http localhost:6700 http://localhost:6600/debug/pprof/heap

生成svg格式：

go tool pprof -inuse_space -cum -svg http://localhost:6600/debug/pprof/heap > heap_inuse.svg

cpu

cmd:

go tool pprof http://localhost:6600/debug/pprof/profile

Type: cpu
Time: Dec 20, 2023 at 12:09am (CST)
Duration: 30.14s, Total samples = 4.39s (14.57%)
(pprof) top
Showing nodes accounting for 3340ms, 76.08% of 4390ms total
Dropped 93 nodes (cum <= 21.95ms)
Showing top 10 nodes out of 84
      flat  flat%   sum%        cum   cum%
     700ms 15.95% 15.95%      700ms 15.95%  runtime.memclrNoHeapPointers
     690ms 15.72% 31.66%      690ms 15.72%  runtime.stdcall1
     680ms 15.49% 47.15%      680ms 15.49%  runtime.stdcall3
     540ms 12.30% 59.45%      610ms 13.90%  runtime.writeHeapBits.flush
     220ms  5.01% 64.46%      220ms  5.01%  runtime.stdcall2
     190ms  4.33% 68.79%      300ms  6.83%  runtime.scanobject
     100ms  2.28% 71.07%      100ms  2.28%  runtime.stdcall6
      90ms  2.05% 73.12%      110ms  2.51%  runtime.scanblock
      80ms  1.82% 74.94%       80ms  1.82%  runtime.stdcall4
      50ms  1.14% 76.08%       50ms  1.14%  runtime.(*mheap).setSpans
(pprof) top -cum
Showing nodes accounting for 0.07s, 1.59% of 4.39s total
Dropped 93 nodes (cum <= 0.02s)
Showing top 10 nodes out of 84
      flat  flat%   sum%        cum   cum%
     0.02s  0.46%  0.46%      1.90s 43.28%  runtime.systemstack
     0.01s  0.23%  0.68%      1.59s 36.22%  main.main.func1
         0     0%  0.68%      1.57s 35.76%  runtime.makeslice
     0.02s  0.46%  1.14%      1.57s 35.76%  runtime.mallocgc
         0     0%  1.14%      0.90s 20.50%  runtime.mcall
     0.02s  0.46%  1.59%      0.90s 20.50%  runtime.park_m
         0     0%  1.59%      0.87s 19.82%  runtime.schedule
         0     0%  1.59%      0.83s 18.91%  runtime.gcBgMarkWorker.func2
         0     0%  1.59%      0.82s 18.68%  runtime.gcDrain
         0     0%  1.59%      0.77s 17.54%  runtime.(*mcache).allocLarge
  • flat：只统计当前方法的CPU
  • cum：整个调用链的方法会向上累加CPU

运行之后，还会生成profile文件保存在本地，后缀为 .pb.gz，此时可以使用 pprof 打开profile文件使用 graphviz 来查看图形化profile

go tool pprof -http localhost:6700 [xxx.pb.gz]

或者直接pprof时查看图形化，此时也同样会生成profile文件保存在本地：

go tool pprof -http localhost:6700 http://localhost:6600/debug/pprof/profile

trace

trace在go1.5在之后的推出的， 它提供了指定时间内程序发生的事件的完整信息，包括:

  • 协程的创建、开始和结束
  • 协程的阻塞 – 系统调用、通道、锁
  • 网络I/O相关事件
  • 系统调用事件
  • 垃圾回收相关事件

curl -o trace.out http://localhost:6060/debug/pprof/trace?seconds=5 go tool trace trace.out

参考资料

CATALOG
    FEATURED TAGS
    Git Golang Pprof Python 性能优化 Storage Clickhouse Bigdata Victorialogs Victoriametrics 高可用