A Piece Of: Golang Profile
Tips on Profile 先说几个小坑点: 默认情况下,Golang Profile 取样的频率为 100Hz,意味着每 10ms 才会取样一次,所以程序运行时间少于 10ms 肯定不会被取样 但是我们可以通过 runtime.SetCPUProfileRate() 重新设置值,重新进行调试,比如将采样率设置为 1000,每 1ms 就会取样一次,但是这样对性能的开销很大,Golang 官方建议这个值不要设置在 200 以上 其实最好的还是让程序多运行一段时间,比如 1s 左右,个人测试即使将采样率调高,如果一个程序只运行 10ms 左右,采样的结果也大概率为空 在正确位置设置上述语句后,程序提示 “runtime: cannot set cpu profile rate until previous profile has finished.",这句错误提示简直不明不白的,我第一次看到这个错误提示还以为就是字面意思:系统中可能存在正在运行的 profile 程序 查资料后发现,runtime.SetCPUProfileRate() 是一种比较 Hack 的做法,所以该错误提示可以忽略 在程序运行时,直接通过 kill 命令结束程序的话,最后生成的 profile 为空(?),最好使用下面的这个模式: sigs := make(chan os.Signal, 1) signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM) server := NewServer(port, connMap) go server.Run() <-sigs Log.Info("Shutting down server") 通过 signal.Notify 来拦截 kill 的信号,保证程序能够正常结束,profile 文件不为空 How to Profile if pprofFlag { // runtime.SetCPUProfileRate(1000) cpuFile, err := os.Create("executor_profile.prof") if err != nil { fmt.Println("无法创建 CPU profile 文件:", err) return } defer cpuFile.Close() // 开始 CPU profile if err := pprof.StartCPUProfile(cpuFile); err != nil { fmt.Println("无法启动 CPU profile:", err) return } defer pprof.StopCPUProfile() } 注意这段代码只能放在 main 函数中,否则 defer 语句的语义会有影响 How to Read Profile Results 命令行 (pprof) top 10 Showing nodes accounting for 40ms, 100% of 40ms total Showing top 10 nodes out of 26 flat flat% sum% cum cum% 10ms 25.00% 25.00% 10ms 25.00% os.(*File).checkValid (inline) 10ms 25.00% 50.00% 10ms 25.00% runtime.(*mheap).allocSpan 10ms 25.00% 75.00% 10ms 25.00% runtime.(*profBuf).read 10ms 25.00% 100% 10ms 25.00% runtime.startm 0 0% 100% 10ms 25.00% log.(*Logger).Output 0 0% 100% 10ms 25.00% log.Println 0 0% 100% 10ms 25.00% main.main.func1 0 0% 100% 10ms 25.00% os.(*File).Write 0 0% 100% 10ms 25.00% runtime.(*mcache).nextFree 0 0% 100% 10ms 25.00% runtime.(*mcache).refill flat:该函数本身直接消耗的时间。比如,flat = 10ms 表示这个函数自身消耗了 10 毫秒的 CPU 时间,而不是它调用的其他函数所消耗的时间。 ...