runtime: panic: "fatal error: malloc deadlock" with CPU profile #14599

ncw · 2016-03-02T17:44:52Z

What version of Go are you using (go version)?

go version go1.6 linux/amd64

What operating system and processor architecture are you using (go env)?

Ubuntu 15.10 Wily

Linux 4.2.0-23-generic #28-Ubuntu SMP Sun Dec 27 17:47:31 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

What did you do?

I'm getting "panic: fatal error: malloc deadlock" quite reproducibly in
my program: https://github.com/ncw/go-nflog-acctd when compiled with go
1.6 and run with cpu profiling.

The code runs clean with the race detector enabled.

The panic only seems to happen when cpu profiling is enabled so I'd
guess it is something to do with that.

To reproduce on a Linux amd64 based system

sudo apt-get install libnetfilter-log-dev
go get github.com/ncw/go-nflog-acctd
cd $GOPATH/github.com/ncw/go-nflog-acctd
sudo start-iptables-accounting-nflog
sudo go-nflog-acctd  -interval 10s -ip4-dst-group=4 -ip4-src-group=5
-ip6-dst-group=6 -ip6-src-group=7 -cpuprofile z.prof

In another window run

sudo sudo hping3 127.0.0.2 --syn -p 80 -s 53 --flood

This usually produces a stack trace within a minute or two.

I haven't made it go wrong without the -cpuprofile z.prof flag.

What did you expect to see?

No traceback

What did you see instead?

This traceback

panic: fatal error: malloc deadlock

goroutine 0 [idle]:
panic(0x58a9a0, 0xc8200100d0)
    /usr/local/go/src/runtime/panic.go:355 +0x7a

goroutine 8 [syscall, locked to thread]:
runtime.cgocall(0x536610, 0xc8200f9ea0, 0x0)
    /usr/local/go/src/runtime/cgocall.go:123 +0x11b fp=0xc8200f9e50
sp=0xc8200f9e20
main._Cfunc_nflog_handle_packet(0x222db50, 0x7f1d000008c0, 0x1dc4, 0x0)
    ??:0 +0x41 fp=0xc8200f9ea0 sp=0xc8200f9e50
main.(*NfLog).Loop(0xc820016140)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:357 +0x386
fp=0xc8200f9fa8 sp=0xc8200f9ea0
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200f9fb0
sp=0xc8200f9fa8
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 1 [chan receive]:
main.main()
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:399 +0xf1a

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

goroutine 5 [syscall]:
os/signal.signal_recv(0x0)
    /usr/local/go/src/runtime/sigqueue.go:116 +0x132
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 6 [syscall]:
runtime.CPUProfile(0x0, 0x0, 0x0)
    /usr/local/go/src/runtime/cpuprof.go:421 +0x34
runtime/pprof.profileWriter(0x7f1d21ddb308, 0xc820028030)
    /usr/local/go/src/runtime/pprof/pprof.go:607 +0x1c
created by runtime/pprof.StartCPUProfile
    /usr/local/go/src/runtime/pprof/pprof.go:601 +0x145

goroutine 7 [runnable, locked to thread]:
main._C2func_recv(0x4, 0x7f1d080008c0, 0x400000, 0x0, 0x1144, 0x0, 0x0)
    ??:0 +0x56
main.(*NfLog).Loop(0xc8200160a0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 9 [syscall, locked to thread]:
main._C2func_recv(0x6, 0x7f1d1db54010, 0x400000, 0x0, 0x0, 0x0, 0x0)
    ??:0 +0x56
main.(*NfLog).Loop(0xc8200161e0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 10 [syscall, locked to thread]:
main._C2func_recv(0x7, 0x7f1d1c751010, 0x400000, 0x0, 0x0, 0x0, 0x0)
    ??:0 +0x56
main.(*NfLog).Loop(0xc820016280)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 11 [runnable]:
main.(*Accounting).Engine(0xc82000a1b0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:190 +0x3fa
created by main.(*Accounting).Start
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:280 +0x8a

goroutine 12 [select]:
main.(*Accounting).DumpStats(0xc82000a1b0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:260 +0x6f1
created by main.(*Accounting).Start
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:282 +0xcf

goroutine 13 [select, locked to thread]:
runtime.gopark(0x60bf20, 0xc820021f28, 0x5c24d8, 0x6, 0x18, 0x2)
    /usr/local/go/src/runtime/proc.go:262 +0x163
runtime.selectgoImpl(0xc820021f28, 0x0, 0x18)
    /usr/local/go/src/runtime/select.go:392 +0xa67
runtime.selectgo(0xc820021f28)
    /usr/local/go/src/runtime/select.go:215 +0x12
runtime.ensureSigM.func1()
    /usr/local/go/src/runtime/signal1_unix.go:279 +0x358
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1

And here is one with GOTRACEBACK=all

panic: fatal error: malloc deadlock

goroutine 0 [idle]:
panic(0x58a9a0, 0xc8200100e0)
    /usr/local/go/src/runtime/panic.go:355 +0x7a

goroutine 7 [syscall, locked to thread]:
runtime.cgocall(0x536610, 0xc8200ebea0, 0x0)
    /usr/local/go/src/runtime/cgocall.go:123 +0x11b fp=0xc8200ebe50 sp=0xc8200ebe20
main._Cfunc_nflog_handle_packet(0xef2050, 0x7fc6000008c0, 0x1144, 0x0)
    ??:0 +0x41 fp=0xc8200ebea0 sp=0xc8200ebe50
main.(*NfLog).Loop(0xc8200160a0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:357 +0x386 fp=0xc8200ebfa8 sp=0xc8200ebea0
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200ebfb0 sp=0xc8200ebfa8
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 1 [chan receive, 1 minutes]:
main.main()
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:399 +0xf1a

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

goroutine 5 [syscall, 1 minutes]:
os/signal.signal_recv(0x0)
    /usr/local/go/src/runtime/sigqueue.go:116 +0x132
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 6 [syscall, 1 minutes]:
runtime.CPUProfile(0x0, 0x0, 0x0)
    /usr/local/go/src/runtime/cpuprof.go:421 +0x34
runtime/pprof.profileWriter(0x7fc61782f308, 0xc820028030)
    /usr/local/go/src/runtime/pprof/pprof.go:607 +0x1c
created by runtime/pprof.StartCPUProfile
    /usr/local/go/src/runtime/pprof/pprof.go:601 +0x145

goroutine 8 [runnable, locked to thread]:
main._C2func_recv(0x5, 0x7fc5fc0008c0, 0x400000, 0x0, 0x1dc4, 0x0, 0x0)
    ??:0 +0x56
main.(*NfLog).Loop(0xc820016140)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 9 [syscall, locked to thread]:
main._C2func_recv(0x6, 0x7fc6080008c0, 0x400000, 0x0, 0x0, 0x0, 0x0)
    ??:0 +0x56
main.(*NfLog).Loop(0xc8200161e0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 10 [syscall, locked to thread]:
main._C2func_recv(0x7, 0x7fc60e3fc010, 0x400000, 0x0, 0x0, 0x0, 0x0)
    ??:0 +0x56
main.(*NfLog).Loop(0xc820016280)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 11 [runnable]:
main.(*Accounting).Engine(0xc82000a1b0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:190 +0x3fa
created by main.(*Accounting).Start
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:280 +0x8a

goroutine 12 [select]:
main.(*Accounting).DumpStats(0xc82000a1b0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:260 +0x6f1
created by main.(*Accounting).Start
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:282 +0xcf

goroutine 13 [select, 1 minutes, locked to thread]:
runtime.gopark(0x60bf20, 0xc820021f28, 0x5c24d8, 0x6, 0x18, 0x2)
    /usr/local/go/src/runtime/proc.go:262 +0x163
runtime.selectgoImpl(0xc820021f28, 0x0, 0x18)
    /usr/local/go/src/runtime/select.go:392 +0xa67
runtime.selectgo(0xc820021f28)
    /usr/local/go/src/runtime/select.go:215 +0x12
runtime.ensureSigM.func1()
    /usr/local/go/src/runtime/signal1_unix.go:279 +0x358
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1

And one with GOTRACEBACK=system

panic: fatal error: malloc deadlock

goroutine 0 [idle]:
runtime.throw(0x5c8120, 0xf)
    /usr/local/go/src/runtime/panic.go:530 +0x90 fp=0xc8200df158 sp=0xc8200df140
runtime.mallocgc(0x21, 0x0, 0x3, 0x0)
    /usr/local/go/src/runtime/malloc.go:544 +0x1cc fp=0xc8200df230 sp=0xc8200df158
runtime.rawstring(0x21, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/go/src/runtime/string.go:284 +0x70 fp=0xc8200df278 sp=0xc8200df230
runtime.rawstringtmp(0x0, 0x21, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/go/src/runtime/string.go:111 +0xb7 fp=0xc8200df2b0 sp=0xc8200df278
runtime.concatstrings(0x0, 0xc8200df440, 0x2, 0x2, 0x0, 0x0)
    /usr/local/go/src/runtime/string.go:49 +0x1bb fp=0xc8200df3e8 sp=0xc8200df2b0
runtime.concatstring2(0x0, 0x5c92c0, 0xf, 0x5e52d0, 0x12, 0x0, 0x0)
    /usr/local/go/src/runtime/string.go:59 +0x67 fp=0xc8200df438 sp=0xc8200df3e8
runtime.(*errorString).Error(0xc8200100d0, 0x0, 0x0)
    <autogenerated>:2 +0xde fp=0xc8200df498 sp=0xc8200df438
runtime.printany(0x58a9a0, 0xc8200100d0)
    /usr/local/go/src/runtime/error.go:73 +0x1aa fp=0xc8200df568 sp=0xc8200df498
panic(0x58a9a0, 0xc8200100d0)
    /usr/local/go/src/runtime/panic.go:355 +0x7a fp=0xc8200df5e8 sp=0xc8200df568
runtime.panicindex()
    /usr/local/go/src/runtime/panic.go:15 +0x49 fp=0xc8200df610 sp=0xc8200df5e8
runtime.findfunc(0x536110, 0x0)
    /usr/local/go/src/runtime/symtab.go:227 +0x195 fp=0xc8200df650 sp=0xc8200df610
runtime.setsSP(0x536110, 0xc800000000)
    /usr/local/go/src/runtime/proc.go:3104 +0x21 fp=0xc8200df668 sp=0xc8200df650
runtime.sigprof(0x536110, 0x7f8f237fdd18, 0x0, 0xc8200a6780, 0xc8200a4800)
    /usr/local/go/src/runtime/proc.go:3020 +0xb8 fp=0xc8200df940 sp=0xc8200df668
runtime.sighandler(0xc80000001b, 0xc8200dfbb0, 0xc8200dfa80, 0xc8200a6780)
    /usr/local/go/src/runtime/signal_amd64x.go:49 +0xbe fp=0xc8200df9d8 sp=0xc8200df940
runtime.sigtrampgo(0x1b, 0xc8200dfbb0, 0xc8200dfa80)
    /usr/local/go/src/runtime/signal_sigtramp.go:48 +0xf6 fp=0xc8200dfa60 sp=0xc8200df9d8
runtime.sigtramp(0x1, 0x0, 0xc8200d8000, 0x0, 0x7fa0, 0x7f8f30155ad0, 0x13f3010, 0x7f8f237fdd40, 0x5f7140, 0x7f8f30155ac0, ...)
    /usr/local/go/src/runtime/sys_linux_amd64.s:234 +0x1b fp=0xc8200dfa80 sp=0xc8200dfa60
runtime.sigreturn(0x0, 0xc8200d8000, 0x0, 0x7fa0, 0x7f8f30155ad0, 0x13f3010, 0x7f8f237fdd40, 0x5f7140, 0x7f8f30155ac0, 0x50, ...)
    /usr/local/go/src/runtime/sys_linux_amd64.s:238 fp=0xc8200dfa88 sp=0xc8200dfa80

goroutine 7 [syscall, locked to thread]:
runtime.cgocall(0x536610, 0xc8200e5ea0, 0x0)
    /usr/local/go/src/runtime/cgocall.go:123 +0x11b fp=0xc8200e5e50 sp=0xc8200e5e20
main._Cfunc_nflog_handle_packet(0x13f3050, 0x7f8f30155010, 0x1144, 0x0)
    ??:0 +0x41 fp=0xc8200e5ea0 sp=0xc8200e5e50
main.(*NfLog).Loop(0xc8200160a0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:357 +0x386 fp=0xc8200e5fa8 sp=0xc8200e5ea0
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200e5fb0 sp=0xc8200e5fa8
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 1 [chan receive]:
runtime.gopark(0x60bee8, 0xc820060598, 0x5c6990, 0xc, 0x17, 0x3)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820039bb0 sp=0xc820039b88
runtime.goparkunlock(0xc820060598, 0x5c6990, 0xc, 0xc8200a2017, 0x3)
    /usr/local/go/src/runtime/proc.go:268 +0x54 fp=0xc820039be8 sp=0xc820039bb0
runtime.chanrecv(0x5462c0, 0xc820060540, 0xc820039eb8, 0x1, 0x0)
    /usr/local/go/src/runtime/chan.go:470 +0x49f fp=0xc820039c70 sp=0xc820039be8
runtime.chanrecv1(0x5462c0, 0xc820060540, 0xc820039eb8)
    /usr/local/go/src/runtime/chan.go:355 +0x2b fp=0xc820039ca0 sp=0xc820039c70
main.main()
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:399 +0xf1a fp=0xc820039f60 sp=0xc820039ca0
runtime.main()
    /usr/local/go/src/runtime/proc.go:188 +0x2b0 fp=0xc820039fb0 sp=0xc820039f60
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820039fb8 sp=0xc820039fb0

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820038fb8 sp=0xc820038fb0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x60bee8, 0x8a8db0, 0x5c7450, 0xf, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820024758 sp=0xc820024730
runtime.goparkunlock(0x8a8db0, 0x5c7450, 0xf, 0xc820000114, 0x1)
    /usr/local/go/src/runtime/proc.go:268 +0x54 fp=0xc820024790 sp=0xc820024758
runtime.forcegchelper()
    /usr/local/go/src/runtime/proc.go:229 +0xb8 fp=0xc8200247c0 sp=0xc820024790
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200247c8 sp=0xc8200247c0
created by runtime.init.4
    /usr/local/go/src/runtime/proc.go:218 +0x2b

goroutine 3 [GC sweep wait]:
runtime.gopark(0x60bee8, 0x8a8f00, 0x5c47c0, 0xd, 0x45cf14, 0x1)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820024f48 sp=0xc820024f20
runtime.goparkunlock(0x8a8f00, 0x5c47c0, 0xd, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:268 +0x54 fp=0xc820024f80 sp=0xc820024f48
runtime.bgsweep(0xc820056000)
    /usr/local/go/src/runtime/mgcsweep.go:79 +0x14d fp=0xc820024fb8 sp=0xc820024f80
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820024fc0 sp=0xc820024fb8
created by runtime.gcenable
    /usr/local/go/src/runtime/mgc.go:191 +0x53

goroutine 4 [finalizer wait]:
runtime.gopark(0x60bee8, 0x8c3a20, 0x5c7120, 0xe, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820025718 sp=0xc8200256f0
runtime.goparkunlock(0x8c3a20, 0x5c7120, 0xe, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:268 +0x54 fp=0xc820025750 sp=0xc820025718
runtime.runfinq()
    /usr/local/go/src/runtime/mfinal.go:158 +0xaa fp=0xc8200257c0 sp=0xc820025750
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200257c8 sp=0xc8200257c0
created by runtime.createfing
    /usr/local/go/src/runtime/mfinal.go:139 +0x60

goroutine 5 [syscall]:
runtime.notetsleepg(0x8c3ca0, 0xffffffffffffffff, 0x1)
    /usr/local/go/src/runtime/lock_futex.go:205 +0x4e fp=0xc820025f40 sp=0xc820025f18
os/signal.signal_recv(0x0)
    /usr/local/go/src/runtime/sigqueue.go:116 +0x132 fp=0xc820025f78 sp=0xc820025f40
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x18 fp=0xc820025fc0 sp=0xc820025f78
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820025fc8 sp=0xc820025fc0
created by os/signal.init.1
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 6 [syscall]:
runtime.notetsleepg(0x7f8f3255a008, 0xffffffffffffffff, 0x0)
    /usr/local/go/src/runtime/lock_futex.go:205 +0x4e fp=0xc820026620 sp=0xc8200265f8
runtime.(*cpuProfile).getprofile(0x7f8f3255a000, 0x0, 0x0, 0x0)
    /usr/local/go/src/runtime/cpuprof.go:341 +0x5dd fp=0xc820026728 sp=0xc820026620
runtime.CPUProfile(0x0, 0x0, 0x0)
    /usr/local/go/src/runtime/cpuprof.go:421 +0x34 fp=0xc820026750 sp=0xc820026728
runtime/pprof.profileWriter(0x7f8f34bdd308, 0xc820028030)
    /usr/local/go/src/runtime/pprof/pprof.go:607 +0x1c fp=0xc8200267b0 sp=0xc820026750
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200267b8 sp=0xc8200267b0
created by runtime/pprof.StartCPUProfile
    /usr/local/go/src/runtime/pprof/pprof.go:601 +0x145

goroutine 8 [runnable, locked to thread]:
runtime.cgocall(0x536610, 0xc820036ea0, 0x0)
    /usr/local/go/src/runtime/cgocall.go:123 +0x11b fp=0xc820036e50 sp=0xc820036e20
main._Cfunc_nflog_handle_packet(0x13f3b50, 0x7f8f180008c0, 0x1dc4, 0xffffffff)
    ??:0 +0x41 fp=0xc820036ea0 sp=0xc820036e50
main.(*NfLog).Loop(0xc820016140)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:357 +0x386 fp=0xc820036fa8 sp=0xc820036ea0
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820036fb0 sp=0xc820036fa8
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 9 [syscall, locked to thread]:
runtime.cgocall(0x5364a0, 0xc820035ea0, 0x0)
    /usr/local/go/src/runtime/cgocall.go:123 +0x11b fp=0xc820035e30 sp=0xc820035e00
main._C2func_recv(0x6, 0x7f8f280008c0, 0x400000, 0x0, 0x0, 0x0, 0x0)
    ??:0 +0x56 fp=0xc820035ea0 sp=0xc820035e30
main.(*NfLog).Loop(0xc8200161e0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202 fp=0xc820035fa8 sp=0xc820035ea0
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820035fb0 sp=0xc820035fa8
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 10 [syscall, locked to thread]:
runtime.cgocall(0x5364a0, 0xc8200e4ea0, 0xc800000000)
    /usr/local/go/src/runtime/cgocall.go:123 +0x11b fp=0xc8200e4e30 sp=0xc8200e4e00
main._C2func_recv(0x7, 0x7f8f1c0008c0, 0x400000, 0x0, 0x0, 0x0, 0x0)
    ??:0 +0x56 fp=0xc8200e4ea0 sp=0xc8200e4e30
main.(*NfLog).Loop(0xc820016280)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:344 +0x202 fp=0xc8200e4fa8 sp=0xc8200e4ea0
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200e4fb0 sp=0xc8200e4fa8
created by main.NewNfLog
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/nflog.go:192 +0x501

goroutine 11 [select]:
runtime.gopark(0x60bf20, 0xc820034ed8, 0x5c24d8, 0x6, 0xc820485e18, 0x2)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820034c00 sp=0xc820034bd8
runtime.selectgoImpl(0xc820034ed8, 0x0, 0x18)
    /usr/local/go/src/runtime/select.go:392 +0xa67 fp=0xc820034dc0 sp=0xc820034c00
runtime.selectgo(0xc820034ed8)
    /usr/local/go/src/runtime/select.go:215 +0x12 fp=0xc820034de0 sp=0xc820034dc0
main.(*Accounting).Engine(0xc82000a1b0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:190 +0x3fa fp=0xc820034fa8 sp=0xc820034de0
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820034fb0 sp=0xc820034fa8
created by main.(*Accounting).Start
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:280 +0x8a

goroutine 12 [select]:
runtime.gopark(0x60bf20, 0xc820077f00, 0x5c24d8, 0x6, 0x18, 0x2)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820077bc8 sp=0xc820077ba0
runtime.selectgoImpl(0xc820077f00, 0x0, 0x18)
    /usr/local/go/src/runtime/select.go:392 +0xa67 fp=0xc820077d88 sp=0xc820077bc8
runtime.selectgo(0xc820077f00)
    /usr/local/go/src/runtime/select.go:215 +0x12 fp=0xc820077da8 sp=0xc820077d88
main.(*Accounting).DumpStats(0xc82000a1b0)
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:260 +0x6f1 fp=0xc820077f98 sp=0xc820077da8
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820077fa0 sp=0xc820077f98
created by main.(*Accounting).Start
    /home/ncw/Code/Go/src/github.com/ncw/go-nflog-acctd/main.go:282 +0xcf

goroutine 13 [select, locked to thread]:
runtime.gopark(0x60bf20, 0xc820021f28, 0x5c24d8, 0x6, 0x18, 0x2)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820021d08 sp=0xc820021ce0
runtime.selectgoImpl(0xc820021f28, 0x0, 0x18)
    /usr/local/go/src/runtime/select.go:392 +0xa67 fp=0xc820021ec8 sp=0xc820021d08
runtime.selectgo(0xc820021f28)
    /usr/local/go/src/runtime/select.go:215 +0x12 fp=0xc820021ee8 sp=0xc820021ec8
runtime.ensureSigM.func1()
    /usr/local/go/src/runtime/signal1_unix.go:279 +0x358 fp=0xc820021fc0 sp=0xc820021ee8
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820021fc8 sp=0xc820021fc0
created by runtime.ensureSigM
    /usr/local/go/src/runtime/signal1_unix.go:292 +0xd0

goroutine 14 [syscall]:
runtime.notetsleepg(0x8a8f38, 0x25406bc80, 0x16)
    /usr/local/go/src/runtime/lock_futex.go:205 +0x4e fp=0xc820022738 sp=0xc820022710
runtime.timerproc()
    /usr/local/go/src/runtime/time.go:209 +0xde fp=0xc8200227c0 sp=0xc820022738
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200227c8 sp=0xc8200227c0
created by runtime.addtimerLocked
    /usr/local/go/src/runtime/time.go:116 +0x11f

goroutine 18 [GC worker (idle)]:
runtime.gopark(0xc8203b8010, 0xc82048c7a0, 0x5e06b0, 0x10, 0x14, 0x0)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc82048c740 sp=0xc82048c718
runtime.gcBgMarkWorker(0xc820018000)
    /usr/local/go/src/runtime/mgc.go:1402 +0xda fp=0xc82048c7b8 sp=0xc82048c740
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc82048c7c0 sp=0xc82048c7b8
created by runtime.gcBgMarkStartWorkers
    /usr/local/go/src/runtime/mgc.go:1329 +0x92

goroutine 19 [GC worker (idle)]:
runtime.gopark(0xc820478000, 0xc82048cfa0, 0x5e06b0, 0x10, 0x14, 0x0)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc82048cf40 sp=0xc82048cf18
runtime.gcBgMarkWorker(0xc820019500)
    /usr/local/go/src/runtime/mgc.go:1402 +0xda fp=0xc82048cfb8 sp=0xc82048cf40
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc82048cfc0 sp=0xc82048cfb8
created by runtime.gcBgMarkStartWorkers
    /usr/local/go/src/runtime/mgc.go:1329 +0x92

goroutine 15 [GC worker (idle)]:
runtime.gopark(0xc82017dba0, 0xc8200217a0, 0x5e06b0, 0x10, 0x14, 0x0)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820021740 sp=0xc820021718
runtime.gcBgMarkWorker(0xc82001aa00)
    /usr/local/go/src/runtime/mgc.go:1402 +0xda fp=0xc8200217b8 sp=0xc820021740
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8200217c0 sp=0xc8200217b8
created by runtime.gcBgMarkStartWorkers
    /usr/local/go/src/runtime/mgc.go:1329 +0x92

goroutine 16 [GC worker (idle)]:
runtime.gopark(0xc820185910, 0xc820022fa0, 0x5e06b0, 0x10, 0x14, 0x0)
    /usr/local/go/src/runtime/proc.go:262 +0x163 fp=0xc820022f40 sp=0xc820022f18
runtime.gcBgMarkWorker(0xc82001c000)
    /usr/local/go/src/runtime/mgc.go:1402 +0xda fp=0xc820022fb8 sp=0xc820022f40
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820022fc0 sp=0xc820022fb8
created by runtime.gcBgMarkStartWorkers
    /usr/local/go/src/runtime/mgc.go:1329 +0x92

The text was updated successfully, but these errors were encountered:

minux · 2016-03-02T18:06:08Z

The key pieces of information is this part of stack trace:

runtime.panicindex()
/usr/local/go/src/runtime/panic.go:15 +0x49 fp=0xc8200df610 sp=0xc8200df5e8
runtime.findfunc(0x536110, 0x0)
/usr/local/go/src/runtime/symtab.go:227 +0x195 fp=0xc8200df650 sp=0xc8200df610
runtime.setsSP(0x536110, 0xc800000000)
/usr/local/go/src/runtime/proc.go:3104 +0x21 fp=0xc8200df668 sp=0xc8200df650
runtime.sigprof(0x536110, 0x7f8f237fdd18, 0x0, 0xc8200a6780, 0xc8200a4800)
/usr/local/go/src/runtime/proc.go:3020 +0xb8 fp=0xc8200df940 sp=0xc8200df668
runtime.sighandler(0xc80000001b, 0xc8200dfbb0, 0xc8200dfa80, 0xc8200a6780)
/usr/local/go/src/runtime/signal_amd64x.go:49 +0xbe fp=0xc8200df9d8 sp=0xc8200df940

sigprof tries to find the func corresponding to 0x536110, but
that pc seems to be in a foreign (C) function, and findfunc
panics with index out out of range at line 227:
https://golang.org/src/runtime/symtab.go#L227.
Because sigprof disables malloc, and trying to print the
index out of range allocates new string, it triggers the
malloc deadlock error.

ianlancetaylor · 2016-03-04T18:30:23Z

My current guess is that 0x536110 is not actually a C function. If it were a C function, it would fail the findmoduledatap test at the start of findfunc. I think that address is actually the very last Go function. I can recreate the problem with this, because the cgo function that calls the C code winds up as the last Go function in the binary.

package main

// void nop() {}
import "C"

import (
    "bytes"
    "runtime/pprof"
)

func main() {
    c := make(chan bool)
    go func() {
        for {
            <-c
            for i := 0; i < 1e7; i++ {
                C.nop()
            }
            c <- true
        }
    }()

    for try := 0; try < 10; try++ {
        var buf bytes.Buffer
        pprof.StartCPUProfile(&buf)
        c <- true
        <-c
        pprof.StopCPUProfile()
    }
}

ianlancetaylor · 2016-03-04T18:39:44Z

Oh, sorry, I'm wrong, the crash is happening when the PC is the first instruction in the C function, which happens to equal firstmoduledatap.maxpc.

gopherbot · 2016-03-04T20:00:58Z

CL https://golang.org/cl/20219 mentions this issue.

gopherbot · 2016-04-14T02:01:02Z

CL https://golang.org/cl/22042 mentions this issue.

Also fix compiler-invoked panics to avoid a confusing "malloc deadlock" crash if they are invoked while executing the runtime. Fixes #14599. Change-Id: I89436abcbf3587901909abbdca1973301654a76e Reviewed-on: https://go-review.googlesource.com/20219 Run-TryBot: Ian Lance Taylor <[email protected]> TryBot-Result: Gobot Gobot <[email protected]> Reviewed-by: Keith Randall <[email protected]> Reviewed-on: https://go-review.googlesource.com/22042 Reviewed-by: Ian Lance Taylor <[email protected]>

ianlancetaylor added this to the Go1.6.1 milestone Mar 3, 2016

ianlancetaylor self-assigned this Mar 4, 2016

gopherbot closed this as completed in 1716162 Mar 4, 2016

adg added the Release-OK label Apr 7, 2016

adg modified the milestones: Go1.6.1, Go1.6.2 Apr 7, 2016

adg added Release-Applied and removed Release-OK labels Apr 14, 2016

ianlancetaylor mentioned this issue Sep 23, 2016

runtime: crash on Windows-created thread calling Go code during CPU profiling #17165

Closed

golang locked and limited conversation to collaborators Apr 19, 2017

gopherbot added the FrozenDueToAge label Apr 19, 2017

rsc unassigned ianlancetaylor Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: panic: "fatal error: malloc deadlock" with CPU profile #14599

runtime: panic: "fatal error: malloc deadlock" with CPU profile #14599

ncw commented Mar 2, 2016

minux commented Mar 2, 2016

ianlancetaylor commented Mar 4, 2016

ianlancetaylor commented Mar 4, 2016

gopherbot commented Mar 4, 2016

gopherbot commented Apr 14, 2016

runtime: panic: "fatal error: malloc deadlock" with CPU profile #14599

runtime: panic: "fatal error: malloc deadlock" with CPU profile #14599

Comments

ncw commented Mar 2, 2016

minux commented Mar 2, 2016

ianlancetaylor commented Mar 4, 2016

ianlancetaylor commented Mar 4, 2016

gopherbot commented Mar 4, 2016

gopherbot commented Apr 14, 2016