golang调试bug及性能监控方式实践总结

如何分析程序运行所需时间及cpu的使用率？

使用shell内置的time指令

time go run '你的程序.go'

$ time go run test.go 

real	0m0.802s
user	0m0.320s
sys	0m0.345s

使用time指令后，会返回三个指标，他们的含义分别是：

• real：程序实际运行的时长。
• user：程序在用户态所消耗的时间
• sys：程序在系统态所消耗的时间

一般来说，real >= user + sys,这是因为系统在运行当前程序时，可能会调用其他进程，从而导致程序整体的运行时增加。

使用/usr/bin/time指令

在linux中，还存在比time指令更为精准详细的time指令，相比于系统自带的time指令，你还需要添加指令的绝对路径以及参数-v。

$ /usr/bin/time -v go run test.go  
Command being timed: "go run test.go"
	User time (seconds): 0.12
	System time (seconds): 0.06
	Percent of CPU this job got: 115%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.16
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 41172
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 1
	Minor (reclaiming a frame) page faults: 15880
	Voluntary context switches: 897
	Involuntary context switches: 183
	Swaps: 0
	File system inputs: 256
	File system outputs: 2664
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0

可以看出，这种time指令比系统自带的要拥有更多的参数。例如：CPU的占用率，内存的使用情况等等。

如何分析go程序的内存使用情况？

聊完了go程序的运行时间的监控方式，我们接下来要讨论的是如何分析内存使用情况的问题。

先贴出一段测试用代码

package main
import (
	"log"
	"runtime"
	"time"
)
func main(){
	log.Println("start...")
	test()
	log.Println("force gc...")
	runtime.GC()//强调调用gc回收
	log.Println("done...")
	time.Sleep(3600*time.Second)
}
func test(){
	//由于切片可以动态扩容，所以这里使用slice进行测试
	container := make([]int, 8)
	log.Println("==> loop start...")
	for i := 0; i < 32*1000*1000; i++ {
		container = append(container, i)
	}
	log.Println("==> loop end...")
}

将test.go文件编译为可执行的二进制文件并执行

$go build -o test && ./test

此时，我们新开一个终端窗口，并使用top命令查看进程的内存占用情况

$top -p $(pidof test)

结果如下：

如图所示，可以看出我们的test进程大概有520m的内存占用，这显然是不正常的，因为test()执行完毕以后，container的内存应该被释放了。

这时，另一种内存分析工具GODEBUG就能派上用场了。

GODEBUG与gctrace

首先，我们要开启打印垃圾回收信息的功能：

$ GODEBUG='gctrace=1' ./test

gctrace=1可以让垃圾回收器在每次回收垃圾时收集用时和释放空间的大小，并将其打印到终端上。

格式及其含义

        gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
	gc #        GC次数的编号，每次GC时递增
	@#s         距离程序开始执行时的时间
	#%          GC占用的执行时间百分比
	#+...+#     GC使用的时间
	#->#-># MB  GC开始，结束，以及当前活跃堆内存的大小，单位M
	# MB goal   全局堆内存大小
	# P         使用processor的数量

如果是由runtime.GC调用触发的，则消息会以forced结尾。

这里虚拟一条输出作为示例：

gc 3 @0.134s 1%: 0.003+28+0.002 ms clock, 0.007+0/0.049/24+0.005 ms cpu, 178->178->100 MB, 180 MB goal, 2 P

该条输出代表的信息如下

• gc 3：GC调试的编号为3。
• @0.134s：此时程序已经运行了0.134s。
• 1%：在全部的运行时间中GC所占时间比例为1%。