I seem to be leaking tls clients

[James Bardin]

I have a server where the heap often blows up on during heavy use. The server make many http/https calls, and processed the results for the user. Looking at the heap profile, almost everything there has to do with a tls client, and is topped off by cnew(?) (BTW, where can i find documentation for all the output of the http/pprof debug pages?). There's also a ton of associated goroutines of course.

I think these also may be causing the response body data to not get released, since the memory usage is often fairly extreme (one server can rack up 1-2GB in a couple hours).

I think I have a working example here, (left in gorilla/mux to keep it as close as possible to what's running): http://play.golang.org/p/SiQcnBltB4

Thanks!

[Matthew Kane]

Don't you need to close the body of the incoming request also?

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

--
matt kane
twitter: the_real_mkb / nynexrepublic
http://hydrogenproject.com

[James Bardin]

On Tuesday, July 23, 2013 11:50:54 AM UTC-4, mkb wrote:

Don't you need to close the body of the incoming request also?

I'm fairly certain that the incoming request body is close implicitly, but I added one anyway, and it didn't seem to make a difference.

It looks like the data may not be tied up in the goroutines, they seem to get cleaned up after a while, and never get out of hand numbers wise. 

The heap just keeps growing however, with lots of entries like:

0: 0 [1: 48] @ 0x20b0c 0x22167 0x2223a 0xcf21 0x17eb49 0xf964a 0xfbd60 0xf9759 0xfbd60 0xfd203 0xfd04a 0x920a1 0x94a1d 0x2dfb5 0x2cf46 0x6580f 0x68aee 0x19fb0
#	0x22167		cnew+0xe7					/usr/local/go/src/pkg/runtime/malloc.goc:811
#	0x2223a		runtime.cnewarray+0x3a				/usr/local/go/src/pkg/runtime/malloc.goc:830
#	0xcf21		reflect.unsafe_NewArray+0x31			/usr/local/go/src/pkg/runtime/iface.c:697
#	0x17eb49	reflect.MakeSlice+0x1c9				/usr/local/go/src/pkg/reflect/value.go:2060
#	0xf964a		encoding/asn1.parseSequenceOf+0x31a		/usr/local/go/src/pkg/encoding/asn1/asn1.go:470
#	0xfbd60		encoding/asn1.parseField+0x2520			/usr/local/go/src/pkg/encoding/asn1/asn1.go:766
#	0xf9759		encoding/asn1.parseSequenceOf+0x429		/usr/local/go/src/pkg/encoding/asn1/asn1.go:474
#	0xfbd60		encoding/asn1.parseField+0x2520			/usr/local/go/src/pkg/encoding/asn1/asn1.go:766
#	0xfd203		encoding/asn1.UnmarshalWithParams+0x173		/usr/local/go/src/pkg/encoding/asn1/asn1.go:872
#	0xfd04a		encoding/asn1.Unmarshal+0xaa			/usr/local/go/src/pkg/encoding/asn1/asn1.go:865
#	0x920a1		crypto/x509.parseCertificate+0x341		/usr/local/go/src/pkg/crypto/x509/x509.go:787
#	0x94a1d		crypto/x509.ParseCertificate+0x12d		/usr/local/go/src/pkg/crypto/x509/x509.go:1052
#	0x2dfb5		crypto/tls.(*Conn).clientHandshake+0xc15	/usr/local/go/src/pkg/crypto/tls/handshake_client.go:100
#	0x2cf46		crypto/tls.(*Conn).Handshake+0xd6		/usr/local/go/src/pkg/crypto/tls/conn.go:896
#	0x6580f		net/http.(*Transport).dialConn+0x46f		/usr/local/go/src/pkg/net/http/transport.go:514
#	0x68aee		net/http.func·014+0x3e				/usr/local/go/src/pkg/net/http/transport.go:418

[Brad Fitzpatrick]

Try disabling keep-alive connections on your http.Client's Transport, or if you're using the DefaultClient / DefaultTransport,

call http://golang.org/pkg/net/http/#Transport.CloseIdleConnections periodically on the DefaultTransport:

http.DefaultTransport.(*http.Transport).CloseIdleConnections()

--

[James Bardin]

Tried disabled keepalives, and called CloseIdleConnections just to be safe, but still no change.

The actual sockets are getting closed; from a system level there's no open connections when the server is idle, even though there are still lots of transport/crypto/tls stuff showing in `/debug/pprof/heap?debug=1'

[James Bardin]

I'm not sure if this is a wild goose chase or not, I don't think I understand exactly what the output of the pprof/heap is showing. It seems to perpetually get longer and longer, so I assumed it was in proportion with the ever-growing process RSS, but the heap Alloc amount levels off. The output of `go tool pprof $PATH_TO_HEAP` shows only 6MB allocated on the heap. I expect the RSS to be significantly larger, because I'm allocating large chunks in C, but I need to find out what causes it to explode at times.

I need to make sure the the client has proper timeouts anyway, so I'll add in a new transport without keepalives too, and put that under load and see what happens.

[Ian Ragsdale]

I seem to be having the same issue - did you have any luck tracking this down?

[Dave Cheney]

Can you please post some example code that others can try to reproduce
the problem.

[Ian Ragsdale]

Unfortunately, I can't post the full program, but it is a long-running process that makes many HTTP calls (a few hundred a minute), and the process size grows around 100MB/hour. I can upload a full test program if you want, but the HTTP request part looks like the code below. When I use the profiler after a few hours, it looks like this:

Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) top10
Total: 767.5 MB
484.0 63.1% 63.1% 484.0 63.1% cnew
66.0 8.6% 71.7% 66.0 8.6% newdefer
42.0 5.5% 77.1% 110.5 14.4% crypto/x509.parseCertificate
37.5 4.9% 82.0% 37.5 4.9% crypto/rc4.NewCipher
20.0 2.6% 84.6% 283.0 36.9% net/http.(*Transport).dialConn
12.5 1.6% 86.3% 346.0 45.1% code.google.com/p/go-imap/go1/imap.DialTLS
9.5 1.2% 87.5% 416.0 54.2% main.watchAccount
9.0 1.2% 88.7% 9.0 1.2% encoding/asn1.parsePrintableString
8.0 1.0% 89.7% 8.0 1.0% code.google.com/p/go-imap/go1/imap.(*Client).setCaps
7.0 0.9% 90.6% 7.0 0.9% crypto/sha1.New

In addition, when I pass in the --heapcheck option to pprof and spit out a PDF, it also shows crypto/x509.parseCertificate, crypto/rc4.NewCipher, and net/http.(*Transport).dialConn as potential leaks.

I've tried pretty hard to locate anything inside my code that could be causing this, and it sure seems like it's coming from the HTTP library.

- Ian

========


var token_channel chan bool = make(chan bool, 25)
func makeRequest() {

token_channel <- true
req, err := http.NewRequest("GET", url, nil)
req.SetBasicAuth("username", os.Getenv("PASS"))
http_rsp, err := http_client.Do(req)
<-token_channel

if err != nil {
log.Printf("Error refreshing access token: %s", err)
return
}

buf := make([]byte, 1024)
io.ReadFull(http_rsp.Body, buf)

// make sure we close the message body
defer http_rsp.Body.Close()

[Dave Cheney]

Please do this, go tool pprof -pdf $BIN $PROF > prof.pdf and make the
pdf available somehow.

[Ian Ragsdale]

You can see it here:

https://www.dropbox.com/s/7le34bk3f21mxqs/heap-1.pdf

- Ian

[Dave Cheney]

Thanks for that, it does look like a lot of the allocations are coming
from the DialTLS path. With that in mind it should be easy to create a
short program which does DialTLS in a loop that reproduces the
problem.

[Ian Ragsdale]

Hmm, I've discounted that path because my program keeps open many thousands of persistent TLS connections open on purpose - when that profile was run, there were probably 10-12k connections open. Because they're persistent and it stops opening them after a point, I wouldn't expect the memory usage to keep rising like it does.

I was suspecting the http code because it keeps making many new requests, and because some of that stuff shows up in the top 10. I wrote a simple program that just uses the makeRequest method listed below to make 100k http connections in a loop. I let it run overnight, and profiled it this morning. It's got 1.08GB allocated, and the pprof top 10 looks like this:

(pprof) top10
Total: 227.5 MB
204.5 89.9% 89.9% 204.5 89.9% newdefer
21.5 9.5% 99.3% 21.5 9.5% runtime.malg
1.0 0.4% 99.8% 1.0 0.4% cnew
0.5 0.2% 100.0% 0.5 0.2% encoding/asn1.parseIA5String
0.0 0.0% 100.0% 0.5 0.2% _cgo_sys_thread_start
0.0 0.0% 100.0% 0.5 0.2% bufio.(*Writer).Write

A pdf of the profiling output is here:

https://www.dropbox.com/s/z0nwar1m30q6e29/prof.pdf

Sure looks to me like the call to getIdleConn is leaking defer blocks somehow. I've got DisableKeepAlives set to true, and just for good measure I'm calling CloseIdleConnections every minute.

My test program is below:

package main

import (
"io"
"log"
"net/http"
_ "net/http/pprof"
"runtime"
"time"
)

var (
http_transport *http.Transport = &http.Transport{MaxIdleConnsPerHost: 0, DisableKeepAlives: true}
http_client *http.Client = &http.Client{Transport: http_transport}
url string = "https://www.google.com"
)

func main() {
log.Printf("Starting up")

go func() {
for _ = range time.NewTicker(time.Minute).C {
http_transport.CloseIdleConnections()
}
}()

for i := 0; i < 100000; i++ {
go makeRequest()
runtime.Gosched()
}

http.ListenAndServe(":3000", nil)

}

var token_channel chan bool = make(chan bool, 25)

func makeRequest() {

token_channel <- true
req, err := http.NewRequest("GET", url, nil)

req.SetBasicAuth("username", "pass")

http_rsp, err := http_client.Do(req)
<-token_channel

if err != nil {
log.Printf("Error refreshing access token: %s", err)
return

} else {
log.Print(".")

[Greg Ing]

I'm really curious about this issue. I'm about to build mini crawler that has to deal with a lot of SSL'd content. I ran this code on on my Macbook using go 1.1.2 and encountered the same leak.

[Dave Cheney]

I have a suspicion.

Can you please run this simplified program and tell me how much memory
it consumes on your system.

http://play.golang.org/p/_AvhKFco2y

On my system it consumes 432mb of RSS, which is expected.

[James Bardin]

On Wed, Sep 11, 2013 at 6:29 AM, Dave Cheney <da...@cheney.net> wrote:

I have a suspicion.

Can you please run this simplified program and tell me how much memory
it consumes on your system.

http://play.golang.org/p/_AvhKFco2y

On my system it consumes 432mb of RSS, which is expected

That's roughly what I see on osX and linux. 

[Dave Cheney]

Excellent. So that is the overhead of the goroutines just by themselves. As all but 25 can run at once and google is doing some rate limiting in their end, that could account for a large amount of memory used. 

Could you rewrite your program with 25 worker goroutines, each running in a loop and try again. 

[Ian Ragsdale]

Thanks, Dave! You've certainly opened my eyes to the fact that it's quite possible that the growing memory usage could reflect unbounded growth in goroutines waiting to perform HTTP queries, which leads me to a few questions. 

1) A large portion of the difference (over 600MB) between the two test programs shows up in the newdefer allocations - that's by far the largest in the old test, and doesn't show up at all in the new. Do you believe that to be a measurement artifact / red herring?

2) Is unbounded goroutine growth something that can be recognized in the heap results, which I missed due to my lack of skill at reading them? If not, is that a potential improvement for the profiler? I see the goroutine profile, which does give me the ability to at least understand how many are allocated.

3) Is there a fairly standard pattern for workers that I should use? Seems like I can just create as many goroutines as I want concurrent connections, and have them reading from a buffered channel, the size of which represents how many requests I'm willing to queue - any other suggestions?

Thanks,

Ian

[Greg Ing]

> As all but 25 can run at once and google is doing some rate limiting in their end, that could account for a large amount of memory used. 

Is 25 the default limit of outbound requests in the net/http package?

[Dave Cheney]

The constant 25 came from the OPs code. 

--

[Dave Cheney]

On Thu, Sep 12, 2013 at 12:41 AM, Ian Ragsdale <ian.ra...@gmail.com> wrote:
> Thanks, Dave! You've certainly opened my eyes to the fact that it's quite
> possible that the growing memory usage could reflect unbounded growth in
> goroutines waiting to perform HTTP queries, which leads me to a few
> questions.
>
> 1) A large portion of the difference (over 600MB) between the two test
> programs shows up in the newdefer allocations - that's by far the largest in
> the old test, and doesn't show up at all in the new. Do you believe that to
> be a measurement artifact / red herring?

As I understand it, the memory profile shows the count of allocations,
not the allocations in use. TBH, I don't use memprofile much, so
someone else can probably speak more authoritatively.

> 2) Is unbounded goroutine growth something that can be recognized in the
> heap results, which I missed due to my lack of skill at reading them? If
> not, is that a potential improvement for the profiler? I see the goroutine
> profile, which does give me the ability to at least understand how many are
> allocated.

I always work from the goroutine dump. If you hit your original test
process with SIGQUIT, you'll see there are 100,000 goroutines all
blocked. Everyone of those costs 4kb

> 3) Is there a fairly standard pattern for workers that I should use? Seems
> like I can just create as many goroutines as I want concurrent connections,
> and have them reading from a buffered channel, the size of which represents
> how many requests I'm willing to queue - any other suggestions?

That is how I'd do it. Just like there is no point in running more
hardware threads than you have cpus, in this case there is little
value in spawning workers if they are limited by the number of
concurrent http requests.

This still leaves the other 1/2 of your memory allocation problem
unaccounted for. I suggest rewriting the application to use a poll of
workers as discussed. I wouldn't both buffering the work queue, there
is no correct value, so you may as well use 0. Then let's profile
again.