1、出现内存泄漏 1.1 事发现场
在风和日丽的一天,本人正看着需求、敲着代码,展望美好的未来。突然收到一条内存使用率过高的告警。
1.2 证人证词 告警的这个项目,老代码是python的,最近一直在go化。随着go化率不断上升,发现内存的RSS使用率越飙越高。最终达到容器内存限制后,进程会自动重启。RSS如下图所示:
2、排查内存泄露 2.1 分析问题 看到这种不正常的RSS增长,第一反应是:是不是最近上的代码有什么问题?是不是发生了内存泄露?内存泄露可是大事,赶紧查查。于是将时间线拉长,看看是从哪天开始的。结果,现实是很残酷的。从项目刚上线的时候就有这个问题了。由于项目是2周一个版本,以前是还没达到内存限制,所以没有发出告警。
那么问题应该就是在最初的版本里。这个时候就想了想,难道是我们使用的框架本身存在缺陷?但是很快就否定了这个想法,因为我们使用的框架是其他项目已经上线已久的成熟框架。不应该有这个问题。
显然,看代码这种本办法是不可能发现问题的。于是想到了golang的性能分析工具pprof。由于pprof线上环境是不开启的,所以排查我这里只能去预发环境。
2.2 寻找问题 2.2.1 获取内存使用监控 复制 go tool pprof - source_path=/ path/ to/ gopath - inuse_space https: // target.service .url / debug/ pprof/ allocs
-source_path Search path for source files 是分析代码时,需要用到源码路径,这里就是你自己本地的gopath路径 /debug/pprof/allocs -inuse_space Same as -sample_index=inuse_space 是监控使用中的内存。因为我们分析的是内存泄露,所以要查看的是实际占用的内存 输入以上命令,会出现以下界面的内容:
2.2.2 分析内存监控 2.2.2.1 获取top10的内存占用
由于我们需要分析内存占用,所以这个时候输入一个top10,看看占用内存前10的都是哪些代码。
复制
(pprof) top 10
Showing nodes accounting for 145.07MB, 92.64% of 156.59MB total
Dropped 163 nodes (cum <= 0.78MB)
Showing top 10 nodes out of 157
flat flat% sum% cum cum%
117.36MB 74.95% 74.95% 117.36MB 74.95% github.com/beorn7/perks/quantile.newStream (inline)
14.55MB 9.29% 84.25% 134.42MB 85.84% github.com/prometheus/client_golang/prometheus.newSummary
3.53MB 2.25% 86.50% 4.06MB 2.59% compress/flate.NewWriter
2MB 1.28% 87.77% 2MB 1.28% github.com/prometheus/client_golang/prometheus.MakeLabelPairs
1.53MB 0.97% 88.75% 1.53MB 0.97% github.com/rcrowley/go-metrics.newExpDecaySampleHeap
1.50MB 0.96% 89.71% 1.50MB 0.96% go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).snapshot
1.50MB 0.96% 90.67% 1.50MB 0.96% github.com/Shopify/sarama.(*TopicMetadata).decode
1.06MB 0.68% 91.35% 1.06MB 0.68% github.com/valyala/fasthttp/stackless.NewFunc
1.03MB 0.66% 92.00% 1.03MB 0.66% github.com/xdg-go/stringprep.init
1MB 0.64% 92.64% 1MB 0.64% strings.(*Builder).WriteByte
1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16.
这个时候需要解释一下显示的指标的含义
flat:函数在内存上的占用 flat%:函数在内存占用上的占用百分比 sum%:是从上往下到当前行所有函数累加使用内存的比例 如第二行,sum=84.25=74.95+9.29 cum:这个函数以及子函数运行所占用的内存,应该大于等于flat cum%:这个函数以及子函数运行所占用的内存的比例,应该大于等于flat% 2.2.2.2 查看占用函数调用栈
看完以上返回,明眼人应该就能看出,第一行这个newStream问题很大呀,让我们进去看看他哪行代码出了问题。需要用到一下命令
让我们输入list github.com/beorn7/perks/quantile.newStream一探究竟
(pprof) list: Output annotated source for functions matching regexp 显示具体调用的代码块并显示相应指标
复制
( pprof) list github.com / beorn7/ perks/ quantile.newStream
Total: 156.59 MB
ROUTINE ======================== github.com / beorn7/ perks/ quantile.newStream in pkg/ mod/ github.com / beorn7/ perks@v1.0 .1 / quantile/ stream.go
117.36 MB 117.36 MB ( flat, cum) 74.95 % of Total
. . 128 : sorted bool
. . 129 : }
. . 130 :
. . 131 : func newStream( ƒ invariant) * Stream {
. . 132 : x : = & stream{ ƒ: ƒ}
117.36 MB 117.36 MB 133 : return & Stream{ x, make( Samples, 0 , 500 ) , true }
. . 134 : }
. . 135 :
. . 136 : // Insert inserts v into the stream.
. . 137 : func ( s * Stream) Insert ( v float64) {
. . 138 : s.insert ( Sample{ Value: v, Width: 1 } )
1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16.
2.2.2.3 分析泄露原因
看到这里,应该能看出这个newStream的内存占用,主要是因为生成了一个容量为500的数组。那这个数组是什么样的呢?
复制
type Sample struct {
Value float64 `json:",string"`
Width float64 `json:",string"`
Delta float64 `json:",string"`
}
以上结构可以看出,生成一次需要占用的内存是50038字节,那么一次就是12000个字节,差不多是11.72kb。这么看来,应该是有个地方不停的调用,导致数据持续膨胀。看到这里,我们继续往下追。
复制
(pprof) list github.com/prometheus/client_golang/prometheus.newSummary
Total: 156.59MB
ROUTINE ======================== github.com/prometheus/client_golang/prometheus.newSummary in pkg/mod/github.com/prometheus/client_golang@v1.12.2/prometheus/summary.go
14.55MB 134.42MB (flat, cum) 85.84% of Total
. . 220: }
. . 221: s.init(s) // Init self-collection.
. . 222: return s
. . 223: }
. . 224:
512.12kB 512.12kB 225: s := &summary{
. . 226: desc: desc,
. . 227:
. . 228: objectives: opts.Objectives,
. . 229: sortedObjectives: make([]float64, 0, len(opts.Objectives)),
. . 230:
. 1MB 231: labelPairs: MakeLabelPairs(desc, labelValues),
. . 232:
7.03MB 7.03MB 233: hotBuf: make([]float64, 0, opts.BufCap),
7.03MB 7.03MB 234: coldBuf: make([]float64, 0, opts.BufCap),
. . 235: streamDuration: opts.MaxAge / time.Duration(opts.AgeBuckets),
. . 236: }
. . 237: s.headStreamExpTime = time.Now().Add(s.streamDuration)
. . 238: s.hotBufExpTime = s.headStreamExpTime
. . 239:
. . 240: for i := uint32(0); i < opts.AgeBuckets; i++ {
. 118.86MB 241: s.streams = append(s.streams, s.newStream())
. . 242: }
. . 243: s.headStream = s.streams[0]
. . 244:
. . 245: for qu := range s.objectives {
. . 246: s.sortedObjectives = append(s.sortedObjectives, qu)
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.
由此看出,还不止使用一次newStream()。通过观看代码,我这里发现,此处的opts.AgeBuckets是等于5的,那么就意味着,循环生成了5个stream,实际上占用的内存是500*3*8*5=60000字节,也就是58.6kb。
2.2.2.4 分析调用链路
那么现在基本追溯完了大概的泄露原因。那怎么样能寻找是具体的调用链的呢,总不能一层一层往上查找调用吧?这个时候pprof提供了一个命令,可以把整体调用生成一张图片展示。命令如下:
复制 go tool pprof - png - source_path=/ path/ to/ gopath - inuse_space https: // target.service .url / debug/ pprof/ allocs > heap.png
只需要在命令中加一个-png,那么就会生成一张图片。当然为了方便寻找,最后可以指定图片生成地址。我这边抓取了和本文有关的一段截图,如下。
根据上图链路,我们大致可以看出。应该是mysql的调用,在OnFinished处,prometheus的上报的地方出现了内存泄露。这个时候我们就可以追一下OnFinished处的代码了,因为之后的都是prometheus的调用,这是一个成熟的三方,理论不应该是他这个点出问题。
2.2.3 寻找泄露代码 OnFinished的代码如下:
复制 label : = append( [ ] string{ getOperation( db) , s.host , s.database , tableName, hasErr, sqlState} , metrics.InjectTagValue ( collector.MetricsTitle , db.Statement .Context , attachment) ...)
elapsed : = time .Since ( s.StartTime ) .Seconds ( )
collector.DurationReporter .Collector .( prometheus.ObserverVec ) .WithLabelValues ( label...) .Observe ( elapsed)
看到这里我想大家就应该知道了,go代码会为prometheus创建一个5*500的缓冲池,来记录数据,prometheus会周期性的调用/mertic来拉取对应的内容。那么这里是怎么造成内存泄露的呢?这里就要分析上述代码的这个label了。
复制
func ( m * MetricVec) GetMetricWithLabelValues( lvs ...string) ( Metric, error) {
h, err : = m.hashLabelValues ( lvs)
if err != nil {
return nil, err
}
return m.metricMap .getOrCreateMetricWithLabelValues ( h, lvs, m.curry ) , nil
}
func ( m * MetricVec) hashLabelValues( vals [ ] string) ( uint64, error) {
if err : = validateLabelValues( vals, len( m.desc .variableLabels ) - len( m.curry ) ) ; err != nil {
return 0 , err
}
var (
h = hashNew( )
curry = m.curry
iVals, iCurry int
)
for i : = 0 ; i < len( m.desc .variableLabels ) ; i++ {
if iCurry < len( curry) && curry[ iCurry] .index == i {
h = m.hashAdd ( h, curry[ iCurry] .value )
iCurry++
} else {
h = m.hashAdd ( h, vals[ iVals] )
iVals++
}
h = m.hashAddByte ( h, model.SeparatorByte )
}
return h, nil
}
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. 2.3 发现问题(伪) 通过查看函数调用,我这边发现label最终进入的是这个hashLabelValues中,如果已存在就返回对应的metricMap中的内容,如果不一样,则会创建一个新的缓冲池。内存泄露就出在这个创建中。
这个时候我就在想,难道是我们label采集的数据太多了?通过排列组合,我估算了一下内存最大值
getOperation(db)=4(操作类型,增删改查4种)
s.host=1
s.database=3(我们有3个db实例)
tableName=30(表名,保守估计最少30个)
hasErr, sqlState=2 (报错与没报错2个状态)
metrics.InjectTagValue(collector.MetricsTitle, db.Statement.Context, attachment)...
这里面记录的是请求,保守估计最少40个接口
这样算下来:4*1*3*30*2*40*5*500*8*3=1648mb。再加上程序本身的一些内存开销,感觉和我们碰到的问题能对上了。
2.4 解决问题(伪) 于是一拍脑袋觉得发现了问题,但是又无法解决问题(抓的指标无法修改)。于是屁颠屁颠的升了服务器配置,将4c2g升为了4c4g。
3、解决内存泄漏 3.1 发现问题(真) 没错,当你看到这里的时候,就知道,升配这件事情并没有结束。现实给了我一记响亮的耳光。
因为升配以后总觉得还是哪里有问题。于是还是每天都在不停的观察RSS情况。结果,还真发现问题了。因为内存还在坐火箭,这不科学啊。
当我准备继续深入研究代码的时候,我的一位同事提醒了我,你可以去看下/metrics具体上报了什么。说时迟那时快。于是抓取了/metrics里的上报数据,看到了以下数据:
复制
go_mysql_execute_count_total{ command= "SELECT" , db= "db_xxxxxx" , endpoint= "[DELETE]/url/:id" , error= "false" , host= "xxxxxx" , main_table= "table_xxxxxx" , sql_state= "0" , startpoint= "/url/49630"
} 1
go_mysql_execute_count_total{ command= "SELECT" , db= "db_xxxxxx" , endpoint= "[DELETE]/url/:id" , error= "false" , host= "xxxxxx" , main_table= "table_xxxxxx" , sql_state= "0" , startpoint= "/url/49631"
} 1
go_mysql_execute_count_total{ command= "SELECT" , db= "db_xxxxxx" , endpoint= "[DELETE]/url/:id" , error= "false" , host= "xxxxxx" , main_table= "table_xxxxxx" , sql_state= "0" , startpoint= "/url/49668"
} 1
go_mysql_execute_count_total{ command= "SELECT" , db= "db_xxxxxx" , endpoint= "[DELETE]/url/:id" , error= "false" , host= "xxxxxx" , main_table= "table_xxxxxx" , sql_state= "0" , startpoint= "/url/49673"
} 1
这不看不要紧,一看——原来startpoint里上报的是restful风格的请求地址。那么上面的计算缓冲池的算法,就要再乘一个无限膨胀的startpoint。这给多少个G内存也都不够。
于是继续查看代码,看能不能关闭startpoint上报。这一查,果然有:
3.2 解决问题(真) 看到这个设置START_POINT的环境变量,能关闭startpoint上报。于是立马加到生产环境后重启服务器。上线后观察了一段时间,RSS使用量如下图所示:
到此,此次内存泄露问题终于排查并修复完成。真是有惊无险。
4、内存泄露问题总结 这边大致归纳下go语言中有哪些常见的内存泄露。
常见内存泄露 4.1 Goroutine泄漏 goroutine泄露是开发过程中碰到最常见、最频繁的。一般经常碰到的是以下几种,由于网上相关的文章太多了,就不用代码举例了。
4.1.1 协程无法退出 锁占用 channel无法读取或写入 协程中逻辑有死循环 4.1.2 协程阻塞 协程业务逻辑时间长,释放速度跟不上生成速度 4.1.3 内存使用不当 持续增长的常驻协程,申请了大量内存空间,由于是常驻的协程,不会释放内存造成泄露 并发申请大量内存后,未达到GC时间或GC阈值,未触发GC,导致内存泄露 4.2 结构使用不当 结构使用不当也是开发中常见的,只是可能并发不高,或者内存泄露的不多,导致使用者容易忽视掉。
4.2.1 字符串、切片截取
复制 func main() {
var str0 = "1234567890"
str1 := str0[:5]
}
func main() {
var s0 = []int{1,2,3,4,5,6,7,8,9,0}
s1 := s0[:5]
}
上面两段代码,会有5个字节的泄露,因为字符串和切片的两个变量,底层是共享内存的。只要str1或s1一直在用,str0和s0就不会回收。这样剩下的5个字节或者5个int就会有临时的泄露。这个场景,如果在高并发,并且数据够大的情况下,就算是临时的泄露,也可能对性能有极大的影响。
4.2.2 指针类型
复制 func main() {
var prt0 = []*int{new(int), new(int), new(int), new(int), new(int)}
ptr1 := prt0[:3]
}
指针类型的这段代码,其实和上面字符串、切片的例子很像,指针是指向内存地址的。只要ptr1没释放,前面的指针数组中未被用的指针就不会释放,从而导致临时的内存泄露。
4.2.3 数组传参
复制 func main( ) {
var arr1 = [ 3 ] int { 1 , 2 , 3 }
var arr2 = [ 3 ] int { }
arr2 = arr1
fmt.Printf ( "array address :%p, array : %+v \n" , & arr1, arr1)
fmt.Printf ( "array address :%p, array : %+v \n" , & arr2, arr2)
test( arr1)
}
func test( arr [ 3 ] int ) {
fmt.Printf ( "array address :%p, array : %+v \n" , & arr, arr)
}
1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 打印结果如下:
复制
array address : 0xc000122030 , array : [ 1 2 3 4 5 ]
array address : 0xc000122060 , array : [ 1 2 3 4 5 ]
array address : 0xc0001220f0 , array : [ 1 2 3 4 5 ]
看结果可知,三条打印的地址各不相同,说明数组是值传递的,那这会有什么问题呢?毕竟我们很多代码都是这么写的。
问题在于,只要传递的这个数组足够大,那么调用一次就会生成一个一样大小的新地址,这样会消耗大量内存。如果短时间内无法GC,会产生临时的内存泄露。这种泄露对于高并发是致命的。
4.2.4 定时器
复制 func main( ) {
chi : = make( chan int )
go func( ) {
for {
timer : = time .After ( 10 * time .Second )
select {
case <- ch:
fmt.Println ( "get it" )
case <- timer:
fmt.Println ( "end" )
}
}
} ( )
for i: = 1 ; i< 1000000 ; i++ {
chi <- i
time .sleep ( time .Millisecond )
}
}
1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 以上代码,之所以会造成内存泄露。是因为time.After的底层是实现了一个timer,只要定时器未到时间,这个定时器就不会被gc回收,从而造成临时的内存泄露。如果这里的代码没写好,定时器都是新创建的,那么就会造成永久性的泄露。
其实golang中的内存泄露远不止上文提到的这些。有些可能甚至连查都查不到。这个时候还是要提醒大家,不仅要了解问题,还要学会查找问题。这样不管遇到什么问题,都能发现蛛丝马迹,问题也将迎刃而解。