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 (
"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
}
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->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
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
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 &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->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--
Compiling the program with -gcflags="-m" 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.