go内存泄露case

chosen0ne · · 5679 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

用go写了一个守护进程程序:用于检测redis的存活状态并将结果写到zookeeper中,部署到redis机器上,对于每个redis实例会有一个goroutine每隔固定时间去检测其状态,由主goroutine负责信号处理等,再接收到信号时kill其他的goroutine。程序运行了一段时间发现,有些redis实例的对应zookeeper的信息不更新,通过日志发现对应redis的goroutine挂掉了。阅读源码发现貌似是zk的第三方库抛出一个非预期的异常导致。

为了解决这个问题,对逻辑重构:由主goroutine每隔固定时间,对于每个redis实例启动一个goroutine去进行检测,避免出现非预期异常导致goroutine挂掉,从而状态信息不更新的情况。由于goroutine的创建开销很低,并且golang官方推荐使用大量的goroutine来抗并发,所以这种方式实现也很合理。重构完,上线测试发现存在内存泄露。

(1)观察GC

首先对代码review,因为半年前写的,并且最近都没用golang,所以没有发现bug。接着,就想看下gc相关的信息,也许可能透漏些东西。网上查了golang gc相关,在runtime的doc中描述了,通过设置环境变量GODEBUG='gctrace=1'可以让go的运行时把gc信息打印到stderr。

GODEBUG='gctrace=1' ./sentinel-agent >gc.log &
gc.log的输出如下:

gc781(1): 1+2385+17891+0 us, 60 -> 60 MB, 21971 (3503906-3481935) objects, 13818/14/7369 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc782(1): 1+1794+18570+1 us, 60 -> 60 MB, 21929 (3503906-3481977) objects, 13854/1/7315 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc783(1): 1+1295+20499+0 us, 59 -> 59 MB, 21772 (3503906-3482134) objects, 13854/1/7326 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc781:从程序启动开始,第781次gc

(1):参与gc的线程个数

1+2385+17891+0:分别是1)stop-the-world的时间,即暂停所有goroutine;2)清扫标记对象的时间;3)标记垃圾对象的时间;4)等待线程结束的耗时。单位都是us,4者之和就是gc暂停的整体耗时

60 -> 60 MB:gc后,堆上存活对象占用的内存,以及整个堆大小(包括垃圾对象)

21971 (3503906-3481935) objects:gc后,堆上的对象数量,gc前分配的对象以及本次释放的对象

13818/14/7369 sweeps:描述对象清扫阶段。一共有13818个memory span,其中14在后台被清扫,7369在stop-the-world期间被清扫

0(0) handoff,0(0) steal:描述并行标记阶段的负载均衡特性。当前在不同线程间传送操作数和总传送操作数,以及当前steal操作数和总steal操作数

0/0/0 yields:描述并行标记阶段的效率。在等待其他线程的过程中,一共有0次yields操做

经过观察gc的输出,发现当前堆上对象总数不断增多,没有减少的趋势,这说明存在对象的泄露,从而导致内存泄露。

(2)memory profile

根据golang官网profile指南,在代码中添加

import _ "net/http/pprof"

func main() {
    go func() {
        http.ListenAndServe("localhost:6060", nil)
    }()
}
可以在运行时对程序进行profile,通过http访问:

go tool pprof http://localhost:6060/debug/pprof/heap

进行memory profile,默认是--inuse_space,显示当前活跃的对象(不包括垃圾对象)占用的空间。使用--alloc_space可以显示所有分配的对象(包括垃圾对象)。不过这两种方式都没有发现异常。

(3)监控goroutine个数

通过runtime.NumGoroutine()可以获取当前的goroutine的个数。通过给程序添加http server获取一些统计信息来了解程序的运行状态,这是Jeff Dean推崇的方法。通过添加下述代码来实时查看goroutine的个数

    // goroutine stats and pprof
    go func() {
        http.HandleFunc("/goroutines", func(w http.ResponseWriter, r *http.Request) {
            num := strconv.FormatInt(int64(runtime.NumGoroutine()), 10)
            w.Write([]byte(num))
        });
        http.ListenAndServe("localhost:6060", nil)
        glog.Info("goroutine stats and pprof listen on 6060")
    }()
通过命令:

curl localhost:6060/goroutines

查询当前的goroutine的个数。通过不程序运行期间,不断查看,发现goroutine个数不断增加,没有销毁的迹象。

(4)goroutine泄露

通过上面的观察,发现存在goroutine泄露,即goroutine没有正常退出。由于每轮(每隔10秒执行一次)都会创建多个goroutine,如果不能正常退出,则会存在大量的goroutine。go的gc使用的是mark and sweep,会从全局变量、goroutine的栈为根集合扫描所有的存活对象,如果goroutine不退出,就会泄露大量内存。

在确定是由于goroutine没有正常退出后,重新review代码,发现了泄露的根本原因。在重构前,在信号处理程序中,为了正常结束程序,对于每个goroutine都有一个channel,用于主goroutine等待所有goroutine正常结束后再退出。主goroutine中,信号处理程序用于等待所有goroutine的代码:

waiters = make([]chan int, Num)
for _, w := range waiters {
    <- w
}

执行检查逻辑的goroutine在结束后,会调用ag.w <- 1,用于向主goroutine发送消息。

重构后,由于每轮都会创建goroutine,由于用于主goroutine和检查逻辑的goroutine之间的channel的大小是1,所以所有创建的检查goroutine都阻塞在ag.w <- 1上,不能正常退出。最后,把channel逻辑去掉,就不存在goroutine泄露了。

(5)总结

- goroutine的管理很重要,如果goroutine泄露,就会存在内存泄露

- 内嵌http server,用于查看程序运行状态

- 目前,go的gc还比较脆弱,尽量减少对象的创建,能缓存的就缓存。因为对象多了的话,扫描的时间也会加长

版权声明:本文为博主原创文章,未经博主允许不得转载。


有疑问加站长微信联系(非本文作者)

本文来自:CSDN博客

感谢作者:chosen0ne

查看原文:go内存泄露case

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:692541889

5679 次点击  ∙  1 赞  
加入收藏 微博
1 回复  |  直到 2000-01-01 00:00:00
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传