Golang性能调优实战
背景
随着企点电话业务的发展，坐席数量日渐增多，日外呼通话时长峰值已达百万分钟级，而电话功能对服务稳定性要求非常高，运维压力大。支撑业务的相关模块如jssdk事件推送、外呼模块、基础开号、开放平台等都是我们的重要保障对象。为了提高服务的性能及稳定性，核心服务都基于Golang开发，而在开发及维护过程中也遇到了各种各样的问题，比较常见的如内存占用高、CPU占用高、协程数量暴涨或者临时内存申请过大。面对这些问题除了需要做好各类监控和防护外，还需要学会如何排查，经过实践及梳理，我们最终整理出一套Golang的性能调优最佳实践。
目录
本文大概分为以下几个部分。
背景 目录性能调优 -- pprof篇一、pprof是什么二、pprof使用方法1、runtime/pprof：指定区块进行数据分析采样2、net/http/pprof：基于HTTP Server进行数据分析采样3、go test：通过测试用例指定所需要标记进行数据采样分析三、pprof参数简介四、pprof采样类型1、CPU Profiling2、Memory Profiling3、 Block Profiling4、Mutex Profiling5、 Goroutine Profiling5、ThreadCreate Profiling性能调优 -- Trace篇一、Trace参数简介二、Trace适用的场景1、诊断延迟问题2、诊断并行问题3、什么时候Trace不合适三、Trace案例分析性能调优 -- GODEBUG篇一、GODEBUG基础简介二、GODEBUG常用参数三、GODEBUG的调度分析1、schedtrace2、scheddetail调度点四、GODEBUG的GC分析1、GC的三种触发方式性能调优 -- 逃逸分析篇一、逃逸分析简介1、堆和栈二、逃逸分析案例1、指针逃逸2、泄漏参数3、栈空间不足逃逸4、动态类型逃逸闭包引用对象逃逸三、逃逸分析总结1、逃逸分析的作用2、逃逸分析总结性能调优 -- 实战案例案例1：调用三方API超时造成的协程泄漏场景说明分析过程解决方案类似该场景Mock代码案例2：引入三方SDK发生的内存泄漏场景说明分析过程解决方案类似该场景Mock代码案例3：全局变量引起的内存泄漏场景说明分析过程解决方案类似该场景Mock代码总结和展望
性能调优 -- pprof篇
一、pprof是什么
pprof 是用于可视化和分析性能分析数据的工具。
pprof 以 profile.proto 读取分析样本的集合，并生成报告以可视化并帮助分析数据（支持文本和图形报告）。
profile.proto 是一个 Protocol Buffer v3 的描述文件，它描述了一组 callstack 和 symbolization 信息， 作用是表示统计分析的一组采样的调用栈，是很常见的 stacktrace 配置文件格式。
二、pprof使用方法
pprof支持三种采样方式。
1、runtime/pprof：指定区块进行数据分析采样
package main
import (
"fmt"
"net/http"
"runtime/pprof"
)
func main() {
f, err := os.Create("demo.prof") defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
f, err := os.Create("demo.mprof") defer f.Close()
pprof.WriteHeapprofile(f)
}
2、net/http/pprof：基于HTTP Server进行数据分析采样
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
)
func main() {
startMemProfile startCPUProfile()
......
stopCPUProfile()
}
func startCPUProfile() {
if *cpuProfile != "" {
f, err := os.Create(*cpuProfile)
if err != nil {
fmt.Fprintf(os.Stderr, "Can not create cpu profile output file: %s",
err)
return
}
if err := pprof.StartCPUProfile(f); err != nil {
fmt.Fprintf(os.Stderr, "Can not start cpu profile: %s", err)
f.Close()
return
}
}
}
func stopCPUProfile() {
if *cpuProfile != "" {
pprof.StopCPUProfile() // 把记录的概要信息写到已指定的文件
}
}
func startMemProfile() {
if *memProfile != "" && *memProfileRate > 0 {
runtime.MemProfileRate = *memProfileRate
}
}
func stopBlockProfile() {
if *blockProfile != "" && *blockProfileRate >= 0 {
f, err := os.Create(*blockProfile)
if err != nil {
fmt.Fprintf(os.Stderr, "Can not create block profile output file: %s", err)
return
}
if err = pprof.Lookup("block").WriteTo(f, 0); err != nil {
fmt.Fprintf(os.Stderr, "Can not write %s: %s", *blockProfile, err)
}
f.Close()
}
}
3、go test：通过测试用例指定所需要标记进行数据采样分析
package data
import "testing"
const url = "https://github.com"
func TestAdd(t *testing.T) {
s := Add(url)
if s == "" {
t.Errorf("Test.Add error!")
}
}
func BenchmarkAdd(b *testing.B) {
for i := 0; i < b.N; i++ {
Add(url)
}
}
/**
go test -bench=. -cpuprofile=cpu.prof
pkg: go-pprof-example/data
BenchmarkAdd-4 10000000 187 ns/op
PASS
ok github.com/EDDYCJY/go-pprof-example/data 2.300s
**/
三、pprof参数简介
通常会借助go tool命令行工具直接查看分析，或者生成grafviz分析，pprof工具在交互模式下支持的命令。
四、pprof采样类型
几种web视图(需要安装graphviz)：
·Top视图
·Graph视图：显示整体的函数调用，框越大、线越粗、颜色越鲜艳代表占用资源越高。
·Peek视图：与top相比增加了所属上线文的信息展示。
·Source视图：增加了面向源代码的追踪和分析。
·Flame Graph视图：火焰图，颜色越鲜艳、区块越大代表占用资源越高。
1、CPU Profiling
go tool pprof http://127.0.0.1:6060/debug/pprof/profile\?seconds\=30
go tool pprof -http=:8080 http://127.0.0.1:6060/debug/pprof/profile\?seconds\=30
2、Memory Profiling
go tool pprof http://127.0.0.1:6060/debug/pprof/heap
go tool pprof -http=:8080 http://127.0.0.1:6060/debug/pprof/heap
3、 Block Profiling
go tool pprof http://127.0.0.1:6060/debug/pprof/block
go tool pprof -http=:8080 http://127.0.0.1:6060/debug/pprof/block
4、Mutex Profiling
go tool pprof http://127.0.0.1:6060/debug/pprof/mutex
go tool pprof -http=:8080 http://127.0.0.1:6060/debug/pprof/mutex
5、 Goroutine Profiling
go tool pprof http://127.0.0.1:6060/debug/pprof/goroutine
go tool pprof -http=:8080 http://127.0.0.1:6060/debug/pprof/goroutine
5、ThreadCreate Profiling
go tool pprof http://127.0.0.1:6060/debug/pprof/threadcreate
go tool pprof -http=:8080 http://127.0.0.1:6060/debug/pprof/threadcreate
性能调优 -- Trace篇
很多时候仅仅使用pprof不一定能完整的观察并解决问题，这是因为真实场景下程序中往往包含了许多隐藏动作，比如goroutine在执行的时候会做哪些操作？执行阻塞了多长时间？在哪里被阻止的？这些都是pprof很难分析出来的，这时候trace就可以轻松分析它。
package main
import (
"os"
"runtime/trace"
)
func main() {
f, err := os.Create("trace.out")
if err != nil {
panic(err)
}
defer f.Close()
err = trace.Start(f)
if err != nil { panic(err)
}
defer trace.Stop() ch := make(chan string)
go func() {
ch <- "hello"
}()
<-ch
}
一、Trace参数简介
Goroutine analysis协程调度分析
在对当前程序的 Goroutine 运行分布有了初步了解后，我们再通过 “查看跟踪” 看看之间的关联性，如下：
1.时间线：显示执行的时间单元，根据时间维度的不同可以调整区间，具体可执行 shift + ? 查看帮助手册。
2.堆：显示执行期间的内存分配和释放情况。
3.协程：显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行，其包含 GC 等待（GCWaiting）、可运行（Runnable）、运行中（Running）这三种状态。
4.OS 线程：显示在执行期间有多少个线程在运行，其包含正在调用 Syscall（InSyscall）、运行中（Running）这两种状态。
5.虚拟处理器：每个虚拟处理器显示一行，虚拟处理器的数量一般默认为系统内核数。
6.协程和事件：显示在每个虚拟处理器上有什么 Goroutine 正在运行，而连线行为代表事件关联。
二、Trace适用的场景
1、诊断延迟问题
当完成关键任务的goroutine被阻止运行时，可能会引起延迟问题。可能的原因有很多：做系统调用时被阻塞; 被共享内存阻塞（通道/互斥等）; 被runtime系统（例如GC）阻塞，甚至可能调度程序不像您想要的那样频繁地运行关键goroutine。
所有这些都可以使用go tool trace来识别。您可以通过查看PROCs时间线来跟踪问题，并发现一段时间内goroutine被长时间阻塞。一旦你确定了这段时间，应该给出一个关于根本原因的线索。
2、诊断并行问题
假设你已经编写了一个程序，希望使用所有的CPU，但运行速度比预期的要慢。这可能是因为您的程序不像您所期望的那样并行运行。这可能是由于在很多关键路径上串行运行太多，而很多代码原本是可以异步（并行）运行的。
3、什么时候Trace不合适
当然，go tool trace不能解决一切问题。如果您想跟踪运行缓慢的函数，或者找到大部分CPU时间花费在哪里，这个工具就是不合适的。为此，您应该使用go tool pprof，它可以显示在每个函数中花费的CPU时间的百分比。 go tool trace更适合于找出程序在一段时间内正在做什么，而不是总体上的开销。此外，还有“view trace”链接提供的其他可视化功能，这些对于诊断争用问题特别有用。了解您的程序在理论上的表现（使用老式Big-O分析）也是无可替代的。
三、Trace案例分析
回到之前我们准备的demo，执行里面的trace，生成trace.out，然后我们分析。
package main
import (
"fmt"
"os"
"runtime"
"runtime/trace"
"sync/atomic"
"time"
)
var (
stop int32
count int64
sum time.Duration
)
func concat() {
for n := 0; n < 100; n++ {
for i := 0; i < 8; i++ {
go func() {
s := "Go GC"
s += " " + "Hello"
s += " " + "World"
_ = s
}()
} }
}
func main() {
f, _ := os.Create("trace.out")
defer f.Close()
trace.Start(f)
defer trace.Stop()
go func() {
var t time.Time
for atomic.LoadInt32(&stop) == 0 {
t = time.Now()
runtime.GC()
sum += time.Since(t)
count++
}
fmt.Printf("GC spend avg: %v\n", time.Duration(int64(sum)/count)) }()
concat()
atomic.StoreInt32(&stop, 1)
}
看结果我们发现GC 平均执行一次需要长达GC spend avg: 2.534362ms 的时间，（这里可以利用grafana查看metrics）我们再进一步观察 trace 的结果：
程序的整个执行过程中仅执行了一次 GC，而且仅 Sweep STW 就耗费了超过 1 ms，非常反常。甚至查看赋值器 mutator 的 CPU 利用率，在整个 trace 尺度下连 40% 都不到：
主要原因是什么呢？我们不妨查看 goroutine 的分析：
在这个榜单中我们不难发现，goroutine 的执行时间占其生命周期总时间非常短的一部分，但大部分时间都花费在调度器的等待上了（蓝色的部分），说明同时创建大量 goroutine 对调度器产生的压力确实不小，我们不妨将这一产生速率减慢，一批一批地创建 goroutine：
func concat() { wg := sync.WaitGroup{} for n := 0; n < 100; n++ { wg.Add(8) for i := 0; i < 8; i++ { go func() { s := "Go GC" s += " " + "Hello" s += " " + "World" _ = s wg.Done() }() } wg.Wait() }
}
我们再次执行发现GC降到了GC spend avg: 295.07µs,这时的赋值器 CPU 使用率也提高到了 60%，相对来说就很可观了：
当然，这个程序仍然有优化空间，例如我们其实没有必要等待很多 goroutine 同时执行完毕才去执行下一组 goroutine。而可以当一个 goroutine 执行完毕时，直接启动一个新的 goroutine，也就是 goroutine 池的使用。有兴趣的可以沿着这个思路进一步优化这个程序中赋值器对 CPU 的使用率。
性能调优 -- GODEBUG篇
一、GODEBUG基础简介
godebug是Go语言十分强大的工具之一，godebug可以让运行程序运行时输出调试信息，通过godebug我们可以很只管的查看到调度器或者垃圾回收等详细信息。godebug可以控制运行时的调试变量，参数之间以逗号分隔，格式为name=val.
二、GODEBUG常用参数
https://golang.org/pkg/runtime/
三、GODEBUG的调度分析
Go scheduler 的主要功能是针对在处理器上运行的 OS 线程分发可运行的 Goroutine，而我们一提到调度器，就离不开三个经常被提到的缩写，分别是：
·G：Goroutine，实际上我们每次调用 go func 就是生成了一个 G。
·P：处理器，一般为处理器的核数，可以通过 GOMAXPROCS 进行修改。
·M：OS 线程
这三者交互实际来源于 Go 的 M: N 调度模型，也就是 M 必须与 P 进行绑定，然后不断地在 M 上循环寻找可运行的 G 来执行相应的任务，如果想具体了解可以详细阅读 《Go Runtime Scheduler》，我们抽其中的工作流程图进行简单分析，如下:
1.当我们执行 go func() 时，实际上就是创建一个全新的 Goroutine，我们称它为 G。
2.新创建的 G 会被放入 P 的本地队列（Local Queue）或全局队列（Global Queue）中，准备下一步的动作。
3.唤醒或创建 M 以便执行 G。
4.不断地进行事件循环
5.寻找在可用状态下的 G 进行执行任务
6.清除后，重新进入事件循环
而在描述中有提到全局和本地这两类队列，其实在功能上来讲都是用于存放正在等待运行的 G，但是不同点在于，本地队列有数量限制，不允许超过 256 个。并且在新建 G 时，会优先选择 P 的本地队列，如果本地队列满了，则将 P 的本地队列的一半的 G 移动到全局队列，这其实可以理解为调度资源的共享和再平衡。
func main() {
wg := sync.WaitGroup{}
wg.Add(10)
for i := 0; i < 10; i++ {
go func(wg *sync.WaitGroup) {
var counter int
for i := 0; i < 1e10; i++ {
counter++
}
wg.Done()
}(&wg)
}
wg.Wait()
}
1、schedtrace
$ GODEBUG=schedtrace=1000 ./sched
SCHED 0ms: gomaxprocs=4 idleprocs=1 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0]
SCHED 1000ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 2000ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 3001ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 4010ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 5011ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 6012ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 7021ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 8023ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 9031ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 10033ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 11038ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 12044ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 13051ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 14052ms: gomaxprocs=4 idleprocs=2 threads=5
...
在上面我们有提到 “自旋线程” 这个概念，如果你之前没有了解过相关概念，一听 “自旋” 肯定会比较懵，我们引用 《Head First of Golang Scheduler》 的内容来说明：
自旋线程的这个说法，是因为 Go Scheduler 的设计者在考虑了 “OS 的资源利用率” 以及 “频繁的线程抢占给 OS 带来的负载” 之后，提出了 “Spinning Thread” 的概念。也就是当 “自旋线程” 没有找到可供其调度执行的 Goroutine 时，并不会销毁该线程 ，而是采取 “自旋” 的操作保存了下来。虽然看起来这是浪费了一些资源，但是考虑一下 syscall 的情景就可以知道，比起 “自旋"，线程间频繁的抢占以及频繁的创建和销毁操作可能带来的危害会更大。
2、scheddetail
如果我们想要更详细的看到调度器的完整信息时，我们可以增加 scheddetail 参数，就能够更进一步的查看调度的细节逻辑，如下：
$ GODEBUG=scheddetail=1,schedtrace=1000 ./sched
SCHED 1000ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
P0: status=1 schedtick=2 syscalltick=0 m=3 runqsize=3 gfreecnt=0
P1: status=1 schedtick=2 syscalltick=0 m=4 runqsize=1 gfreecnt=0
P2: status=1 schedtick=2 syscalltick=0 m=0 runqsize=1 gfreecnt=0
P3: status=1 schedtick=1 syscalltick=0 m=2 runqsize=1 gfreecnt=0
M4: p=1 curg=18 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
M3: p=0 curg=22 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
M2: p=3 curg=24 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
M1: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
M0: p=2 curg=26 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
G1: status=4(semacquire) m=-1 lockedm=-1
G2: status=4(force gc (idle)) m=-1 lockedm=-1
G3: status=4(GC sweep wait) m=-1 lockedm=-1
G17: status=1() m=-1 lockedm=-1
G18: status=2() m=4 lockedm=-1
G19: status=1() m=-1 lockedm=-1
G20: status=1() m=-1 lockedm=-1
G21: status=1() m=-1 lockedm=-1
G22: status=2() m=3 lockedm=-1
G23: status=1() m=-1 lockedm=-1
G24: status=2() m=2 lockedm=-1
G25: status=1() m=-1 lockedm=-1
G26: status=2() m=0 lockedm=-1
·status：G 的运行状态。
·m：隶属哪一个 M。
·lockedm：是否有锁定 M。
在第一点中我们有提到 G 的运行状态，这对于分析内部流转非常的有用，共涉及如下 9 种状态
调度点
1、调用runtime.gosched函数。goroutine主动放弃CPU，该goroutine会被置为runnable状态，然后放入全局G队列，P继续执行下一个goroutine。
·主动行为
·使用场景：一般发生在执耗时长的任务又想其他goroutine得到执行机会时调用。
2、调用runtime.park函数。goroutine进入wait状态，除非对其调用runtime.ready函数，否则该goroutine永远不刽得到执行。而P继续执行下一个G任务。
·使用场景：读写channel。一般是在某个条件如果得不到满足就不能继续运行下去时调用，当条件满足后需要使用runtime.ready唤醒它，类似于Java里的await和notify
3、慢系统调用。将该处理器P上设置为syscall状态，然后对应的线程M进入系统调用阻塞等待。sysmom监控线程会定期扫描所有的P（处理器），若发现一个P处于syscall状态，就讲=将M（线程）和P（处理器）分离，并再分配一个M与这个P绑定，从而继续执行P本地队列中的其他goroutine。当之前阻塞的M从系统调用返回后，将其执行的goroutine放入全局G队列中，该M去sleep。
四、GODEBUG的GC分析
GC，全称 GarbageCollection，即垃圾回收，是一种自动内存管理的机制。
涉及的术语：
·mark：标记阶段。
·markTermination：标记结束阶段。
·mutator assist：辅助 GC，是指在 GC 过程中 mutator 线程会并发运行，而 mutator assist 机制会协助 GC 做一部分的工作。
·heap_live：在 Go 的内存管理中，span 是内存页的基本单元，每页大小为 8kb，同时 Go 会根据对象的大小不同而分配不同页数的 span，而 heap_live 就代表着所有 span 的总大小。
·dedicated / fractional / idle：在标记阶段会分为三种不同的 mark worker 模式，分别是 dedicated、fractional 和 idle，它们代表着不同的专注程度，其中 dedicated 模式最专注，是完整的 GC 回收行为，fractional 只会干部分的 GC 行为，idle 最轻松。这里你只需要了解它是不同专注程度的 mark worker 就好了，详细介绍我们可以等后续的文章。
GC触发时机：
·到达堆阈值：默认情况下，它将在堆大小加倍时运行，可通过GOGC来设定更高阈值（不建议变更此配置）
·到达时间阈值：每两分钟会强制启动一次GC循环
当程序向操作系统申请的内存不再需要时，垃圾回收主动将其回收并供其他代码进行内存申请时候复用，或者将其归还给操作系统，这种针对内存级别资源的自动回收过程，即为垃圾回收。而负责垃圾回收的程序组件，即为垃圾回收器.
通常，垃圾回收器的执行过程被划分为两个半独立的组件：
·赋值器（Mutator）：这一名称本质上是在指代用户态的代码。因为对垃圾回收器而言，用户态的代码仅仅只是在修改对象之间的引用关系，也就是在对象图（对象之间引用关系的一个有向图）上进行操作。
·回收器（Collector）：负责执行垃圾回收的代码。
STW 是 StoptheWorld 的缩写，即万物静止，是指在垃圾回收过程中为了保证实现的正确性、防止无止境的内存增长等问题而不可避免的需要停止赋值器进一步操作对象图的一段过程。
在这个过程中整个用户代码被停止或者放缓执行， STW 越长，对用户代码造成的影响（例如延迟）就越大，早期 Go 对垃圾回收器的实现中 STW 长达几百毫秒，对时间敏感的实时通信等应用程序会造成巨大的影响。
1、GC的三种触发方式
package main
import (
"runtime"
"time"
)
func main() {
go func() {
for {
} }()
time.Sleep(time.Millisecond)
runtime.GC()
println("OK")
}
上面的这个程序在 Go 1.14 以前永远都不会输出 OK，其罪魁祸首是 STW 无限制的被延长。
尽管 STW 如今已经优化到了半毫秒级别以下，但这个程序被卡死原因在于仍然是 STW 导致的。原因在于，GC 在进入 STW 时，需要等待让所有的用户态代码停止，但是 for{} 所在的 goroutine 永远都不会被中断，从而停留在 STW 阶段。实际实践中也是如此，当程序的某个 goroutine 长时间得不到停止，强行拖慢 STW，这种情况下造成的影响（卡死）是非常可怕的。好在自 Go 1.14 之后，这类 goroutine 能够被异步地抢占，从而使得 STW 的时间如同普通程序那样，不会超过半个毫秒，程序也不会因为仅仅等待一个 goroutine 的停止而停顿在 STW 阶段。
package main
func allocate() { _ = make([]byte, 1<<20)
}
func main() {
for n := 1; n < 100000; n++ {
allocate() }
}
GODEBUG=gctrace=1 ./main
gc 1 @0.000s 2%: 0.009+0.23+0.004 ms clock, 0.11+0.083/0.019/0.14+0.049 ms cpu, 4->6->2 MB, 5 MB goal, 12 P
scvg: 8 KB released
scvg: inuse: 3, idle: 60, sys: 63, released: 57, consumed: 6 (MB)
gc 2 @0.001s 2%: 0.018+1.1+0.029 ms clock, 0.22+0.047/0.074/0.048+0.34 ms cpu, 4->7->3 MB, 5 MB goal, 12 P
scvg: inuse: 3, idle: 60, sys: 63, released: 56, consumed: 7 (MB)
gc 3 @0.003s 2%: 0.018+0.59+0.011 ms clock, 0.22+0.073/0.008/0.042+0.13 ms cpu, 5->6->1 MB, 6 MB goal, 12 P
scvg: 8 KB released
scvg: inuse: 2, idle: 61, sys: 63, released: 56, consumed: 7 (MB)
gc 4 @0.003s 4%: 0.019+0.70+0.054 ms clock, 0.23+0.051/0.047/0.085+0.65 ms cpu, 4->6->2 MB, 5 MB goal, 12 P
scvg: 8 KB released
scvg: inuse: 3, idle: 60, sys: 63, released: 56, consumed: 7 (MB)
scvg: 8 KB released
scvg: inuse: 4, idle: 59, sys: 63, released: 56, consumed: 7 (MB)
gc 5 @0.004s 12%: 0.021+0.26+0.49 ms clock, 0.26+0.046/0.037/0.11+5.8 ms cpu, 4->7->3 MB, 5 MB goal, 12 P
scvg: inuse: 5, idle: 58, sys: 63, released: 56, consumed: 7 (MB)
gc 6 @0.005s 12%: 0.020+0.17+0.004 ms clock, 0.25+0.080/0.070/0.053+0.051 ms cpu, 5->6->1 MB, 6 MB goal, 12 P
scvg: 8 KB released
scvg: inuse: 1, idle: 62, sys: 63, released: 56, consumed: 7 (MB)
wall clock 是指开始执行到完成所经历的实际时间，包括其他程序和本程序所消耗的时间；cpu time 是指特定程序使用 CPU 的时间；他们存在以下关系：
·wall clock < cpu time: 充分利用多核
·wall clock ≈ cpu time: 未并行执行
·wall clock > cpu time: 多核优势不明显
最后再看一个例子
$ GODEBUG=gctrace=1 ./main
begin to analyze memory profile.
gc 1 @0.002s 1%: 0.004+0.96+0.002 ms clock, 0.004+0.22/0.17/0+0.002 ms cpu, 10->10->0 MB, 11 MB goal, 1 P
begin to analyze memory profile.
gc 2 @5.011s 0%: 0.027+0.65+0.002 ms clock, 0.027+0/0.073/0.55+0.002 ms cpu, 10->10->0 MB, 11 MB goal, 1 P
begin to analyze memory profile.
gc 3 @10.017s 0%: 0.021+0.58+0.002 ms clock, 0.021+0/0.060/0.49+0.002 ms cpu, 10->10->0 MB, 11 MB goal, 1 P
begin to analyze memory profile.
gc 4 @15.023s 0%: 0.026+0.64+0.003 ms clock, 0.026+0/0.088/0.53+0.003 ms cpu, 10->10->0 MB, 11 MB goal, 1 P
begin to analyze memory profile.
gc 5 @20.030s 0%: 0.020+0.53+0.003 ms clock, 0.020+0/0.061/0.45+0.003 ms cpu, 10->10->0 MB, 11 MB goal, 1 P
可以看到，GC 差不多每 5 秒就发生一次，且每次 GC 都会从 10MB 清理到几乎 0MB，说明程序在不断的申请内存再释放，这是高性能 golang 程序所不允许的。
所以接下来使用 pprof 排查时，我们在乎的不是什么地方在占用大量内存，而是什么地方在不停地申请内存，这两者是有区别的。
由于内存的申请与释放频度是需要一段时间来统计的，所有我们保证程序已经运行了几分钟之后，再运行命令：
go tool pprof http://127.0.0.1:6060/debug/pprof/allocs
可以发现Run函数里面会进行无意义的内存申请，这里有个小插曲，你可尝试一下将 10<<20 修改成一个较小的值，重新编译运行，会发现并不会引起频繁 GC，原因是在 golang 里，对象是使用堆内存还是栈内存，由编译器进行逃逸分析并决定，如果对象不会逃逸，便可在使用栈内存，但总有意外，就是对象的大小过大时，便不得不使用堆内存。所以这里设置申请的内存就是为了避免编译器直接在栈上分配，如果那样得话就不会涉及到 GC 了。
性能调优 -- 逃逸分析篇
一、逃逸分析简介
1、堆和栈
要理解什么是逃逸分析会涉及堆和栈的一些基本知识，如果忘记的同学我们可以简单的回顾一下：
·堆（Heap）：一般来讲是人为手动进行管理，手动申请、分配、释放。堆适合不可预知大小的内存分配，这也意味着为此付出的代价是分配速度较慢，而且会形成内存碎片。
·栈（Stack）：由编译器进行管理，自动申请、分配、释放。一般不会太大，因此栈的分配和回收速度非常快；我们常见的函数参数（不同平台允许存放的数量不同），局部变量等都会存放在栈上。
再往简单的说，Go是通过在编译器里做逃逸分析（escape analysis）来决定一个对象放栈上还是放堆上，不逃逸的对象放栈上，可能逃逸的放堆上；即我发现变量在退出函数后没有用了，那么就把丢到栈上，毕竟栈上的内存分配和回收比堆上快很多；反之，函数内的普通变量经过逃逸分析后，发现在函数退出后变量还有在其他地方上引用，那就将变量分配在堆上。
go run -gcflags '-m -l' main.go
·-m会打印出逃逸分析的优化策略，实际上最多总共可以用 4 个-m`，但是信息量较大，一般用 1 个就可以了。
·-l 会禁用函数内联，在这里禁用掉内联能更好的观察逃逸情况，减少干扰。(如果一个函数是内联的，那么在编译时，编译器会把该函数的代码副本放置在每个调用该函数的地方。对内联函数进行任何修改，都需要重新编译函数的所有客户端，因为编译器需要重新更换一次所有的代码，否则将会继续使用旧的函数。如果想把一个函数定义为内联函数，则需要在函数名前面放置关键字 inline，在调用函数之前需要对函数进行定义。如果已定义的函数多于一行，编译器会忽略 inline 限定符。)
二、逃逸分析案例
1、指针逃逸
package main
type Student struct {
Name string
Age int
}
func StudentRegister(name string, age int) *Student {
s := new(Student) //局部变量s逃逸到堆
s.Name = name
s.Age = age
return s
}
func main() {
StudentRegister("Jim", 18)
}
虽然 在函数 StudentRegister() 内部 s 为局部变量，其值通过函数返回值返回，s 本身为一指针，其指向的内存地址不会是栈而是堆，这就是典型的逃逸案例。
$ go run -gcflags '-m -l' ponitor.go
# command-line-arguments
./ponitor.go:14:22: leaking param: name
./ponitor.go:15:10: new(Student) escapes to heap
2、泄漏参数
package main
type Student struct {
Name string
Age int
}
func GetUserInfo(u *Student) *Student {
return u
}
func main() {
GetUserInfo(&Student{Name:"111", Age:11})
}
上面代码中并没有发生逃逸，因为GetUserInfo里面没有做任何引用的操作。
$ go run -gcflags '-m -l' params.go
# command-line-arguments
./params.go:14:18: leaking param: u to result ~r1 level=0
./params.go:19:14: &Student literal does not escape
如果GetUserInfo返回地址，那么它就可能被外部引用，因此分配到了堆上。
$ go run -gcflags '-m -l' params.go
# command-line-arguments
./params.go:14:18: moved to heap: u
3、栈空间不足逃逸
package main
func Slice() {
s := make([]int, 10000, 10000)
for index, _ := range s {
s[index] = index
}
}
func main() {
Slice()
}
实际上当栈空间不足以存放当前对象时或无法判断当前切片长度时会将对象分配到堆中。
$ go run -gcflags '-m -l' stack.go # command-line-arguments./stack.go:10:11: make([]int, 10000, 10000) escapes to heap
4、动态类型逃逸
package main
import "fmt"
func main() {
s := "Escape"
fmt.Println(s)
}
很多函数参数为interface类型，比如fmt.Println(a …interface{})，编译期间很难确定其参数的具体类型，也能产生逃逸。
$ go run -gcflags '-m -l' dynamic.go
# command-line-arguments
./dynamic.go:13:13: ... argument does not escape
./dynamic.go:13:13: s escapes to heap
Escape
闭包引用对象逃逸
package main
import "fmt"
func Fibonacci() func() int {
a, b := 0, 1
return func() int {
a, b = b, a+b
return a
}
}
func main() {
f := Fibonacci()
for i := 0; i < 10; i++ {
fmt.Printf("Fibonacci: %d\n", f())
}
}
Fibonacci()函数中原本属于局部变量的a和b由于闭包的引用，不得不将二者放到堆上，以致产生逃逸。
$ go run -gcflags '-m -l' closure.go
# command-line-arguments
./closure.go:12:2: moved to heap: a
./closure.go:12:5: moved to heap: b
./closure.go:13:9: func literal escapes to heap
./closure.go:23:13: ... argument does not escape
./closure.go:23:34: f() escapes to heap
三、逃逸分析总结
1、逃逸分析的作用
·逃逸分析的好处是为了减少gc的压力，不逃逸的对象分配在栈上，当函数返回时就回收了资源，不需要gc标记清除。
·逃逸分析完后可以确定哪些变量可以分配在栈上，栈的分配比堆快，性能好(逃逸的局部变量会在堆上分配 ,而没有发生逃逸的则有编译器在栈上分配)。
·同步消除，如果你定义的对象的方法上有同步锁，但在运行时，却只有一个线程在访问，此时逃逸分析后的机器码，会去掉同步锁运行。
2、逃逸分析总结
·栈上分配内存比在堆中分配内存有更高的效率
·栈上分配的内存不需要GC处理
·堆上分配的内存使用完毕会交给GC处理
·逃逸分析目的是决定内分配地址是栈还是堆
·逃逸分析在编译阶段完成
·处处使用指针传递不一定是最好的
性能调优 -- 实战案例
案例1：调用三方API超时造成的协程泄漏
场景说明
某天我们的企微机器人收到了频繁的告警通知，通过系统监控发现服务的协程数在一个时间节点突然持续上涨且不下降，
如图所示：
分析过程
1、协程不断上涨首先考虑是否发生了协程泄漏，协程泄漏使用pprof分析非常方便。
2、执行 go tool pprof http://ip:port/debug/pprof/goroutine，top查看协程数较多的地方。
➜ ~ go tool pprof http://ip:port/debug/pprof/goroutine
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 492, 99.39% of 495 total
Dropped 29 nodes (cum <= 2)
Showing top 10 nodes out of 48
flat flat% sum% cum cum%
492 99.39% 99.39% 492 99.39% runtime.gopark
0 0% 99.39% 5 1.01% bufio.(*Reader).Read
0 0% 99.39% 23 4.65% bytes.(*Buffer).ReadFrom
0 0% 99.39% 19 3.84% crypto/tls.(*Conn).Handshake
0 0% 99.39% 5 1.01% crypto/tls.(*Conn).Read
0 0% 99.39% 19 3.84% crypto/tls.(*Conn).clientHandshake
0 0% 99.39% 23 4.65% crypto/tls.(*Conn).readFromUntil
0 0% 99.39% 18 3.64% crypto/tls.(*Conn).readHandshake
0 0% 99.39% 23 4.65% crypto/tls.(*Conn).readRecord (inline)
0 0% 99.39% 23 4.65% crypto/tls.(*Conn).readRecordOrCCS
(pprof)
3、发现信息不够全，则执行tree查看调用链路，可以看到大部分调用落到了net/http
(pprof) tree
Showing nodes accounting for 492, 99.39% of 495 total
Dropped 29 nodes (cum <= 2)
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
448 91.06% | runtime.selectgo
...
----------------------------------------------------------+-------------
448 100% | net/http.(*Client).Get (inline)
0 0% 99.39% 448 90.51% | net/http.(*Client).Do
448 100% | net/http.(*Client).do
----------------------------------------------------------+-------------
448 100% | net/http.Get
0 0% 99.39% 448 90.51% | net/http.(*Client).Get
448 100% | net/http.(*Client).Do (inline)
----------------------------------------------------------+-------------
448 100% | net/http.(*Client).Do
0 0% 99.39% 448 90.51% | net/http.(*Client).do
448 100% | net/http.(*Client).send
----------------------------------------------------------+-------------
448 100% | net/http.(*Client).do
0 0% 99.39% 448 90.51% | net/http.(*Client).send
448 100% | net/http.send
----------------------------------------------------------+-------------
448 100% | net/http.send
0 0% 99.39% 448 90.51% | net/http.(*Transport).RoundTrip
448 100% | net/http.(*Transport).roundTrip
448 100% | runtime.gopark
----------------------------------------------------------+-------------
4、通过日常经验，考虑使用net/http会造成协程泄漏可能有两个方面，一是未执行defer rsp.Body.Close()关闭资源而导致的阻塞，二是下游服务超时导致协程阻塞；三是协程中的业务逻辑耗时较长导致。通过分析代码发现defer rsp.Body.Close()也是存在的，说明资源被释放了不存在资源未释放阻塞的问题，那么考虑是下游服务超时导致，最终通过增加客户端超时时间可解决此问题。
解决方案
设置客户端超时时间即可，其他协程内调用三方API/RPC遵循同样的道理，需要考虑好客户端的超时时间，防止请求量增大而下游服务超时发现阻塞，进而造成协程泄漏。
httpClient := http.Client{
Timeout: time.Second * 5,
}
类似该场景Mock代码
func (h *Rpc) Run() { for { go func() { rsp, err := http.Get("https://third-service/") if err != nil { fmt.Printf("http.Get err: %v\n", err) } defer rsp.Body.Close() // do something... }() fmt.Println("goroutines: ", runtime.NumGoroutine()) }
}
案例2：引入三方SDK发生的内存泄漏
场景说明
在日常巡视服务健康度的时候发现某个服务存在内存飙升且内存不下降的问题，通过查看系统监控如下图:
分析过程
1、通过监控发现协程数不断上涨且伴随着内存上涨，考虑是否发生协程泄漏，使用pprof分析，top查看协程数较多的地方，通过list查看源码。
➜ ~ go tool pprof -source_path=/usr/local/Cellar/go/1.16.5/libexec/src http://xxx:8081/debug/pprof/goroutine
...
(pprof) top20
Showing nodes accounting for 3239, 99.91% of 3242 total
Dropped 134 nodes (cum <= 16)
flat flat% sum% cum cum%
3239 99.91% 99.91% 3239 99.91% runtime.gopark
...
0 0% 99.91% 19 0.59% github.com/Shopify/sarama.withRecover
0 0% 99.91% 1566 48.30% net/http.(*persistConn).readLoop
0 0% 99.91% 1566 48.30% net/http.(*persistConn).writeLoop
0 0% 99.91% 40 1.23% runtime.chanrecv
0 0% 99.91% 25 0.77% runtime.chanrecv2
0 0% 99.91% 3184 98.21% runtime.selectgo
(pprof)
(pprof) list readLoop
Total: 3242
ROUTINE ======================== net/http.(*persistConn).readLoop in net/http/transport.go
0 1566 (flat, cum) 48.30% of Total
. ...
. . 2204: case bodyEOF := <-waitForBodyRead:
. . 2205: replaced := pc.t.replaceReqCanceler(rc.cancelKey, nil) // before pc might return to idle pool
. . 2206: alive = alive &&
. 1565 2207: bodyEOF &&
. . 2208: !pc.sawEOF &&
. . 2209: pc.wroteRequest() &&
. . 2210: replaced && tryPutIdleConn(trace)
. . 2211: if bodyEOF {
. . 2212: eofc <- struct{}{}
2、分析发现协程数较多的地方再net/http上，所以去看代码里有没有调用net/http的地方。
3、分析代码，业务中使用了cos sdk会发起http请求，分析sdk源码后发现sdk提供的Http请求方法没有主动关闭资源，而业务方也没有主动关闭资源，导致资源没有关闭造成了http请求场景下的协程泄漏。
4、业务代码在请求完后主动关闭资源后问题得到解决。
解决方案
业务方使用sdk方法返回response后主动关闭资源即可。
rsp, err := cosClient.Object.PutFromFile(context.Background(), key, file, nil)
defer rsp.Body.Close()
类似该场景Mock代码
func (h *Rpc) Run() { for { go func() {
// cos-service rsp, err := http.Get("https://cos-service/") if err != nil { fmt.Printf("http.Get err: %v\n", err) } }() fmt.Println("goroutines: ", runtime.NumGoroutine()) }
}
案例3：全局变量引起的内存泄漏
场景说明
在日常巡视服务健康度的时候，发现一个客户端服务出现了内存上涨不释放的情况，如下图
分析过程
1、出现内存上涨且不释放，首先分析是否发生了内存泄漏。使用pprof工具分析，top查看内存占用较高的地方，使用list匹配源码。
➜ ~ go tool pprof http://ip:port/*
...
Type: inuse_space
Time: Jan 4, 2022 at 12:16am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 36.68MB, 100% of 36.68MB total
flat flat% sum% cum cum%
22.68MB 61.83% 61.83% 36.68MB 100% *.Run
14MB 38.17% 100% 14MB 38.17% fmt.Sprintf
...
(pprof) list Run
Total: 36.68MB
ROUTINE ======================== *.Run in *
22.68MB 36.68MB (flat, cum) 100% of Total
. . 51: paasType := int64(2)
. . 52: tasks := initTask()
. . 53: for item, _ := range tasks {
. . 54: err := Process(item)
. . 55: if err != nil {
22.68MB 22.68MB 56: failData = append(failData, FailData{
. . 57: KFUin: kfuin,
. . 58: KFExt: kfext,
. . 59: PaasType: paasType,
. 14MB 60: ErrMsg: fmt.Sprintf("call d.DeletePlatformEmployeeNoAudioFiles error. err:+%v"),
. . 61: // system error
. . 62: ErrCode: 99999,
. . 63: })
. . 64: }
. . 65: }
(pprof)
2、分析发现问题出在了一个切片的append操作。考虑可能是批处理任务量过大有大量的数据append到切片里且未被释放。
3、查阅代码，发现failData是一个全局的切片，当任务量大的时候，所以发生的错误都会写入这个切片，导致内存不断增大无法释放。
type FailData struct { AudioId int64 KFUin int64 KFExt int64 PaasType int64 ErrMsg string ErrCode int64
}
var failData []FailData
解决方案
全局变量failData切片改为在函数内定义failData切片。
类似该场景Mock代码
type Heap struct{}
var hole = map[interface{}]interface{}{}
func NewHeap() *Heap { return new(Heap)
}
func (h *Heap) Run() { fmt.Println("begin to analyze memory profile.") loop := 20 for i := 0; i < loop; i++ { m := make([]byte, 10<<20)
hole[i] = m }
}
总结和展望
以上分别从pprof、trace、godebug、逃逸分析和代码规范场景讨论了golang性能调优的方法，并针对各个场景演示了基本demo，实际业务场景可能比这个复杂得多 ，但是调优方法常用的就是以上几种方式，配合我们对服务和机器的监控，就可以很轻松发现程序中存在的问题。golang天生为并发而生，虽然golang的gc已经做得非常出色了，但是实际业务场景我们还是关注以上一些指标的，只有不断打磨我们才能写出真正的高性能服务。
随着企点电话在云原生架构方面的应用，基于DevOps、微服务、容器化的能力帮助业务团队快速、持续、可靠地交付系统，同时也带来了系统复杂度的提升和相应的运维挑战。分布式系统下单点及单维度的指标已经不足以帮助我们衡量系统的运行状况，因此设计可观测的服务成为重要的任务。
业界就可观测性而言提出了三个数据类型：Metrics、Tracing、Logging。Metrics，通常是数值类型的时间序列数据。这类需求的存在非常广泛，以至于衍生了专门服务于这个目标的数据库子类，时间序列数据库，TSDB，influxdb等。logging 通常会是工程师定位生产环境问题最直接的手段，在分布式架构下ELK已经成为成熟的日志聚合方案。Tracing 通常是理解系统，定位系统故障的最重要手段。在存储层面，Tracing 已经有相对明确的方案，无论是 OpenZipkin，还是 CNCF 的 Jaeger ，都提供几乎开箱即用的后端软件。
目前电话业务在服务告警、指标监控、日志聚合、分布式跟踪方面都有了一定的实践。如对电话核心模块JSSDK推送模块的监控及调优如引入使用协程池，openid转换引入内存缓存，服务隔离部署等，从原来的推送时延高、毛刺多到推送平滑稳定，都离不开这些工具的辅助。
未来除系统及应用程序指标的监控外还将持续完善业务告警监控和业务自定义监控指标，提高业务运营的可观测性及提前发现问题的能力。
参考文献
·https://mp.weixin.qq.com/s/o2oMMh0PF5ZSoYD0XOBY2Q
E N D
往期推荐