runtime: huge page fragmentation on Linux leads to out of memory

[bmhatfield]

I recently upgraded to Go 1.5 from 1.4.2 for a moderately large production service, serving thousands of requests per second. This particular program has been run on every Go version from 1.1 through (now) 1.5, and has been stable in production for about 2+ years. Switching to Go 1.5 saw dramatic improvements in GC pause time, as expected, but the processes are intermittently exiting (somewhere between 1-6h of uptime) with the below panic.

On each version, this has been running on Ubuntu 12.04.

fatal error: runtime: cannot allocate memory

runtime stack:
runtime.throw(0x8c8f20, 0x1f)
        /usr/local/go/src/runtime/panic.go:527 +0x90
runtime.persistentalloc1(0x4000, 0x8, 0xaa8a78, 0xa8d3a8)
        /usr/local/go/src/runtime/malloc.go:878 +0x2e3
runtime.persistentalloc.func1()
        /usr/local/go/src/runtime/malloc.go:831 +0x3b
runtime.systemstack(0x7ff1377fdc78)
        /usr/local/go/src/runtime/asm_amd64.s:278 +0xab
runtime.persistentalloc(0x4000, 0x0, 0xaa8a78, 0x5)
        /usr/local/go/src/runtime/malloc.go:832 +0x58
runtime.fixAlloc_Alloc(0xa95eb8, 0xa8d3a8)
        /usr/local/go/src/runtime/mfixalloc.go:67 +0xee
runtime.mHeap_AllocSpanLocked(0xa89ba0, 0x5, 0x412c1b)
        /usr/local/go/src/runtime/mheap.go:561 +0x1a7
runtime.mHeap_Alloc_m(0xa89ba0, 0x5, 0x100000000, 0xc8200205bc)
        /usr/local/go/src/runtime/mheap.go:425 +0x1ac
runtime.mHeap_Alloc.func1()
        /usr/local/go/src/runtime/mheap.go:484 +0x41
runtime.systemstack(0x7ff1377fddb8)
        /usr/local/go/src/runtime/asm_amd64.s:278 +0xab
runtime.mHeap_Alloc(0xa89ba0, 0x5, 0x10100000000, 0x923300)
        /usr/local/go/src/runtime/mheap.go:485 +0x63
runtime.largeAlloc(0x9c40, 0x0, 0x4d4f07)
        /usr/local/go/src/runtime/malloc.go:745 +0xb3
runtime.mallocgc.func3()
        /usr/local/go/src/runtime/malloc.go:634 +0x33
runtime.systemstack(0xc820020000)
        /usr/local/go/src/runtime/asm_amd64.s:262 +0x79
runtime.mstart()
        /usr/local/go/src/runtime/proc1.go:674

goroutine 1145040165 [running]:
runtime.systemstack_switch()
        /usr/local/go/src/runtime/asm_amd64.s:216 fp=0xc8226375f0 sp=0xc8226375e8
runtime.mallocgc(0x9c40, 0x731f60, 0x0, 0x60)
        /usr/local/go/src/runtime/malloc.go:635 +0x9c4 fp=0xc8226376c0 sp=0xc8226375f0
runtime.newarray(0x731f60, 0x1388, 0x3)
        /usr/local/go/src/runtime/malloc.go:777 +0xc9 fp=0xc822637700 sp=0xc8226376c0
runtime.makechan(0x7320e0, 0x1388, 0xc93f800000)
        /usr/local/go/src/runtime/chan.go:72 +0x135 fp=0xc822637750 sp=0xc822637700
github.com/crashlytics/gusset/caching-proxy.(*CachingProxy).Request(0xc820110550, 0x7ff13c6c01b0, 0xc964463810, 0xc9644b30a4, 0x0, 0x0)
        /srv/go/src/github.com/crashlytics/gusset/caching-proxy/caching-proxy.go:445 +0x6d0 fp=0xc822637908 sp=0xc822637750
main.cachedRequestHandler(0x7ff13c6c0178, 0xc9644e2580, 0xc9642b6380)
        /srv/go/src/github.com/crashlytics/gusset/gusset.go:69 +0x437 fp=0xc822637b68 sp=0xc822637908
net/http.HandlerFunc.ServeHTTP(0x922e98, 0x7ff13c6c0178, 0xc9644e2580, 0xc9642b6380)
        /usr/local/go/src/net/http/server.go:1422 +0x3a fp=0xc822637b88 sp=0xc822637b68
net/http.(*ServeMux).ServeHTTP(0xc82010d530, 0x7ff13c6c0178, 0xc9644e2580, 0xc9642b6380)
        /usr/local/go/src/net/http/server.go:1699 +0x17d fp=0xc822637be0 sp=0xc822637b88
net/http.serverHandler.ServeHTTP(0xc82011c540, 0x7ff13c6c0178, 0xc9644e2580, 0xc9642b6380)
        /usr/local/go/src/net/http/server.go:1862 +0x19e fp=0xc822637c40 sp=0xc822637be0
net/http.(*conn).serve(0xc8aef18160)
        /usr/local/go/src/net/http/server.go:1361 +0xbee fp=0xc822637f98 sp=0xc822637c40
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc822637fa0 sp=0xc822637f98
created by net/http.(*Server).Serve
        /usr/local/go/src/net/http/server.go:1910 +0x3f6

[davecheney]

@bmhatfield can you please run the process with env GODEBUG=gctrace=1 and include the log, or at least the most relevant parts in this report. I suspect memory usage will do one of two things.

1. climb slowly and inevitably towards a crash
2. operate stably for a period of time, then skyrocket.

The gctrace log will show both.

btw. this information is always being collected, just normally supressed, so there is little impact in running it in production.

[bmhatfield]

Can do. In the meantime, I am not seeing any odd memory usage (stack, heap, or just general system memory). I have graphs of everything available in https://github.com/bmhatfield/go-runtime-metrics/blob/master/runstats.go if you have any specific requests.

Here's a high level of system memory (plotted against a metric that demonstrates the crash occurance)

[ianlancetaylor]

CC @RLH @aclements

[aclements]

@bmhatfield, do you happen to know the approximate heap size (or have the equivalent graphs) for your service when it was running on Go 1.4?

It looks like your heap size graph is going up even between restarts (each restart cycle quickly climbs to a larger heap size than the previous cycle had when it crashed). That's a bit perplexing.

[bmhatfield]

Hi @aclements - here's an annotated graph of the normal heap size for this service. My general takeaway is that the heap size appears to be within expected bounds for this service, and the normal operating size does not appear to be "changed" as of 1.5.

This service is essentially an HTTP cache using the go-cache library with some additional features focused on analyzing the traffic it receives (those features being the primary reason this service exists). When this service is deployed (or re-spawned after a crash), it exhibits some oscillation for a short period of time, related to the initially-synchronized 10 minute cache entry TTLs, which explains the heap growth and then reduction that you're seeing. This behavior normalizes relatively quickly, and was "normalized" when these crashes occurred.

[aclements]

Thanks for the plot and explanation. Is the traceback on the crash always/usually the same? In the one you posted, it's failing in a surprisingly specific place.

[bmhatfield]

Great question, sorry I did not think of that before. Doing some digging now, I see one that looks like:

runtime/cgo: pthread_create failed: Resource temporarily unavailable
SIGABRT: abort
PC=0x7f82381d7425 m=2

goroutine 0 [idle]:

goroutine 1 [IO wait]:
net.runtime_pollWait(0x7f82387a5660, 0x72, 0xc820010100)
        /usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc820133560, 0x72, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820133560, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc820133500, 0x0, 0x7f82387a6628, 0xc86e6d93a0)
        /usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc82010e0e8, 0x452790, 0x0, 0x0)
        /usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net/http.tcpKeepAliveListener.Accept(0xc82010e0e8, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:2135 +0x41
net/http.(*Server).Serve(0xc82011e540, 0x7f82387a65f0, 0xc82010e0e8, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1887 +0xb3
net/http.(*Server).ListenAndServe(0xc82011e540, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1877 +0x136
main.main()
        /srv/go/src/github.com/crashlytics/gusset/gusset.go:260 +0xb50

goroutine 17 [syscall, 474 minutes, locked to thread]:
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1

and another like this:

runtime/cgo: out of memory in thread_start
SIGABRT: abort
PC=0x7fb4da635425 m=2

goroutine 0 [idle]:

goroutine 1 [IO wait]:
net.runtime_pollWait(0x7fb4d84fb240, 0x72, 0xc820010100)
        /usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc820131560, 0x72, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820131560, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc820131500, 0x0, 0x7fb4d853f080, 0xc92a6cde80)
        /usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc820598028, 0x452790, 0x0, 0x0)
        /usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net/http.tcpKeepAliveListener.Accept(0xc820598028, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:2135 +0x41
net/http.(*Server).Serve(0xc820110540, 0x7fb4d853f048, 0xc820598028, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1887 +0xb3
net/http.(*Server).ListenAndServe(0xc820110540, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1877 +0x136
main.main()
        /srv/go/src/github.com/crashlytics/gusset/gusset.go:260 +0xb50

goroutine 17 [syscall, 464 minutes, locked to thread]:
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1

Please note that at the time that this claimed "out of memory", the system had been using less than 50% (~7GB) of available memory (~15GB instances), and the process has been able to claim more memory from the system both before (on 1.5) and after (still 1.5) the occurrences of those crashes.

[bmhatfield]

Here's another example of the 'runtime out of memory' traceback, from a different host at a different time:

fatal error: runtime: out of memory

runtime stack:
runtime.throw(0x8ba570, 0x16)
        /usr/local/go/src/runtime/panic.go:527 +0x90
runtime.sysMap(0xc8159fc000, 0x8000, 0xc96bf50000, 0xaa8a98)
        /usr/local/go/src/runtime/mem_linux.go:143 +0x9b
runtime.mHeap_MapBits(0xa89ba0, 0xc96c050000)
        /usr/local/go/src/runtime/mbitmap.go:144 +0xcc
runtime.mHeap_SysAlloc(0xa89ba0, 0x100000, 0x7f331b306f10)
        /usr/local/go/src/runtime/malloc.go:424 +0x186
runtime.mHeap_Grow(0xa89ba0, 0x8, 0x0)
        /usr/local/go/src/runtime/mheap.go:628 +0x63
runtime.mHeap_AllocSpanLocked(0xa89ba0, 0x1, 0x412ab1)
        /usr/local/go/src/runtime/mheap.go:532 +0x5f1
runtime.mHeap_Alloc_m(0xa89ba0, 0x1, 0x2, 0xc96b54dff0)
        /usr/local/go/src/runtime/mheap.go:425 +0x1ac
runtime.mHeap_Alloc.func1()
        /usr/local/go/src/runtime/mheap.go:484 +0x41
runtime.systemstack(0x7f3332777d28)
        /usr/local/go/src/runtime/asm_amd64.s:278 +0xab
runtime.mHeap_Alloc(0xa89ba0, 0x1, 0x10000000002, 0x410524)
        /usr/local/go/src/runtime/mheap.go:485 +0x63
runtime.mCentral_Grow(0xa91188, 0x0)
        /usr/local/go/src/runtime/mcentral.go:190 +0x93
runtime.mCentral_CacheSpan(0xa91188, 0x0)
        /usr/local/go/src/runtime/mcentral.go:86 +0x4d4
runtime.mCache_Refill(0x7f33367b3e28, 0xc900000002, 0xc964f2d7d8)
        /usr/local/go/src/runtime/mcache.go:118 +0xcf
runtime.mallocgc.func2()
        /usr/local/go/src/runtime/malloc.go:611 +0x2b
runtime.systemstack(0xc82001aa00)
        /usr/local/go/src/runtime/asm_amd64.s:262 +0x79
runtime.mstart()
        /usr/local/go/src/runtime/proc1.go:674

goroutine 1231230574 [running]:
runtime.systemstack_switch()
        /usr/local/go/src/runtime/asm_amd64.s:216 fp=0xc964f2d588 sp=0xc964f2d580
runtime.mallocgc(0x10, 0x7410a0, 0x430000c900000000, 0xc96b54dff0)
        /usr/local/go/src/runtime/malloc.go:612 +0x842 fp=0xc964f2d658 sp=0xc964f2d588
runtime.newarray(0x7410a0, 0x1, 0xc96bf4c0e8)
        /usr/local/go/src/runtime/malloc.go:777 +0xc9 fp=0xc964f2d698 sp=0xc964f2d658
runtime.makeslice(0x730d00, 0x1, 0x1, 0x0, 0x0, 0x0)
        /usr/local/go/src/runtime/slice.go:32 +0x165 fp=0xc964f2d6e8 sp=0xc964f2d698
net/http.Header.clone(0xc96b019950, 0xa7b200)
        /usr/local/go/src/net/http/header.go:63 +0x13e fp=0xc964f2d818 sp=0xc964f2d6e8
net/http.(*response).WriteHeader(0xc96ba11970, 0xc8)
        /usr/local/go/src/net/http/server.go:694 +0x102 fp=0xc964f2d908 sp=0xc964f2d818
main.cachedRequestHandler(0x7f3331737128, 0xc96ba11970, 0xc968f25960)
        /srv/go/src/github.com/crashlytics/gusset/gusset.go:93 +0x9b1 fp=0xc964f2db68 sp=0xc964f2d908
net/http.HandlerFunc.ServeHTTP(0x922e98, 0x7f3331737128, 0xc96ba11970, 0xc968f25960)
        /usr/local/go/src/net/http/server.go:1422 +0x3a fp=0xc964f2db88 sp=0xc964f2db68
net/http.(*ServeMux).ServeHTTP(0xc82010d530, 0x7f3331737128, 0xc96ba11970, 0xc968f25960)
        /usr/local/go/src/net/http/server.go:1699 +0x17d fp=0xc964f2dbe0 sp=0xc964f2db88
net/http.serverHandler.ServeHTTP(0xc82011c540, 0x7f3331737128, 0xc96ba11970, 0xc968f25960)
        /usr/local/go/src/net/http/server.go:1862 +0x19e fp=0xc964f2dc40 sp=0xc964f2dbe0
net/http.(*conn).serve(0xc8d3778dc0)
        /usr/local/go/src/net/http/server.go:1361 +0xbee fp=0xc964f2df98 sp=0xc964f2dc40
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc964f2dfa0 sp=0xc964f2df98
created by net/http.(*Server).Serve
        /usr/local/go/src/net/http/server.go:1910 +0x3f6

[bmhatfield]

And another example in thread_start:

runtime/cgo: out of memory in thread_start
SIGABRT: abort
PC=0x7f8a5a918425 m=11

goroutine 0 [idle]:

goroutine 47 [running]:
runtime.systemstack_switch()
        /usr/local/go/src/runtime/asm_amd64.s:216 fp=0xc907f09bd8 sp=0xc907f09bd0
runtime.newproc(0x38, 0x7f8a5805e4a8)
        /usr/local/go/src/runtime/proc1.go:2213 +0x62 fp=0xc907f09c20 sp=0xc907f09bd8
github.com/crashlytics/go-libraries/extralog.Timer(0xc8f3154510, 0x24, 0x900df)
        /srv/go/src/github.com/crashlytics/gusset/Godeps/_workspace/src/github.com/crashlytics/go-libraries/extralog/extralog.go:63 +0x2b5 fp=0xc907f09d00 sp=0xc907f09c20
github.com/crashlytics/go-libraries/startablebeanstalk.(*StartableBeanstalkWriter).Write(0xc82010e9c0, 0xc931f381e0, 0x1be, 0x1d7, 0x1423839494, 0x0, 0x0)
        /srv/go/src/github.com/crashlytics/gusset/Godeps/_workspace/src/github.com/crashlytics/go-libraries/startablebeanstalk/startablebeanstalk.go:68 +0xbb9 fp=0xc907f09ee8 sp=0xc907f09d00
github.com/crashlytics/go-libraries/poolwriter.WriterWorker(0x7f8a5805e4b0, 0xc82010e9c0, 0xc82011c480)
        /srv/go/src/github.com/crashlytics/gusset/Godeps/_workspace/src/github.com/crashlytics/go-libraries/poolwriter/poolwriter.go:34 +0xd2 fp=0xc907f09f88 sp=0xc907f09ee8
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc907f09f90 sp=0xc907f09f88
created by github.com/crashlytics/go-libraries/poolwriter.NewWriter
        /srv/go/src/github.com/crashlytics/gusset/Godeps/_workspace/src/github.com/crashlytics/go-libraries/poolwriter/poolwriter.go:66 +0x1f3

goroutine 1 [IO wait]:
net.runtime_pollWait(0x7f8a5aee6ce8, 0x72, 0xc820010100)
        /usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc820131560, 0x72, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820131560, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc820131500, 0x0, 0x7f8a5805e758, 0xc93ddb03c0)
        /usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc82002c0a8, 0x452790, 0x0, 0x0)
        /usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net/http.tcpKeepAliveListener.Accept(0xc82002c0a8, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:2135 +0x41
net/http.(*Server).Serve(0xc82011c540, 0x7f8a5805e720, 0xc82002c0a8, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1887 +0xb3
net/http.(*Server).ListenAndServe(0xc82011c540, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1877 +0x136
main.main()
        /srv/go/src/github.com/crashlytics/gusset/gusset.go:260 +0xb50

goroutine 17 [syscall, 321 minutes, locked to thread]:
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1

[bmhatfield]

And finally, another example of the pthread_create crash:

untime/cgo: pthread_create failed: Resource temporarily unavailable
SIGABRT: abort
PC=0x7ff354fc3425 m=2

goroutine 0 [idle]:

goroutine 1 [IO wait]:
net.runtime_pollWait(0x7ff355591840, 0x72, 0xc820010100)
        /usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc820139560, 0x72, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820139560, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc820139500, 0x0, 0x7ff3526cd688, 0xc894f90780)
        /usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc8205d2000, 0x452790, 0x0, 0x0)
        /usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net/http.tcpKeepAliveListener.Accept(0xc8205d2000, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:2135 +0x41
net/http.(*Server).Serve(0xc820124540, 0x7ff3526cd650, 0xc8205d2000, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1887 +0xb3
net/http.(*Server).ListenAndServe(0xc820124540, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1877 +0x136
main.main()
        /srv/go/src/github.com/crashlytics/gusset/gusset.go:260 +0xb50

goroutine 17 [syscall, 617 minutes, locked to thread]:
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1

[bmhatfield]

Here's a graph demonstrating the cadence of these crashes. The "causes" are a mixture of the above tracebacks. It's probably worth highlighting (with the discovery of additional tracebacks) that this did not happen in 1.4.2 - no crashes at all.

[bmhatfield]

@aclements @davecheney Caught one with the GC logging on! And with a new backtrace "reason". I've included an arbitrary number of GC log messages "back" from the crash:

gc 575 @9912.118s 3%: 11+150+2.0+810+21 ms clock, 57+150+0+3437/1615/0.029+109 ms cpu, 4809->4873->2483 MB, 4932 MB goal, 8 P
gc 576 @9930.019s 3%: 8.4+65+30+885+22 ms clock, 67+65+0+2530/1754/739+177 ms cpu, 4718->4782->2522 MB, 4839 MB goal, 8 P
gc 577 @9947.601s 3%: 11+168+5.2+812+22 ms clock, 57+168+0+3409/1622/0.046+111 ms cpu, 4793->4858->2507 MB, 4916 MB goal, 8 P
gc 578 @9965.602s 3%: 8.4+182+1.5+771+21 ms clock, 67+182+0+3283/1538/163+175 ms cpu, 4762->4824->2448 MB, 4884 MB goal, 8 P
gc 579 @9983.589s 3%: 8.1+111+5.0+863+21 ms clock, 40+111+0+3446/1725/0.022+108 ms cpu, 4652->4715->2513 MB, 4771 MB goal, 8 P
gc 580 @10001.383s 3%: 8.2+185+1.8+783+21 ms clock, 41+185+0+3417/1565/128+108 ms cpu, 4776->4839->2462 MB, 4898 MB goal, 8 P
gc 581 @10019.072s 3%: 8.5+100+2.4+857+22 ms clock, 51+100+0+3431/1715/35+133 ms cpu, 4679->4739->2521 MB, 4799 MB goal, 8 P
gc 582 @10037.624s 3%: 8.3+160+5.6+808+23 ms clock, 41+160+0+3379/1616/0.019+115 ms cpu, 4797->4861->2482 MB, 4920 MB goal, 8 P
scvg66: 14 MB released
scvg66: inuse: 4804, idle: 4598, sys: 9403, released: 4358, consumed: 5044 (MB)
gc 583 @10055.601s 3%: 8.2+111+0.57+837+21 ms clock, 66+111+0+3229/1668/31+174 ms cpu, 4715->4777->2435 MB, 4836 MB goal, 8 P
gc 584 @10072.948s 3%: 8.2+75+23+868+22 ms clock, 41+75+0+3131/1736/187+111 ms cpu, 4628->4691->2497 MB, 4747 MB goal, 8 P
gc 585 @10091.237s 3%: 8.2+163+2.7+820+22 ms clock, 41+163+0+3509/1637/83+111 ms cpu, 4747->4809->2450 MB, 4869 MB goal, 8 P
gc 586 @10109.203s 3%: 11+119+4.5+829+22 ms clock, 67+119+0+2848/1658/524+132 ms cpu, 4656->4711->2505 MB, 4776 MB goal, 8 P
gc 587 @10127.338s 3%: 8.3+120+1.0+838+22 ms clock, 41+120+0+3317/1675/0+110 ms cpu, 4777->4841->2470 MB, 4900 MB goal, 8 P
gc 588 @10145.555s 3%: 8.4+163+3.5+784+21 ms clock, 42+163+0+3220/1563/47+109 ms cpu, 4693->4755->2429 MB, 4813 MB goal, 8 P
gc 589 @10163.364s 3%: 8.2+141+1.1+822+22 ms clock, 41+141+0+3332/1643/0.043+110 ms cpu, 4616->4678->2490 MB, 4734 MB goal, 8 P
gc 590 @10181.239s 3%: 11+138+1.6+805+21 ms clock, 80+138+0+3363/1609/39+153 ms cpu, 4733->4795->2448 MB, 4855 MB goal, 8 P
gc 591 @10198.829s 3%: 8.1+102+21+844+23 ms clock, 40+102+0+3442/1686/0.054+117 ms cpu, 4652->4715->2510 MB, 4771 MB goal, 8 P
scvg67: 37 MB released
scvg67: inuse: 4889, idle: 4513, sys: 9403, released: 4390, consumed: 5012 (MB)
gc 592 @10216.888s 3%: 8.2+133+7.9+815+21 ms clock, 57+133+0+3350/1631/50+152 ms cpu, 4773->4835->2468 MB, 4895 MB goal, 8 P
runtime:objectstart Span weird: p=0xc900000000 k=0x6480000 s.start=0xc8ffffa000 s.limit=0xc900003c40 s.state=2
fatal error: objectstart: bad pointer in unexpected span

goroutine 108 [running]:
runtime.throw(0x8ea820, 0x2b)
        /usr/local/go/src/runtime/panic.go:527 +0x90 fp=0xc82058ee18 sp=0xc82058ee00
runtime.heapBitsForObject(0xc900000000, 0x0, 0x0, 0xc800000000, 0x7f8d16809d20)
        /usr/local/go/src/runtime/mbitmap.go:217 +0x287 fp=0xc82058ee50 sp=0xc82058ee18
runtime.scanobject(0xc95d6e8c30, 0xc82001f220)
        /usr/local/go/src/runtime/mgcmark.go:863 +0x239 fp=0xc82058ef20 sp=0xc82058ee50
runtime.gcDrain(0xc82001f220, 0x7d0)
        /usr/local/go/src/runtime/mgcmark.go:674 +0xf4 fp=0xc82058ef50 sp=0xc82058ef20
runtime.gcBgMarkWorker(0xc82001e000)
        /usr/local/go/src/runtime/mgc.go:1319 +0x281 fp=0xc82058efb8 sp=0xc82058ef50
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82058efc0 sp=0xc82058efb8
created by runtime.gcBgMarkStartWorkers
        /usr/local/go/src/runtime/mgc.go:1238 +0x93

goroutine 1 [runnable]:
net.runtime_pollWait(0x7f8d30dc3e40, 0x72, 0xc82000e100)
        /usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc820131560, 0x72, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820131560, 0x0, 0x0)
        /usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc820131500, 0x0, 0x7f8d30502038, 0xc92cf131a0)
        /usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc82060a010, 0x452790, 0x0, 0x0)
        /usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net/http.tcpKeepAliveListener.Accept(0xc82060a010, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:2135 +0x41
net/http.(*Server).Serve(0xc8201184e0, 0x7f8d30502000, 0xc82060a010, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1887 +0xb3
net/http.(*Server).ListenAndServe(0xc8201184e0, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:1877 +0x136
main.main()
        /srv/go/src/github.com/crashlytics/gusset/gusset.go:260 +0xb50

goroutine 17 [syscall, 170 minutes, locked to thread]:
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1

[davecheney]

Are you able to track the number of threads active in that process. It
looks like your program is consuming a lot of operating system threads and
the most common cause of that is DNS lookups.

Can you try setting GODEBUG=netdns=go to force the net package to only use
the pure go native resolver. If you already build with -tags netgo or some
other dance to disable cgo, this advice may not be relevant, but it could
be worth a try as the incantation for this procedure does change frequently.

On Fri, Aug 21, 2015 at 4:52 AM, Brian Hatfield notifications@github.com
wrote:

@aclements https://github.com/aclements @davecheney
https://github.com/davecheney Caught one with the GC logging on! And
with a new backtrace "reason". I've included an arbitrary number of GC log
messages "back" from the crash:

gc 575 @9912.118s 3%: 11+150+2.0+810+21 ms clock, 57+150+0+3437/1615/0.029+109 ms cpu, 4809->4873->2483 MB, 4932 MB goal, 8 P
gc 576 @9930.019s 3%: 8.4+65+30+885+22 ms clock, 67+65+0+2530/1754/739+177 ms cpu, 4718->4782->2522 MB, 4839 MB goal, 8 P
gc 577 @9947.601s 3%: 11+168+5.2+812+22 ms clock, 57+168+0+3409/1622/0.046+111 ms cpu, 4793->4858->2507 MB, 4916 MB goal, 8 P
gc 578 @9965.602s 3%: 8.4+182+1.5+771+21 ms clock, 67+182+0+3283/1538/163+175 ms cpu, 4762->4824->2448 MB, 4884 MB goal, 8 P
gc 579 @9983.589s 3%: 8.1+111+5.0+863+21 ms clock, 40+111+0+3446/1725/0.022+108 ms cpu, 4652->4715->2513 MB, 4771 MB goal, 8 P
gc 580 @10001.383s 3%: 8.2+185+1.8+783+21 ms clock, 41+185+0+3417/1565/128+108 ms cpu, 4776->4839->2462 MB, 4898 MB goal, 8 P
gc 581 @10019.072s 3%: 8.5+100+2.4+857+22 ms clock, 51+100+0+3431/1715/35+133 ms cpu, 4679->4739->2521 MB, 4799 MB goal, 8 P
gc 582 @10037.624s 3%: 8.3+160+5.6+808+23 ms clock, 41+160+0+3379/1616/0.019+115 ms cpu, 4797->4861->2482 MB, 4920 MB goal, 8 P
scvg66: 14 MB released
scvg66: inuse: 4804, idle: 4598, sys: 9403, released: 4358, consumed: 5044 (MB)
gc 583 @10055.601s 3%: 8.2+111+0.57+837+21 ms clock, 66+111+0+3229/1668/31+174 ms cpu, 4715->4777->2435 MB, 4836 MB goal, 8 P
gc 584 @10072.948s 3%: 8.2+75+23+868+22 ms clock, 41+75+0+3131/1736/187+111 ms cpu, 4628->4691->2497 MB, 4747 MB goal, 8 P
gc 585 @10091.237s 3%: 8.2+163+2.7+820+22 ms clock, 41+163+0+3509/1637/83+111 ms cpu, 4747->4809->2450 MB, 4869 MB goal, 8 P
gc 586 @10109.203s 3%: 11+119+4.5+829+22 ms clock, 67+119+0+2848/1658/524+132 ms cpu, 4656->4711->2505 MB, 4776 MB goal, 8 P
gc 587 @10127.338s 3%: 8.3+120+1.0+838+22 ms clock, 41+120+0+3317/1675/0+110 ms cpu, 4777->4841->2470 MB, 4900 MB goal, 8 P
gc 588 @10145.555s 3%: 8.4+163+3.5+784+21 ms clock, 42+163+0+3220/1563/47+109 ms cpu, 4693->4755->2429 MB, 4813 MB goal, 8 P
gc 589 @10163.364s 3%: 8.2+141+1.1+822+22 ms clock, 41+141+0+3332/1643/0.043+110 ms cpu, 4616->4678->2490 MB, 4734 MB goal, 8 P
gc 590 @10181.239s 3%: 11+138+1.6+805+21 ms clock, 80+138+0+3363/1609/39+153 ms cpu, 4733->4795->2448 MB, 4855 MB goal, 8 P
gc 591 @10198.829s 3%: 8.1+102+21+844+23 ms clock, 40+102+0+3442/1686/0.054+117 ms cpu, 4652->4715->2510 MB, 4771 MB goal, 8 P
scvg67: 37 MB released
scvg67: inuse: 4889, idle: 4513, sys: 9403, released: 4390, consumed: 5012 (MB)
gc 592 @10216.888s 3%: 8.2+133+7.9+815+21 ms clock, 57+133+0+3350/1631/50+152 ms cpu, 4773->4835->2468 MB, 4895 MB goal, 8 P
runtime:objectstart Span weird: p=0xc900000000 k=0x6480000 s.start=0xc8ffffa000 s.limit=0xc900003c40 s.state=2
fatal error: objectstart: bad pointer in unexpected span

goroutine 108 [running]:
runtime.throw(0x8ea820, 0x2b)
/usr/local/go/src/runtime/panic.go:527 +0x90 fp=0xc82058ee18 sp=0xc82058ee00
runtime.heapBitsForObject(0xc900000000, 0x0, 0x0, 0xc800000000, 0x7f8d16809d20)
/usr/local/go/src/runtime/mbitmap.go:217 +0x287 fp=0xc82058ee50 sp=0xc82058ee18
runtime.scanobject(0xc95d6e8c30, 0xc82001f220)
/usr/local/go/src/runtime/mgcmark.go:863 +0x239 fp=0xc82058ef20 sp=0xc82058ee50
runtime.gcDrain(0xc82001f220, 0x7d0)
/usr/local/go/src/runtime/mgcmark.go:674 +0xf4 fp=0xc82058ef50 sp=0xc82058ef20
runtime.gcBgMarkWorker(0xc82001e000)
/usr/local/go/src/runtime/mgc.go:1319 +0x281 fp=0xc82058efb8 sp=0xc82058ef50
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82058efc0 sp=0xc82058efb8
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1238 +0x93

goroutine 1 [runnable]:
net.runtime_pollWait(0x7f8d30dc3e40, 0x72, 0xc82000e100)
/usr/local/go/src/runtime/netpoll.go:157 +0x60
net.(_pollDesc).Wait(0xc820131560, 0x72, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(_pollDesc).WaitRead(0xc820131560, 0x0, 0x0)
/usr/local/go/src/net/fd_poll_runtime.go:78 +0x36
net.(_netFD).accept(0xc820131500, 0x0, 0x7f8d30502038, 0xc92cf131a0)
/usr/local/go/src/net/fd_unix.go:408 +0x27c
net.(_TCPListener).AcceptTCP(0xc82060a010, 0x452790, 0x0, 0x0)
/usr/local/go/src/net/tcpsock_posix.go:254 +0x4d
net/http.tcpKeepAliveListener.Accept(0xc82060a010, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/net/http/server.go:2135 +0x41
net/http.(_Server).Serve(0xc8201184e0, 0x7f8d30502000, 0xc82060a010, 0x0, 0x0)
/usr/local/go/src/net/http/server.go:1887 +0xb3
net/http.(_Server).ListenAndServe(0xc8201184e0, 0x0, 0x0)
/usr/local/go/src/net/http/server.go:1877 +0x136
main.main()
/srv/go/src/github.com/crashlytics/gusset/gusset.go:260 +0xb50

goroutine 17 [syscall, 170 minutes, locked to thread]:
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1696 +0x1

—
Reply to this email directly or view it on GitHub
#12233 (comment).