性能分析

寒江蓑笠翁大约 26 分钟

性能分析

当一个程序编写完毕后,我们对它的要求不仅仅只是能运行,还希望它是一个稳定高效的应用。通过各种各样的测试,我们可以保证程序大部分的稳定性,而程序是否高效,就需要我们对其进行性能分析,在此前的内容中,性能分析的唯一手段就只能通过Benchmark来测试某一个功能单元的平均执行耗时,内存分配情况等,然而现实中对程序性能分析的需求远远不止于此,有时候我们需要分析程序整体的CPU占用,内存占用,堆分配情况,协程状态,热点代码路径等等,这是Benchmark所不能满足的。好在go工具链集成了许多性能分析工具以供开发者使用,下面就来逐一讲解。

逃逸分析

在go中,变量的内存分配是由编译器决定的,一般就分配到栈上和堆上这两个地方。如果一个本该分配到栈上的变量被分配到了堆上,那么这种情况就称之为逃逸,逃逸分析便是要分析程序中的内存分配情况,由于它是在编译期进行,所以是静态分析的一种。

提示

前往内存分配文章了解go具体是如分配内存的。

引用局部指针

package main

func main() {
	GetPerson()
}

type Person struct {
	Name string
	Mom  *Person
}

func GetPerson() Person {
	mom := Person{Name: "lili"}
	son := Person{Name: "jack", Mom: &mom}
	return son
}

GetPerson函数中创建了mom变量,由于它是函数内创建的,本来应该是将其分配到栈上,但是它被sonMom字段所引用了,并且son被作为了函数返回值返回出去,所以编译器就将其分配到了堆上。这是一个很简单的示例,所以理解起来不需要花费太多力气,但如果是一个大点的项目,代码行数有好几万,人工分析就不是那么的轻松了,为此就需要使用工具来进行逃逸分析。前面提到过内存的分配是由编译器主导的,所以逃逸分析也是由编译器来完成,使用起来十分简单,只需要执行如下命令:

$ go build -gcflags="-m -m -l"

gcflags即编译器gc的参数,

  • -m,打印出代码优化建议,同时出现两个会更加进行细节的输出
  • -l,禁用内联优化

输出如下

$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:13:2: mom escapes to heap:
./main.go:13:2:   flow: son = &mom:
./main.go:13:2:     from &mom (address-of) at ./main.go:14:35
./main.go:13:2:     from Person{...} (struct literal element) at ./main.go:14:15
./main.go:13:2:     from son := Person{...} (assign) at ./main.go:14:6
./main.go:13:2:   flow: ~r0 = son:
./main.go:13:2:     from return son (return) at ./main.go:15:2
./main.go:13:2: moved to heap: mom

编译器很明确的告诉了我们变量mom发生了逃逸,导致原因是因为返回值包含了函数内的局部指针,除了这种情况外还有其它情况可能会发生逃逸现象

::: tips

如果你对逃逸分析的细节感兴趣,可以在标准库cmd/compile/internal/escape/escape.go里面了解到更多内容。

:::

闭包引用

闭包引用了函数外的变量,那么该变量也会逃逸到堆上,这个很好理解。

package main

func main() {
	a := make([]string, 0)
	do(func() []string {
		return a
	})
}

func do(f func() []string) []string {
	return f()
}

输出

$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:10:9: f does not escape
./main.go:4:2: main capturing by value: a (addr=false assign=false width=24)
./main.go:4:11: make([]string, 0) escapes to heap:
./main.go:4:11:   flow: a = &{storage for make([]string, 0)}:
./main.go:4:11:     from make([]string, 0) (spill) at ./main.go:4:11
./main.go:4:11:     from a := make([]string, 0) (assign) at ./main.go:4:4
./main.go:4:11:   flow: ~r0 = a:
./main.go:4:11:     from return a (return) at ./main.go:6:3
./main.go:4:11: make([]string, 0) escapes to heap
./main.go:5:5: func literal does not escape

空间不足

栈空间不足时,也会发生逃逸现象,下面创建的切片申请了1<<15的容量

package main

func main() {
	_ = make([]int, 0, 1<<15)
}

输出

$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:4:10: make([]int, 0, 32768) escapes to heap:
./main.go:4:10:   flow: {heap} = &{storage for make([]int, 0, 32768)}:
./main.go:4:10:     from make([]int, 0, 32768) (too large for stack) at ./main.go:4:10
./main.go:4:10: make([]int, 0, 32768) escapes to heap

长度未知

当切片的长度是一个变量的时候,由于其长度未知,便会发生逃逸现象(map并不会)

package main

func main() {
	n := 100
	_ = make([]int, n)
}

输出

$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:5:10: make([]int, n) escapes to heap:
./main.go:5:10:   flow: {heap} = &{storage for make([]int, n)}:
./main.go:5:10:     from make([]int, n) (non-constant size) at ./main.go:5:10
./main.go:5:10: make([]int, n) escapes to heap

还有一种特殊情况便是函数参数为...any类型时也可能会发生逃逸

package main

import "fmt"

func main() {
	n := 100
	fmt.Println(n)
}

输出

$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:7:14: n escapes to heap:
./main.go:7:14:   flow: {storage for ... argument} = &{storage for n}:
./main.go:7:14:     from n (spill) at ./main.go:7:14
./main.go:7:14:     from ... argument (slice-literal-element) at ./main.go:7:13
./main.go:7:14:   flow: {heap} = {storage for ... argument}:
./main.go:7:14:     from ... argument (spill) at ./main.go:7:13
./main.go:7:14:     from fmt.Println(... argument...) (call parameter) at ./main.go:7:13
./main.go:7:13: ... argument does not escape
./main.go:7:14: n escapes to heap

我们之所以要进行逃逸分析,把内存分配控制的这么细,主要是为了减轻GC压力,不过go并不是c语言,内存分配的最终决定权依旧掌握在编译器手里,除了极端的性能要求情况下,大多数时候我们也无需太过于专注内存分配的细节,毕竟GC诞生的目的就是为了解放开发者。

小细节

对于一些引用类型,当确认以后不会再用到它时,我们可以将其置为nil,来告诉GC可以将其回收。

type Writer struct {
	buf []byte
}

func (w Writer) Close() error {
	w.buff = nil
	return nil
}

pprof

pprof(program profiling),是一个程序性能分析的利器,它会对程序运行时的数据进行部分采样,涵盖了cpu,内存,协程,锁,堆栈信息等许多方面,然后再使用工具对采样的数据进行分析并展示结果。

所以pprof的使用步骤就只有两步:

  1. 采集数据
  2. 分析结果

采集

数据采集的方式有两种,自动和手动,各有优劣。在此之前,编写一个简单的函数来模拟内存和cpu的消耗

func Do() {
	for i := 0; i < 10; i++ {
		slice := makeSlice()
		sortSlice(slice)
	}
}

func makeSlice() []int {
	var s []int
	for range 1 << 24 {
		s = append(s, rand.Int())
	}
	return s
}

func sortSlice(s []int) {
	slices.Sort(s)
}

手动

手动采集就是通过代码来控制,其优点是可控,灵活,可以自定义,直接在代码中使用pprof需要引入runtime/pprof

package main

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

func main() {
    Do()
	w, _ := os.Create("heap.pb")
	heapProfile := pprof.Lookup("heap")
	err := heapProfile.WriteTo(w, 0)
	if err != nil {
		log.Fatal(err)
	}
}

pprof.Lookup支持的参数如下面代码所示

profiles.m = map[string]*Profile{
    "goroutine":    goroutineProfile,
    "threadcreate": threadcreateProfile,
    "heap":         heapProfile,
    "allocs":       allocsProfile,
    "block":        blockProfile,
    "mutex":        mutexProfile,
}

该函数会将采集到的数据写入到指定文件中,在写入时传入的数字有以下几个含义

  • 0,写入压缩后的Protobuf数据,没有可读性
  • 1,写入文本格式的数据,能够阅读,http接口返回的就是这一种数据
  • 2,仅goroutine可用,表示打印panic风格的堆栈信息

采集cpu数据需要单独使用 pprof.StartCPUProfile函数,它需要一定的时间进行采样,且其原始数据不可读,如下所示

package main

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

func main() {
    Do()
	w, _ := os.Create("cpu.out")
	err := pprof.StartCPUProfile(w)
	if err != nil {
		log.Fatal(err)
	}
	time.Sleep(time.Second * 10)
	pprof.StopCPUProfile()
}

采集trace的数据也是同样如此

package main

import (
	"log"
	"os"
	"runtime/trace"
	"time"
)

func main() {
    Do()
	w, _ := os.Create("trace.out")
	err := trace.Start(w)
	if err != nil {
		log.Fatal(err)
	}
	time.Sleep(time.Second * 10)
	trace.Stop()
}

自动

net/http/pprof包将上面的分析函数包装成了http接口,并注册到了默认路由中,如下所示

package pprof

import ...

func init() {
    http.HandleFunc("/debug/pprof/", Index)
    http.HandleFunc("/debug/pprof/cmdline", Cmdline)
    http.HandleFunc("/debug/pprof/profile", Profile)
    http.HandleFunc("/debug/pprof/symbol", Symbol)
    http.HandleFunc("/debug/pprof/trace", Trace)
}

这使得我们可以直接一键运行pprof数据采集

package main

import (
	"net/http"
    // 记得要导入这个包
	_ "net/http/pprof"
)

func main() {
    go func(){
        http.ListenAndServe(":8080", nil)
    }
    for {
        Do()
    }
}

此时打开浏览器访问http://127.0.0.1:8080/debug/pprof,就会出现这样的页面

页面中有几个可供选择的选项,它们分别代表了

  • allocs:内存分配抽样
  • block:同步原语的阻塞跟踪
  • cmdline:当前程序的命令行调用
  • goroutine:跟踪所有的协程
  • heap:对于存活对象的内存分配抽样
  • mutex:互斥锁相关信息的跟踪
  • profile:cpu分析,会分析一段时间并下载一个文件
  • threadcreate:分析导致创建新OS线程原因
  • trace:当前程序执行情况的跟踪,同样会下载一个文件

这里的数据大多数可读性并不高,主要是拿来给工具分析用的,如下所图

具体的分析工作要留到后面再进行,除了profiletrace两个选项之外,如果你想要在网页中下载数据文件,可以将query参数debug=1去掉。也可以将这些接口集成到自己的路由中而不是使用默认路由,如下所示

package main

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

func main() {
	mux := http.NewServeMux()
	mux.HandleFunc("/trace", pprof.Trace)
	servre := &http.Server{
		Addr:    ":8080",
		Handler: mux,
	}
	servre.ListenAndServe()
}

如此一来,也能其集成到其它的web框架中,比如giniris等等。

分析

在得到了采集的数据文件后,有两种方式进行分析,命令行或网页,两者都需要借助pprof命令行工具,go默认集成该工具,所以不需要额外下载。

pprof开源地址:google/pprof: pprof is a tool for visualization and analysis of profiling data (github.com)open in new window

命令行

将此前收集到的数据文件作为参数

$ go tool pprof heap.pb

如果数据是由web采集的话,用web url替换掉文件名即可。

$ go tool pprof -http :8080 http://127.0.0.1/debug/pprof/heap

然后就会出现一个交互式的命令行

15:27:38.3266862 +0800 CST
Type: inuse_space
Time: Apr 15, 2024 at 3:27pm (CST)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

输入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
	...

在命令行中查看数据一般使用top命令,也可以用traces命令不过它的输出很冗长,top命令只是简单的看个大概。

(pprof) top 5
Showing nodes accounting for 117.49MB, 100% of 117.49MB total
      flat  flat%   sum%        cum   cum%
  117.49MB   100%   100%   117.49MB   100%  main.makeSlice (inline)
         0     0%   100%   117.49MB   100%  main.Do
         0     0%   100%   117.49MB   100%  main.main
         0     0%   100%   117.49MB   100%  runtime.main

简单介绍一些其中的一些指标(cpu同理)

  • flat,代表着当前函数所消耗的资源
  • cum,当前函数及其后续调用链所消耗的资源总和
  • flat%,flat/total
  • cum%,cum/total

我们可以很明显的看到整个调用栈的内存占用是117.49MB,由于Do函数本身什么都没做,只是调用了其它函数,所以其flat的指标是0,创建切片的事情是由makeSlice函数在负责,所以其flat指标是100%

我们可以将转换可视化的格式,pprof支持相当多的格式,比如pdf,svg,png,gif等等(需要安装Graphvizopen in new window)。

(pprof) png
Generating report in profile001.png

通过图片我们可以更加清晰的看到整个调用栈的内存情况。

通过list命令以源代码的形式查看

(pprof) list Do
Total: 117.49MB
ROUTINE ======================== main.Do in D:\WorkSpace\Code\GoLeran\golearn\example\main.go
         0   117.49MB (flat, cum)   100% of Total
         .          .     21:func Do() {
         .          .     22:   for i := 0; i < 10; i++ {
         .   117.49MB     23:           slice := makeSlice()
         .          .     24:           sortSlice(slice)
         .          .     25:   }
         .          .     26:}
         .          .     27:
         .          .     28:func makeSlice() []int {

对于图片和源代码而言,还可以用webweblist命令在浏览器中查看图片和源代码。

网页

在此之前为了数据更加多样化,修改一下模拟的函数

func Do1() {
	for i := 0; i < 10; i++ {
		slice := makeSlice()
		sortSlice(slice)
	}
}

func Do2() {
	for i := 0; i < 10; i++ {
		slice := makeSlice()
		sortSlice(slice)
	}
}

func makeSlice() []int {
	var s []int
	for range 1 << 12 {
		s = append(s, rand.Int())
	}
	return s
}

func sortSlice(s []int) {
	slices.Sort(s)
}

网页分析可以可视化结果,免去了我们手动操作命令行,在使用网页分析时,只需执行如下命令

$ go tool pprof -http :8080 heap.pb

如果数据是由web采集的话,将web url替换掉文件名即可

$ go tool pprof -http :8080 http://127.0.0.1:9090/debug/pprof/heap
$ go tool pprof -http :8080 http://127.0.0.1:9090/debug/pprof/profile
$ go tool pprof -http :8080 http://127.0.0.1:9090/debug/pprof/goroutine

提示

关于如何分析数据,前往pprof: How to read the graphopen in new window了解更多

网页中总共有6个可查看的项

  • Top,同命令top
  • Graph,直线图
  • Flame Graph,火焰图
  • Peek,
  • Source,查看源代码
  • Disassemble,反汇编查看

对于内存而言四个维度可以分析

  • alloc_objects:目前已分配的所有对象数量,包括已释放
  • alloc_spcae:目前为止已分配的所有内存空间,包括已释放
  • inuse_objects:正在使用的对象数量
  • inuse_space:正在使用的内存空间
内存分析图
内存分析图

上图最下方的白色叶子节点代表着不同大小的对象占用。

cpu分析图
cpu分析图

关于折线图,有几个点要注意

  • 块的颜色越深,占用越高,线越粗,占用越高
  • 实线代表着直接调用,虚线代表着略过了一些调用链。
内存火焰图
内存火焰图
cpu火焰图
cpu火焰图

对于火焰图而言,从上往下看是调用链,从左往右看是cum的占用百分比。

trace

pprof主要负责分析程序的资源占用,而trace更适合跟踪程序的运行细节,它与前者的数据文件互不兼容,由go tool trace命令来完成相关的分析工作。

如果是手动采集的数据,可以将文件名作为参数

$ go tool trace trace.out

如果是自动采集,也是同样的道理

$ curl http://127.0.0.1:8080/debug/pprof/trace > trace.out && go tool trace trace.out

执行后会开启一个web server

2024/04/15 17:15:40 Preparing trace for viewer...
2024/04/15 17:15:40 Splitting trace for viewer...
2024/04/15 17:15:40 Opening browser. Trace viewer is listening on http://127.0.0.1:51805

打开后页面大概如下所示

这里面主要包含了以下几个部分,这些数据要看懂还挺不容易的。

  • Event timelines for running goroutines

    • trace by proc:显示每一时刻在该处理器上运行的协程时间线

    • trace by thread:显示每一时刻在OS线程上运行的协程时间线

    • Goroutine analysis:展示每组主函数的协程相关统计信息

  • Profiles

    • Network blocking profile: 因网络IO而阻塞的协程信息
    • Synchronization blocking profile:因同步原语而阻塞的协程信息
    • Syscall profile:因系统调用而阻塞的协程信息
  • User-defined tasks and regions

    • User-defined tasks:用户定义任务的相关协程信息
    • User-defined regions:用户定义代码区域的相关协程信息
  • Garbage collection metrics

    • Minimum mutator utilization:展示最近GC的最大耗时