Golang crypto/tls 内存泄漏问题

huangapple go评论68阅读模式
英文:

Golang crypto/tls memory leak

问题

问题:为什么即使变量超出作用域并且使用(*tls.Conn).Close()方法正确关闭了,*tls.Conn仍然没有被垃圾回收?下面是复现问题的完整代码。

动机:作为长时间运行的服务(> 24小时)的一部分,我已经尝试了2个websocket库(https://github.com/gorilla/websocket和https://github.com/gobwas/ws),它们在其生命周期内作为客户端维护了约10个websocket连接。有时它们会与服务器断开连接,在这种情况下我会建立新的连接。内存使用量在其生命周期内稳步增长,并且从内存分析来看,指向底层*tls.Conn对象的指针仍然存在于堆上(没有被垃圾回收)。

复现问题的完整代码:

package main

import (
	"crypto/tls"
	"fmt"
	"log"
	_ "net/http/pprof"
	"os"
	"os/signal"
	"runtime"
	"syscall"
	"time"
)

func finalizer(_ interface{}) {
	fmt.Println("finalizer called")
}

func main() {
	// setup interrupt handler
	c := make(chan os.Signal)
	signal.Notify(c, os.Interrupt, syscall.SIGTERM)

	for i := 0; i < 100; i++ {
		go func() {
			for {
				tlsConnectThenCloseAfterWait()
			}
		}()
	}

	<-c
	os.Exit(1)

}

func tlsConnectThenCloseAfterWait() {
	conn, err := tls.Dial("tcp", "mail.google.com:443", &tls.Config{})
	if err != nil {
		log.Fatalln("failed to connect: " + err.Error())
	}
	defer func() {
		err := conn.Close()
		if err != nil {
			log.Fatalln("closing conn failed")
		}
	}()

	runtime.SetFinalizer(conn, finalizer)
	conn.Write([]byte("hello how are you"))

	timer := time.NewTimer(time.Second)
	<-timer.C
}

GODEBUG=gctrace=1 ./main的输出结果:

gc 1 @0.088s 1%: 0+9.0+0 ms clock, 0+12/11/0+0 ms cpu, 4->5->1 MB, 5 MB goal, 12 P
gc 2 @0.102s 3%: 0+4.9+0.99 ms clock, 0+5.9/6.0/0+11 ms cpu, 4->4->1 MB, 5 MB goal, 12 P
gc 3 @0.114s 5%: 0+4.9+1.0 ms clock, 0+3.9/10/2.9+12 ms cpu, 4->4->2 MB, 5 MB goal, 12 P
gc 4 @0.171s 4%: 0+5.0+0 ms clock, 0+1.0/9.9/0+0 ms cpu, 4->5->3 MB, 5 MB goal, 12 P
gc 5 @0.196s 4%: 0+5.9+0 ms clock, 0+2.9/9.9/0+0 ms cpu, 5->7->3 MB, 6 MB goal, 12 P
gc 6 @0.352s 2%: 1.0+2.0+0 ms clock, 12+0/1.9/1.9+0 ms cpu, 6->7->4 MB, 7 MB goal, 12 P
gc 7 @0.365s 2%: 0.99+3.0+0 ms clock, 11+3.0/5.0/0+0 ms cpu, 7->8->5 MB, 8 MB goal, 12 P
gc 8 @0.399s 3%: 0+13+0 ms clock, 0+18/29/1.0+0 ms cpu, 9->11->6 MB, 10 MB goal, 12 P
gc 9 @1.278s 1%: 1.0+28+0 ms clock, 12+9.9/53/0+0 ms cpu, 10->13->9 MB, 13 MB goal, 12 P
gc 10 @1.433s 2%: 1.0+22+0 ms clock, 12+45/55/1.0+0 ms cpu, 14->16->9 MB, 18 MB goal, 12 P
gc 11 @1.534s 2%: 0+6.0+0 ms clock, 0+4.0/15/3.0+0 ms cpu, 16->17->11 MB, 19 MB goal, 12 P
gc 12 @2.479s 1%: 0+3.0+0 ms clock, 0+0/6.0/18+0 ms cpu, 20->20->12 MB, 22 MB goal, 12 P
gc 13 @2.656s 1%: 1.0+10+0 ms clock, 12+3.0/30/4.9+0 ms cpu, 23->25->16 MB, 25 MB goal, 12 P
gc 14 @3.737s 1%: 0+6.0+0 ms clock, 0+3.0/18/9.0+0 ms cpu, 31->33->20 MB, 33 MB goal, 12 P
gc 15 @4.830s 0%: 0+5.9+0 ms clock, 0+5.0/13/16+0 ms cpu, 39->40->25 MB, 41 MB goal, 12 P
gc 16 @6.733s 0%: 0.99+16+0.99 ms clock, 11+7.9/47/80+11 ms cpu, 50->50->32 MB, 51 MB goal, 12 P
gc 17 @8.140s 0%: 0.99+21+0 ms clock, 11+3.0/59/125+0 ms cpu, 64->64->42 MB, 65 MB goal, 12 P
gc 18 @11.168s 0%: 1.0+28+0 ms clock, 12+24/78/97+0 ms cpu, 82->82->54 MB, 84 MB goal, 12 P
gc 19 @14.433s 0%: 0.99+27+0 ms clock, 11+9.0/74/146+0 ms cpu, 106->106->70 MB, 108 MB goal, 12 P
gc 20 @18.883s 0%: 0+47+0 ms clock, 0+6.0/133/211+0 ms cpu, 137->138->91 MB, 140 MB goal, 12 P
gc 21 @24.437s 0%: 0.99+30+0.99 ms clock, 11+15/91/101+11 ms cpu, 177->178->118 MB, 182 MB goal, 12 P
gc 22 @31.872s 0%: 1.0+105+0 ms clock, 12+60/317/256+0 ms cpu, 230->233->155 MB, 236 MB goal, 12 P
gc 23 @41.705s 0%: 0+101+0 ms clock, 0+15/283/549+0 ms cpu, 302->303->200 MB, 310 MB goal, 12 P
gc 24 @54.302s 0%: 0+92+0 ms clock, 0+9.0/278/472+0 ms cpu, 390->392->260 MB, 400 MB goal, 12 P
gc 25 @70.777s 0%: 0+38+0 ms clock, 0+4.9/113/321+0 ms cpu, 508->508->337 MB, 521 MB goal, 12 P
gc 26 @92.203s 0%: 0+108+0 ms clock, 0+57/326/391+0 ms cpu, 658->662->442 MB, 675 MB goal, 12 P
gc 27 @120.781s 0%: 2.0+99+0 ms clock, 24+11/292/529+0 ms cpu, 862->864->574 MB, 884 MB goal, 12 P

finalizer从未被调用,内存不断增长。

使用go version go1.15.8 windows/amd64

还与此处的GitHub问题链接:https://github.com/golang/go/issues/41987

英文:

Question: Why is *tls.Conn not being garbage collected even after the variable goes out of scope, and it's properly closed using the (*tls.Conn).Close() method? Full code to reproduce given below.

Motivation: I've tried 2 websocket libraries (https://github.com/gorilla/websocket and https://github.com/gobwas/ws) so far as part of long-running service (> 24 hours), which maintains ~10 websocket connections as a client throughout its lifetime. Sometimes they are disconnected from the server, in which case I make a new connection. The memory usage steadily grows throughout its lifetime, and from memory profiles, it points to the underlying *tls.Conn object staying on the heap. (not being garbage collected).

Full code to reproduce

package main

import (
	&quot;crypto/tls&quot;
	&quot;fmt&quot;
	&quot;log&quot;
	_ &quot;net/http/pprof&quot;
	&quot;os&quot;
	&quot;os/signal&quot;
	&quot;runtime&quot;
	&quot;syscall&quot;
	&quot;time&quot;
)

func finalizer(_ interface{}) {
	fmt.Println(&quot;finalizer called&quot;)
}

func main() {
	// setup interrupt handler
	c := make(chan os.Signal)
	signal.Notify(c, os.Interrupt, syscall.SIGTERM)

	for i := 0; i &lt; 100; i++ {
		go func() {
			for {
				tlsConnectThenCloseAfterWait()
			}
		}()
	}

	&lt;-c
	os.Exit(1)

}

func tlsConnectThenCloseAfterWait() {
	conn, err := tls.Dial(&quot;tcp&quot;, &quot;mail.google.com:443&quot;, &amp;tls.Config{})
	if err != nil {
		log.Fatalln(&quot;failed to connect: &quot; + err.Error())
	}
	defer func() {
		err := conn.Close()
		if err != nil {
			log.Fatalln(&quot;closing conn failed&quot;)
		}
	}()

	runtime.SetFinalizer(conn, finalizer)
	conn.Write([]byte(&quot;hello how are you&quot;))

	timer := time.NewTimer(time.Second)
	&lt;-timer.C
}

Output of GODEBUG=gctrace=1 ./main

gc 1 @0.088s 1%: 0+9.0+0 ms clock, 0+12/11/0+0 ms cpu, 4-&gt;5-&gt;1 MB, 5 MB goal, 12 P
gc 2 @0.102s 3%: 0+4.9+0.99 ms clock, 0+5.9/6.0/0+11 ms cpu, 4-&gt;4-&gt;1 MB, 5 MB goal, 12 P
gc 3 @0.114s 5%: 0+4.9+1.0 ms clock, 0+3.9/10/2.9+12 ms cpu, 4-&gt;4-&gt;2 MB, 5 MB goal, 12 P
gc 4 @0.171s 4%: 0+5.0+0 ms clock, 0+1.0/9.9/0+0 ms cpu, 4-&gt;5-&gt;3 MB, 5 MB goal, 12 P
gc 5 @0.196s 4%: 0+5.9+0 ms clock, 0+2.9/9.9/0+0 ms cpu, 5-&gt;7-&gt;3 MB, 6 MB goal, 12 P
gc 6 @0.352s 2%: 1.0+2.0+0 ms clock, 12+0/1.9/1.9+0 ms cpu, 6-&gt;7-&gt;4 MB, 7 MB goal, 12 P
gc 7 @0.365s 2%: 0.99+3.0+0 ms clock, 11+3.0/5.0/0+0 ms cpu, 7-&gt;8-&gt;5 MB, 8 MB goal, 12 P
gc 8 @0.399s 3%: 0+13+0 ms clock, 0+18/29/1.0+0 ms cpu, 9-&gt;11-&gt;6 MB, 10 MB goal, 12 P
gc 9 @1.278s 1%: 1.0+28+0 ms clock, 12+9.9/53/0+0 ms cpu, 10-&gt;13-&gt;9 MB, 13 MB goal, 12 P
gc 10 @1.433s 2%: 1.0+22+0 ms clock, 12+45/55/1.0+0 ms cpu, 14-&gt;16-&gt;9 MB, 18 MB goal, 12 P
gc 11 @1.534s 2%: 0+6.0+0 ms clock, 0+4.0/15/3.0+0 ms cpu, 16-&gt;17-&gt;11 MB, 19 MB goal, 12 P
gc 12 @2.479s 1%: 0+3.0+0 ms clock, 0+0/6.0/18+0 ms cpu, 20-&gt;20-&gt;12 MB, 22 MB goal, 12 P
gc 13 @2.656s 1%: 1.0+10+0 ms clock, 12+3.0/30/4.9+0 ms cpu, 23-&gt;25-&gt;16 MB, 25 MB goal, 12 P
gc 14 @3.737s 1%: 0+6.0+0 ms clock, 0+3.0/18/9.0+0 ms cpu, 31-&gt;33-&gt;20 MB, 33 MB goal, 12 P
gc 15 @4.830s 0%: 0+5.9+0 ms clock, 0+5.0/13/16+0 ms cpu, 39-&gt;40-&gt;25 MB, 41 MB goal, 12 P
gc 16 @6.733s 0%: 0.99+16+0.99 ms clock, 11+7.9/47/80+11 ms cpu, 50-&gt;50-&gt;32 MB, 51 MB goal, 12 P
gc 17 @8.140s 0%: 0.99+21+0 ms clock, 11+3.0/59/125+0 ms cpu, 64-&gt;64-&gt;42 MB, 65 MB goal, 12 P
gc 18 @11.168s 0%: 1.0+28+0 ms clock, 12+24/78/97+0 ms cpu, 82-&gt;82-&gt;54 MB, 84 MB goal, 12 P
gc 19 @14.433s 0%: 0.99+27+0 ms clock, 11+9.0/74/146+0 ms cpu, 106-&gt;106-&gt;70 MB, 108 MB goal, 12 P
gc 20 @18.883s 0%: 0+47+0 ms clock, 0+6.0/133/211+0 ms cpu, 137-&gt;138-&gt;91 MB, 140 MB goal, 12 P
gc 21 @24.437s 0%: 0.99+30+0.99 ms clock, 11+15/91/101+11 ms cpu, 177-&gt;178-&gt;118 MB, 182 MB goal, 12 P
gc 22 @31.872s 0%: 1.0+105+0 ms clock, 12+60/317/256+0 ms cpu, 230-&gt;233-&gt;155 MB, 236 MB goal, 12 P
gc 23 @41.705s 0%: 0+101+0 ms clock, 0+15/283/549+0 ms cpu, 302-&gt;303-&gt;200 MB, 310 MB goal, 12 P
gc 24 @54.302s 0%: 0+92+0 ms clock, 0+9.0/278/472+0 ms cpu, 390-&gt;392-&gt;260 MB, 400 MB goal, 12 P
gc 25 @70.777s 0%: 0+38+0 ms clock, 0+4.9/113/321+0 ms cpu, 508-&gt;508-&gt;337 MB, 521 MB goal, 12 P
gc 26 @92.203s 0%: 0+108+0 ms clock, 0+57/326/391+0 ms cpu, 658-&gt;662-&gt;442 MB, 675 MB goal, 12 P
gc 27 @120.781s 0%: 2.0+99+0 ms clock, 24+11/292/529+0 ms cpu, 862-&gt;864-&gt;574 MB, 884 MB goal, 12 P

The finalizer is never called, and the memory keeps on growing.

Using go version go1.15.8 windows/amd64

Also linked to the github issue here: https://github.com/golang/go/issues/41987

答案1

得分: 3

你似乎误用了runtime.SetFinalizer文档中有这样的说明:

[第一个参数] 必须是一个指针,指向通过调用new、取一个复合字面量的地址或取一个局部变量的地址分配的对象。

(我强调的部分)

如果我将&conn(而不是conn本身)传递给runtime.SetFinalizer,finalizer确实会被调用,并且堆内存永远不会超过8 MB:

$ GODEBUG=gctrace=1 ./main
gc 1 @1.789s 0%: 0.041+0.67+0.018 ms clock, 0.33+0.31/1.0/2.3+0.14 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 2 @1.874s 0%: 0.044+0.69+0.015 ms clock, 0.35+0.20/1.0/2.4+0.12 ms cpu, 4->4->2 MB, 5 MB goal, 8 P
gc 3 @1.880s 0%: 0.064+0.79+0.014 ms clock, 0.51+0.22/1.1/2.3+0.11 ms cpu, 4->4->2 MB, 5 MB goal, 8 P
gc 4 @1.887s 0%: 0.14+1.5+0.080 ms clock, 1.1+1.6/2.5/0+0.64 ms cpu, 5->5->3 MB, 6 MB goal, 8 P
gc 5 @1.904s 0%: 0.097+1.1+0.025 ms clock, 0.77+1.0/1.9/2.6+0.20 ms cpu, 6->6->3 MB, 7 MB goal, 8 P
gc 6 @1.974s 0%: 0.12+1.7+0.12 ms clock, 0.99+1.4/2.9/1.2+0.98 ms cpu, 6->7->3 MB, 7 MB goal, 8 P
gc 7 @2.900s 0%: 0.22+1.9+0.025 ms clock, 1.8+5.7/2.9/0+0.20 ms cpu, 7->7->4 MB, 8finalizer called
 MB goal, 8finalizer called
 P
finalizer called
finalizer called
finalizer called
finalizer called
finalizer called
finalizer called
--snip--

使用-gcflags="-m"编译程序可以看到局部变量conn被移动到了堆上。我不是finalizer的专家(远远不是),但我怀疑你对runtime.SetFinalizer的误用导致了对conn变量的引用保留,从而使得每个实例都无法进行垃圾回收,因此导致了内存泄漏。

我不清楚为什么你想要使用finalizers;传统的观点是应尽量避免使用finalizers

英文:

You seem to be misusing runtime.SetFinalizer; here is what the doc says:

> The [first argument] must be a pointer to an object allocated by calling new, by taking the address of a composite literal, or by taking the address of a local variable.

(my emphasis)

If I pass &amp;conn (rather than conn itself) to runtime.SetFinalizer, the finalizers do get called and the heap never exceeds 8 MB:

$ GODEBUG=gctrace=1 ./main
gc 1 @1.789s 0%: 0.041+0.67+0.018 ms clock, 0.33+0.31/1.0/2.3+0.14 ms cpu, 4-&gt;4-&gt;1 MB, 5 MB goal, 8 P
gc 2 @1.874s 0%: 0.044+0.69+0.015 ms clock, 0.35+0.20/1.0/2.4+0.12 ms cpu, 4-&gt;4-&gt;2 MB, 5 MB goal, 8 P
gc 3 @1.880s 0%: 0.064+0.79+0.014 ms clock, 0.51+0.22/1.1/2.3+0.11 ms cpu, 4-&gt;4-&gt;2 MB, 5 MB goal, 8 P
gc 4 @1.887s 0%: 0.14+1.5+0.080 ms clock, 1.1+1.6/2.5/0+0.64 ms cpu, 5-&gt;5-&gt;3 MB, 6 MB goal, 8 P
gc 5 @1.904s 0%: 0.097+1.1+0.025 ms clock, 0.77+1.0/1.9/2.6+0.20 ms cpu, 6-&gt;6-&gt;3 MB, 7 MB goal, 8 P
gc 6 @1.974s 0%: 0.12+1.7+0.12 ms clock, 0.99+1.4/2.9/1.2+0.98 ms cpu, 6-&gt;7-&gt;3 MB, 7 MB goal, 8 P
gc 7 @2.900s 0%: 0.22+1.9+0.025 ms clock, 1.8+5.7/2.9/0+0.20 ms cpu, 7-&gt;7-&gt;4 MB, 8finalizer called
 MB goal, 8finalizer called
 P
finalizer called
finalizer called
finalizer called
finalizer called
finalizer called
finalizer called
--snip--

Compiling the program with -gcflags=&quot;-m&quot; reveals that local variable conn gets moved to the heap. I'm no finalizer expert (by far), but I suspect that your misuse of runtime.SetFinalizer causes the retention of a reference to the conn variable, thereby making each instance of it ineligible for garbage collection, hence the memory leak.

It's unclear to me why you'd want to use finalizers anyway; conventional wisdom is that finalizers are best avoided.

huangapple
  • 本文由 发表于 2021年6月17日 07:57:59
  • 转载请务必保留本文链接:https://go.coder-hub.com/68011306.html
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定