6.2.2 性能分析
工程师在进行代码优化前，首先要做的就是对代码充分分析。代码分析是一个动态的过程，需要结合各种数值来了解程序运行的细节。为了更方便地分析代码，Go语言提供了runtime/pprof标准库。
prof是profile的缩写，其含义就是性能分析报告，所以该标准包的主要作用就是生成性能分析报告。
工程师可以通过命令go tool pprof --help来了解相关用法。代码分析都是直接或间接地使用runtime/pprof包。
注意
runtime/pprof是比较底层的包，常用于代码分析。不过在后面要讲的Web编程中，一般使用net/http/pprof标准包，其底层也是runtime/pprof，第9章会进行介绍。
要使用pprof包分析性能，首先要对产生性能问题的原因有一定的认识，这样在采集数据的时候也可以有的放矢，一般有以下几个常见原因：
▪CPU占有率高，高负荷运转，要找到是执行哪个函数时出现这种情况的。
▪goroutine在死锁状态，没有运行，但是占用了资源。
▪垃圾回收占用时间。
针对这些情况，可以收集CPU的执行数据，pprof会不停采样，然后找出高度占用CPU的函数。在生成.prof文件后，可以通过go tool pprof文件进行分析。
在runtime/pprof包内提供了如下主要的接口：
//堆栈分析，可以分析内存的使用情况 func WriteHeapProfile(w io.Writer) error //CPU分析 func StartCPUProfile(w io.Writer) error func StopCPUProfile()
在使用的时候将文件指针传入，然后数据会写入文件中，运行结束后再使用上面提到的go tool pprof命令进行分析即可。
下面来看一个示例，这样可以比较直观地感受pprof的使用方法：
book/ch06/6.2/profile.go
1. package main
2.
3. import (
4. "log"
5. "os"
6. "runtime"
7. "runtime/pprof"
8. "time"
9. )
10.
11. var ch4cpu chan uint64
12. var chTimer chan struct{}
13. var memMap map[int]interface{}
14.
15. func init(){
16. ch4cpu = make(chan uint64, 10000)
17. chTimer = make(chan struct{}, 20)
18. memMap = make (map[int]interface{})
19. }
20. func main() {
21. c, err := os.Create("/Users/liujinliang/projects/go/src/ljl/book/
ch06/6.2/cpu_profile.prof")
22. if err != nil {
23. log.Fatal(err)
24. }
25.
26. defer c.Close()
27.
28. m1, err := os.Create("/Users/liujinliang/projects/go/src/ljl/book/
ch06/6.2/mem_profile1.prof")
29. if err != nil {
30. log.Fatal(err)
31. }
32.
33. m2, err := os.Create("/Users/liujinliang/projects/go/src/ljl/book/
ch06/6.2/mem_profile2.prof")
34. if err != nil {
35. log.Fatal(err)
36. }
37.
38. m3, err := os.Create("/Users/liujinliang/projects/go/src/ljl/book/
ch06/6.2/mem_profile3.prof")
39. if err != nil {
40. log.Fatal(err)
41. }
42.
43. m4, err := os.Create("/Users/liujinliang/projects/go/src/ljl/book/
ch06/6.2/mem_profile4.prof")
44. if err != nil {
45. log.Fatal(err)
46. }
47.
48. defer m1.Close()
49. defer m2.Close()
50. defer m3.Close()
51. defer m4.Close()
52.
53. pprof.StartCPUProfile(c)
54. defer pprof.StopCPUProfile()
55.
56. memMap[1]= runMEMTest()
57.
58. runtime.GC()
59. pprof.Lookup("heap").WriteTo(m1, 0)
60. //从此处开始ch4cpu通道被不断地写入数据
61. go runcputest()
62. //goroutine运行15秒后chTimer写入值
63. go func(){
64. time.Sleep(15 * time.Second)
65. log.Println("write timer")
66. chTimer <- struct{}{}
67.
68. }()
69. memMap[2]= runMEMTest()
70. runtime.GC()
71. pprof.Lookup("heap").WriteTo(m2, 0)
72.
73. memMap[2] = nil
74. runtime.GC()
75. pprof.Lookup("heap").WriteTo(m3, 0)
76.
77. memMap[1] = nil
78. runtime.GC()
79. pprof.Lookup("heap").WriteTo(m4, 0)
80.
81. procmsg()
82. }
83.
84. func runMEMTest()([]int) {
85. mem := make([]int, 100000, 120000)
86. return mem
87. }
88.
89. func runcputest(){
90. var i uint64
91. for {
92. ch4cpu <- i
93. i++
94. }
95. }
96.
97. func procmsg(){
98. for {
99. select {
100. case _ = <-ch4cpu:
101. case _ = <-chTimer://直到满足此条件for循环才结束
102. log.Println("timeout")
103. return
104. }
105. }
106. }
下面先讲解相应的代码。
第11行至第19行，定义了两个channel，分别是ch4cpu和chTimer。这两个通道，一个是在测试CPU性能的时候读写数据，一个是用作定时器。chTimer是无缓存通道，此处的用法就是将这个通道作为信号。在第63行至第68行的goroutine内，先休眠15秒，再往chTimer写入数据。而在主goroutine的第81行运行procmsg函数，该函数会不停地循环，直到第101行条件满足的时候，在一定概率下才会执行第二个case结束程序。一定要注意，两个case都满足条件时尽可能随机选择一个case执行，也就是在chTimer满足条件以后会再执行一定次数才结束程序。另外，此处还定义了一个map，用来记录内存分配。
第21行至第51行生成了几个文件，这些文件用来存放分析记录的数据，可通过defer关键字来关闭这些文件，也就是在main函数结束时关闭文件。
第53行和第54行是调用runtime/pprof包的CPU性能测试的两个函数，把结果写入c文件。
第56行至第59行，调用runMEMTest函数分配一个len为100000、cap为120000的int型切片，并且把这个切片返回给memMap[1]。每执行一次，mem这个变量就会通过垃圾回收机制回收一次，然后把堆的分配情况写入文件m1。
第61行，开始运行runcputest函数，不停地往ch4cpu通道写入数据。
第63行至第68行，goroutine运行一个匿名函数，作用是15秒后往chTimer通道写入数据。
第69行至第71行，类似第56行至第59行，这次会进一步增大内存压力，再分配一块内存，再次以值传递的方式传递给memMap[2]，然后把数据写入m2文件。
第73行至第79行是把分配的内存释放，并且分别记录数据到m3和m4文件。
第81行是main函数的最后一个函数调用，对应的procmsg函数的具体代码在第97行至第106行。函数的主体是一个for循环，不停地执行select，可以看到第一个case是一直满足的，而第二个case要等待chTimer可读，一旦执行到第二个case，则整个程序结束。
梳理一下，整段代码其实就是为了分析CPU和内存的运行状况而设计的，对CPU的测试主要是用runcputest函数不停地向通道ch4cpu写入uint64类型的数据，并由procmsg()函数不停地读数据，而procmsg函数结束的条件是等到chTimer可读，chTimer是启动了一个goroutine并在开始运行15秒后往chTimer写入数据的过程，也就是说，大概在chTimer执行以后，procmsg函数就有机会结束了。因为有大量的通道读写，所以这是测试CPU的主要代码。
对于内存的测试，则是通过大量分配内存堆实现的，并且每次都有一个变量是可回收的，如此反复，每次都执行垃圾回收，并记录堆的信息，这是在模拟一种内存使用情况，可以通过分析记录查看内存泄露等情况。
在执行了上述代码以后，应该已经生成了五个文件：cpu_profile.prof、mem_profile1.prof、mem_profile2.prof、mem_profile3.prof、mem_profile4.prof。这些文件都是二进制的，不能直接打开阅读。要使用这些文件就需要借助Go工具。示例如下：
1. $ go tool pprof /Users/liujinliang/projects/go/src/ljl/book/ch06/6.2/cpu_profile.prof 2. Type: cpu 3. Time: Aug 27, 2019 at 9:01am (CST) 4. Duration: 15.12s, Total samples = 25.55s (169.03%) 5. Entering interactive mode (type "help" for commands, "o" for options)
执行该命令后可以看到一些概要信息，注意第4行，这里因为是多线程并行，所以把每个线程执行时间加起来的和是超过整个程序运行时间的。
我们还可以进一步查看更详细的信息，比如查看占用CPU最高的十个函数：
1. (pprof) top 2. Showing nodes accounting for 25.26s, 98.86% of 25.55s total 3. Dropped 10 nodes (cum <= 0.13s) 4. Showing top 10 nodes out of 34 5. flat flat% sum% cum cum% 6. 12.19s 47.71% 47.71% 12.19s 47.71% runtime.pthread_cond_signal 7. 7.41s 29.00% 76.71% 7.41s 29.00% runtime.pthread_cond_wait 8. 4.72s 18.47% 95.19% 4.73s 18.51% runtime.usleep 9. 0.34s 1.33% 96.52% 0.34s 1.33% runtime.pthread_mutex_lock 10. 0.22s 0.86% 97.38% 0.22s 0.86% runtime.(*waitq).dequeue 11. 0.13s 0.51% 97.89% 2.76s 10.80% runtime.lock 12. 0.09s 0.35% 98.24% 3.09s 12.09% runtime.selectgo 13. 0.09s 0.35% 98.59% 0.35s 1.37% runtime.unlock 14. 0.05s 0.2% 98.79% 3.14s 12.29% main.procmsg 15. 0.02s 0.078% 98.86% 0.44s 1.72% runtime.chansend
执行top命令需要在pprof命令包内进行，可以看第一行top命令前括号内的信息。
可以看到，第6行和第7行是CPU使用率最高的方法，而且这两个方法是标准函数。pthread_cond_signal用于唤醒线程，pthread_cond_wait用于使线程进入阻塞状态。CPU使用率高的原因可能是程序中几次主动调用垃圾回收，而在运行的时候会让线程阻塞和唤醒。另外就是不停地向通道ch4cpu写入数据，写数据是通过goroutine实现的，而读数据是在主goroutine中，也会造成缓存区域满的情况。
本节就不再继续优化代码了，仅仅找出可能原因即可，读者可以自行优化测试。如果对于某个具体的函数有疑问，想获取更为详细的信息，可以使用list方法，比如可以看一下自己写的main.procmsg函数：
(pprof) list main.procmsg
对内存使用的分析与CPU类似，即先使用quit命令离开当前的pprof，然后再进入。内存使用分析也是通过list看具体函数执行时的内存使用情况的。
1. $ go tool pprof /Users/liujinliang/projects/go/src/ljl/book/ch06/6.2/
mem_profile2.prof
2. Type: inuse_space
3. Time: Aug 27, 2019 at 9:01am (CST)
4. Entering interactive mode (type "help" for commands, "o" for options)
5. (pprof) list main.main
6. Total: 1.10MB
7. ROUTINE ======================== main.main in /Users/liujinliang/projects/
go/src/ljl/book/ch06/6.2/profile.go
8. 0 1.10MB (flat, cum) 100% of Total
9. . . 67:
10. . . 68: }()
11. . . 69: memMap[2]= runMEMTest()
12. . . 70: runtime.GC()
13. . . 71: pprof.Lookup("heap").WriteTo(m2, 0)
14. . 1.10MB 72:
15. . . 73: memMap[2] = nil
16. . . 74: runtime.GC()
17. . . 75: pprof.Lookup("heap").WriteTo(m3, 0)
18. . . 76:
如果要更加直观地查看内存使用情况，可以生成图片，命令如下：
$ go tool pprof -svg ./mem_profile2.prof > mem.svg
生成的图如图6-1所示。
图6-1 性能分析结果图
注意
上面生成图片的方式依赖graphviz，使用该方式前请先安装该工具。
前面已经介绍了代码优化，而且解释了代码优化的关键是性能分析。除了使用runtime/pprof进行性能分析以外，其实在GitHub上可以找到更好用的第三方工具，不过都是基于该包的封装，希望读者能够掌握该包的使用，在实际项目中不断总结，改进方式。
注意
Donald E. Knuth说过一句非常著名的话“过早地优化是万恶之源”，所以一定要在项目稳定运行没有明显bug后再优化。