本文使用pprof工具调查CPU性能瓶颈，介绍怎么看调用图，火焰图来定位到CPU瓶颈；如何排查goroutine/内存泄漏；如何追查锁竞争频繁的代码。

pprof采集

可以采取两种方式采集，一种是适合长期运行的程序，比如代理软件，web服务等等：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
package main

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

func main() {
	go func() {
		_ = http.ListenAndServe("localhost:6060", nil)
	}()

	// block forever
	select {}
}

访问http://localhost:6060/debug/pprof/可以看到下面的界面：

pprof web页面

对于短期运行的程序可以用下面的代码生成cpu profile：

1
2
3
4
cpuFile, _ := os.Create("cpu.pprof")
pprof.StartCPUProfile(cpuFile) // 开始CPU采样
defer pprof.StopCPUProfile()   // 程序结束时停止采样，统计一段时间的cpu采样结果
// do something

生成heap profile:

1
2
heapFile, _ := os.Create("heap.pprof")
pprof.WriteHeapProfile(heapFile) // 可以在进程进行的任意时刻写入当前时刻瞬间的heap分配快照信息

goroutine泄漏

goroutine页面包含了每种调用栈和它的数量，一般来说，看到只增不减的调用栈路就得怀疑这条调用栈里面是不是有地方卡住了。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
package main

import (
	"fmt"
	"time"

	"net/http"
	_ "net/http/pprof"
)

func main() {
	go func() {
		_ = http.ListenAndServe("localhost:6060", nil)
	}()

	for {
		go func() {
			m := make(map[string]string)
			fmt.Println(m)
			select {}
		}()
		time.Sleep(time.Second)
	}
}

访问http://localhost:6060/debug/pprof/goroutine?debug=2可以看到：

pprof goroutine页面

内存泄漏

下面的代码明显有内存泄漏：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
package main

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

var block = make(chan struct{})

func main() {
	go func() {
		_ = http.ListenAndServe("localhost:6060", nil)
	}()

	go func() {
		time.Sleep(time.Minute)
	}()

	for {
		go func() {
			buf := make([]byte, 2*1024*1024-1000)
			// 触碰每个 4KiB page，强制变成 resident memory
			for i := 0; i < len(buf); i += 4096 {
				buf[i] = 1
			}
			fmt.Println("goroutine")
			<-block
			// runtime.KeepAlive(x) 的语义是把参数标记为在该
			// 调用点仍然 reachable，保证对象不会在该点之前被释放。
			runtime.KeepAlive(buf)
		}()

		time.Sleep(time.Second)
	}
}

pprof heap展示了某条调用链路产生的堆对象数量和字节数：

pprof heap页面

关注这部分内容:

1
2
3
4
5
// 当前存活对象数: 当前存活字节数 [累计分配对象数: 累计分配字节数]

heap profile: 2: 4194304 [2: 4194304] @ heap/1048576
2: 4194304 [2: 4194304] @ 0x74e643 0x45f4f1
#	0x74e642	main.main.func3+0x42	/home/markity/Documents/Blog/code/perf/memleak/main.go:24

上面的heap profile主要用来分析堆内存分配。熟悉Go内存模型的同学应该知道，Go编译器会在编译期间做逃逸分析：如果编译器无法证明某个对象只在当前栈帧内安全使用，或者该对象不适合放在栈上，它就可能被分配到堆上。也就是说，Go程序员通常不需要手动管理栈和堆，但在做性能分析、GC分析和pprof排查时，仍然需要理解这些概念。

那么问题来了：为什么上面分配的变量从代码语义上看并没有明显逃逸，但仍然能被heap profile看到？原因是它的backing array太大了。对于make([]T, n)创建的slice来说，slice变量本身只是一个很小的header，包含data pointer、len、cap；真正占空间的是backing array。这个backing array能否放在栈上，不只取决于逃逸分析，还取决于n是否编译期可知、对象大小是否超过编译器允许的栈分配阈值等。如果对象太大，编译器会选择把它放到堆上，即使它从源码语义上看并不会跨函数返回继续使用。

栈上不适合放太大的对象，原因也比较直接。在C/C++这类语言中，线程栈通常有固定上限，具体大小取决于平台和配置；如果栈空间耗尽，就会出现stack overflow。Go的goroutine栈则是动态增长的，初始栈很小，不够时runtime会扩容。但栈扩容并不是免费的：它可能需要分配新的栈空间，并把旧栈内容复制过去。因此，把大对象放在栈上会增加栈扩容和拷贝成本。

另外，GC成本也要考虑。GC从root出发做可达性分析，root包括goroutine栈、全局变量等。如果栈帧或全局变量里有大量指针，例如var arr [1_000_000]*Object，GC就需要扫描大量指针槽位。类似地，如果对象之间形成了很大的可达对象图，mark阶段也会有更多工作要做。这里真正影响扫描成本的主要是“可扫描指针数量”和“live object graph的规模”，而不是对象的字节数本身。比如[]byte的backing array虽然可能很大，但它不包含指针，GC不需要把其中每个字节都当作指针去扫描。

综上，可以得到几个结论：

  • slice变量本身只是一个很小的header，包含data pointer、len、cap。这个header作为局部变量时通常可以放在栈上，甚至被优化到寄存器里。make([]T, n)创建的backing array放在栈上还是堆上，不只取决于逃逸分析，还取决于n是否编译期可知、对象大小是否超过编译器允许的栈分配阈值等。这个决策主要发生在编译期。
  • 对于map、channel这类引用类型，局部变量本身通常只是一个很小的引用值；真正承载状态的数据结构，例如map的hmap/buckets、channel的hchan/buffer，通常由runtime在堆上分配和管理。
  • GC root主要包括goroutine栈、全局变量等。Go GC会从这些root出发，通过三色标记等机制追踪可达对象。如果root中有大量指针，或者可达对象图本身很大，GC的mark/scan工作量就会上升，从而占用更多CPU。
  • Go扫描栈时不是盲扫整块栈内存，也不是看到一个机器字大小的值就当指针。正常情况下它是精确扫描：编译器在编译期生成栈帧的指针位图，runtime在GC时按这些位图找出哪些栈槽是活跃指针。

最后可以讨论下如何解决根集合过大的问题，可以看看下面的业务场景：

1
2
3
4
5
6
7
8
9
type User struct {
    UserName string
    Password string
} 

// UserName->User struct mapping
var UserMap map[string]*User

// 上面是一个全局变量，存储大量数据

在上面的业务场景中，我们用一个map存储了大量数据，UserMap是一个根对象，GC扫描每个kv一个个往下做可达性分析，这里主要扫描的是UserMap内的string key和*User value。string实际上是一个string header，算一个指针，指向底层真实的数据；*User本身就是一个指针，指向一个堆User对象，并且它下面还有两个string(记得它们是string header，看起来就和指针一样)。所以如果有100个kv，一次gc基本上要扫描约400个指针槽。

优化方法：

  1. 使用map[string]User，这样实际上可以理解为User下面的两个string header指针被直接放在map bucket里面，少了一层指针，现在只用扫描300次。
  2. User内部用UserId uint64这样的数值类型，少用指针或者其它引用类型。
  3. 把User编码成json，UserMap变成map[string]string，这样只用扫描200次了。
  4. 如果有些内容长度固定或者一定小于某个长度，使用数组把字段弄成一个值Password [32]byte，这样就规避指针扫描了。
  5. 从根源上解决做冷热分离，把不太活跃的用户淘汰到文件上，内存里存少一点，但是这其实是在逃避我们上面所讨论的问题。
  6. 数据挂外面去，比如使用boltdb，leveldb。或者直接使用freecache、bigcache库，它们就是专门用来解决cache场景下large gc root问题的，如果使用这种cache它会比map[string]string更狠，直接干到几乎0GC。

内存分配次数与GC Busy

敲下面命令进入当前内存分配次数的火焰图(一个快照，刷新不会变化)：

1
go tool pprof -http=:8080 -alloc_objects http://localhost:6060/debug/pprof/allocs

pprof alloc flame页面

火焰图聚合了同一条调用栈内存分配次数的累积数量信息，进程运行期间它只增不减。最右上角显示77865(100%)，root节点代表整个进程，它累积创建过77865个对象；如果把鼠标放在其它节点，可以分别看到那函数里面分配的对象数目和总占比。

这个图适合定位谁在频繁制造堆对象，寻找gc压力来源。如果想要上首这个内存分配次数火焰图可以使用下面这段代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
package main

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

var out [][]byte

func main() {
	go func() {
		err := http.ListenAndServe("localhost:6060", nil)
		if err != nil {
			panic(err)
		}
	}()

	go func() {
		for {
			fmt.Println(len(out))
            time.Sleep(time.Second)
		}
	}()

	for {
		buf := make([]byte, 500)
		buf[0] = 1
		out = append(out, buf)
		time.Sleep(time.Millisecond)
	}
}

cpu火焰图 - 调用栈维度分析

运行下面的代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
package main

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

func main() {
	go func() {
		err := http.ListenAndServe("localhost:6060", nil)
		if err != nil {
			panic(err)
		}
	}()

	go func() {
		for {
		}
	}()

	select {}
}

使用命令采集30s火焰图信息，30s后打开web页面：

1
2
# 这里指定了./main是因为我们想看哪个地方cpu useage大，需要把二进制给它
go tool pprof -http=:8080 ./main http://localhost:6060/debug/pprof/profile?seconds=30

结果如下:

pprof cpu flame页面

可以轻易的看到main.main.func2是占据最多cpu时间的的地方，右键它点击Show source code就能看到具体代码行数了：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
main.main.func2
/home/markity/Documents/Blog/code/perf/cpubusy/main.go

  Total:      29.97s     29.99s (flat, cum)   100%
      1        850ms      850ms           package main 
      2            .          .            
      3            .          .           import ( 
      4            .          .           	"net/http" 
      5            .          .           	_ "net/http/pprof" 
      6            .          .           ) 
      7            .          .            
      8            .          .           func main() { 
      9            .          .           	go func() { 
     10            .          .           		err := http.ListenAndServe("localhost:6060", nil) 
     11            .          .           		if err != nil { 
     12            .          .           			panic(err) 
     13            .          .           		} 
     14            .          .           	}() 
     15            .          .            
     16            .          .           	go func() { 
     17       29.12s     29.14s           		for { 
     18            .          .           		} 
     19            .          .           	}() 
     20            .          .            
     21            .          .           	select {} 
     22            .          .           }

轻易的就能看到它绝大多数时间都在for循环上，flat是真的花在这个函数内部的时间，cum是这个函数总的耗时，这里虽然没调用其它函数，但是可能在中间发生了runtime抢占，做了其它事情，不精确也不必深究。

cpu调用图 - 函数/调用关系维度分析

和生成火焰图一样的命令打开刚才的web ui，点击上面的VIEW，切换到graph，可以看到调用图，我上面给的代码调用图太简单了，我生成一个复杂一点的。下面是一个http代理程序server端的call graph：

pprof cpu graph页面

可以很清晰的看到CPU时间耗时最大的函数是Syscall6，但是进程运行了30s，但是最大的cpu瓶颈也才是320s的Syscall6，这是一个很典型的IO密集的程序，没有需要特别优化CPU耗时的地方。

这里Syscall6所耗的时间涉及很多udp/tcp的read write的系统调用耗时，包括进入内核，内核世纪执行该syscall，内核返回到用户态的整段时间。

mutex busy

Go默认不开启mutex profine，需要手动开启：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
package main

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

var mu sync.Mutex

func main() {
	runtime.SetMutexProfileFraction(1)

	go func() {
		err := http.ListenAndServe("localhost:6060", nil)
		if err != nil {
			panic(err)
		}
	}()

	go func() {
		for {
			mu.Lock()
			mu.Unlock()
		}
	}()

	go func() {
		for {
			mu.Lock()
			mu.Unlock()
		}
	}()

	select {}
}

抓取到的信息如下：

pprof mutex页面