那些年我们一起踩过的Golang坑(一)

可能引起内存泄漏的time.After()方法

接触golang已经有半年的时间了, 这段时间在写一个MQTT的gateway, 架构很简单用golang实现MQTT协议, 用kafka作为消息中间件服务.

今天要记录的是在使用过程中遇到的一个坑:

场景: 用测试用例往gateway中发数据, 500个线程, 每个线程发20k条, 不间断, 所以发了10M条数据, 每条的内容是18-20个字节不等的MQTT消息. 省去调试的过程, 10M条消息在测试端都接收到了, 消息峰值大概是10k条/s(qos=0) 但是打开任务管理器(我用的windows开发环境)发现server服务的占用内存始终在1G+下不来.

于是准备用pprof作内存分析, pprof的使用, 移步 pprof使用描述

隐式引入pprof

_ "net/http/pprof"

在主进程中加入监听

	go func() {
		http.ListenAndServe("0.0.0.0:9090", nil)
	}()

然后重新跑一遍测试用例. 结束之后, server的内存在1G+.

命令行调用

go tool pprof http=localhost:9090/debug/pprof/heap

在命令中输入web, 可以打开图形界面观察

Fetching profile over HTTP from http://localhost:9090/debug/pprof/heap
Saved profile in C:\Users\Elvis\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz
Type: inuse_space
Time: Aug 21, 2019 at 10:10am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web

从图片中可以看到, time.NewTimer 占用了83.44%的堆内存, 并且随着时间的推移, 这部分占用的内存并没有得到释放.

在箭头上方的提示中找到这段代码的位置是在mdmp_handler中, time.After()中的调用.

找到出错处的源码:

if connMsg.FixedHeader.PackageType == constant.MQTT_MSG_TYPE_CONNECT && h.dealConnect(connMsg, client) {
		x := make(chan bool)
		for {
			//监听超时, 异步读取数据
			go func() {
				n, err = reader.Read(buff)
				logger.Debug("received bytes of ", n, " ", err)
				if n > 0 {
					client.DealByteArray(buff[:n])
					x <- true
					return
				}
				if err != nil {
					if err == io.EOF {
						logger.Info("connection closed by client")
					} else {
						client.Will(connMsg)
						logger.Error(err.Error())
					}
					client.Closing <- true
					return
				}
			}()
			select {
			case <-x: //正常收取消息
				continue
			case <-time.After(time.Duration(3*connMsg.VariableHeader.KeepAliveTimer/2) * time.Second): //超时
				logger.Warn("connection time out")
				client.Will(connMsg)
				h.activeConn.Delete(client)
				client.Close()
				return
			case <-client.Closing: //客户端关闭
				h.activeConn.Delete(client)
				client.Close()
				return
			}
		}
	}

为了确保是time.After()导致的内存占用, 注释掉了

//			case <-time.After(time.Duration(3*connMsg.VariableHeader.KeepAliveTimer/2) * time.Second): //超时
//				logger.Warn("connection time out")
//				client.Will(connMsg)
//				h.activeConn.Delete(client)
//				client.Close()
//				return

再测, 10M条数据过后, server的内存占用稳定在60M上下, 在测试的过程中也一直稳定在这个数值内

居然就是这里!

同时, 我猜测是golang在for循环结束之前资源没有自动gc, 于是编写了测试用例, 将timer放在gorouting中(gorouting结束了肯定要GC吧), 进行测试:

package timer

import (
	"fmt"
	"sync"
	"testing"
	"time"
)

func TestName(t *testing.T) {
	wg := sync.WaitGroup{}
	ch := make(chan bool)
	//timeout := make(chan bool)
	for i := 0; i < 10000000; i++ {
		wg.Add(1)
		go func() {
			ch <- true
		}()
		select {
		case <-ch:
			//fmt.Println(i, " finished")
		case <-time.After(10 * time.Second):
			fmt.Println(i, " timed out")
		}
		wg.Done()
	}
	wg.Wait()
	fmt.Println("all finished")
	time.Sleep(1000 * time.Second)
}

结果是打印了 "all finished"之后, 内存持续占用2G以上!

以上, time.After()不释放内存和for循环无关.

再观察一下time.After()的源码

// After waits for the duration to elapse and then sends the current time
// on the returned channel.
// It is equivalent to NewTimer(d).C.
// The underlying Timer is not recovered by the garbage collector
// until the timer fires. If efficiency is a concern, use NewTimer
// instead and call Timer.Stop if the timer is no longer needed.
func After(d Duration) <-chan Time {
	return NewTimer(d).C
}

The underlying Timer is not recovered by the garbage collector until the timer fires. If efficiency is a concern, use NewTimer instead and call Timer.Stop if the timer is no longer needed.
垃圾收集器无法恢复基础Timer, 直到计时器开火。 如果要考虑效率，请使用NewTimer, 相反，如果不再需要定时器，则调用Timer.Stop。

GC不会自动回收time.After()的timer, 需要调用, time.Timer.Stop()释放掉内存