Crash -- program exceeds 10000-thread limit

[keithchew]

Running on v2.60.9, just encountered this:

runtime: program exceeds 10000-thread limit
fatal error: thread exhaustion

runtime stack:
runtime.throw({0x298f5ef?, 0x4a2ac0?})
	runtime/panic.go:1023 +0x5c fp=0x7f9710072cb8 sp=0x7f9710072c88 pc=0x468c5c
runtime.checkmcount()
	runtime/proc.go:868 +0x8e fp=0x7f9710072ce0 sp=0x7f9710072cb8 pc=0x46dace
runtime.mReserveID()
	runtime/proc.go:884 +0x2f fp=0x7f9710072d08 sp=0x7f9710072ce0 pc=0x46db0f
runtime.startm(0xc000064008?, 0x0, 0x0)
	runtime/proc.go:2862 +0x111 fp=0x7f9710072d58 sp=0x7f9710072d08 pc=0x4710b1
runtime.handoffp(0x7f97ffffffff?)
	runtime/proc.go:2911 +0x336 fp=0x7f9710072d80 sp=0x7f9710072d58 pc=0x4715b6
runtime.retake(0x3b71e6e03ef1)
	runtime/proc.go:6165 +0x23d fp=0x7f9710072de0 sp=0x7f9710072d80 pc=0x4793dd
runtime.sysmon()
	runtime/proc.go:6071 +0x345 fp=0x7f9710072e48 sp=0x7f9710072de0 pc=0x479085
runtime.mstart1()
	runtime/proc.go:1729 +0x93 fp=0x7f9710072e70 sp=0x7f9710072e48 pc=0x46f5f3
runtime.mstart0()
	runtime/proc.go:1686 +0x76 fp=0x7f9710072ea0 sp=0x7f9710072e70 pc=0x46f536
runtime.mstart()
	runtime/asm_amd64.s:394 +0x5 fp=0x7f9710072ea8 sp=0x7f9710072ea0 pc=0x4a2ac5

goroutine 1 gp=0xc0000081c0 m=nil [chan receive, 497 minutes]:
runtime.gopark(0xc002bed788?, 0x475f0b?, 0x68?, 0xd7?, 0x475f40?)
	runtime/proc.go:402 +0xce fp=0xc0f31d9750 sp=0xc0f31d9730 pc=0x46c84e
runtime.chanrecv(0xc000f86060, 0x0, 0x1)
	runtime/chan.go:583 +0x3bf fp=0xc0f31d97c8 sp=0xc0f31d9750 pc=0x4352ff
runtime.chanrecv1(0xc0007dc0e0?, 0xc000a337c0?)
	runtime/chan.go:442 +0x12 fp=0xc0f31d97f0 sp=0xc0f31d97c8 pc=0x434f12
github.com/ledgerwatch/erigon/node.(*Node).Wait(...)
	github.com/ledgerwatch/erigon/node/node.go:272
github.com/ledgerwatch/erigon/turbo/node.(*ErigonNode).Serve(0xc0fee219a0)
	github.com/ledgerwatch/erigon/turbo/node/node.go:34 +0x6e fp=0xc0f31d9840 sp=0xc0f31d97f0 pc=0x224adee
main.runErigon(0xc000f71f40)
	github.com/ledgerwatch/erigon/cmd/erigon/main.go:74 +0x405 fp=0xc0f31d9ab8 sp=0xc0f31d9840 pc=0x2266c45
github.com/ledgerwatch/erigon/turbo/app.MakeApp.func1(0xc000f71f40)
	github.com/ledgerwatch/erigon/turbo/app/make_app.go:54 +0x17f fp=0xc0f31d9be0 sp=0xc0f31d9ab8 pc=0x225b0ff
github.com/urfave/cli/v2.(*Command).Run(0xc000b411e0, 0xc000f71f40, {0xc000138008, 0x21, 0x23})
	github.com/urfave/cli/v2@v2.27.2/command.go:276 +0x97d fp=0xc0f31d9e68 sp=0xc0f31d9be0 pc=0x80537d
github.com/urfave/cli/v2.(*App).RunContext(0xc000f78800, {0x31eb760, 0x52181e0}, {0xc000138008, 0x21, 0x23})
	github.com/urfave/cli/v2@v2.27.2/app.go:333 +0x58b fp=0xc0f31d9ec8 sp=0xc0f31d9e68 pc=0x801cab
github.com/urfave/cli/v2.(*App).Run(...)
	github.com/urfave/cli/v2@v2.27.2/app.go:307
main.main()
	github.com/ledgerwatch/erigon/cmd/erigon/main.go:34 +0x85 fp=0xc0f31d9f50 sp=0xc0f31d9ec8 pc=0x2266765
runtime.main()
	runtime/proc.go:271 +0x29d fp=0xc0f31d9fe0 sp=0xc0f31d9f50 pc=0x46c3fd
runtime.goexit({})
	runtime/asm_amd64.s:1695 +0x1 fp=0xc0f31d9fe8 sp=0xc0f31d9fe0 pc=0x4a4b81

goroutine 2 gp=0xc000008c40 m=nil [force gc (idle), 497 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	runtime/proc.go:402 +0xce fp=0xc000076fa8 sp=0xc000076f88 pc=0x46c84e
runtime.goparkunlock(...)
	runtime/proc.go:408
runtime.forcegchelper()
	runtime/proc.go:326 +0xb3 fp=0xc000076fe0 sp=0xc000076fa8 pc=0x46c6b3
runtime.goexit({})
	runtime/asm_amd64.s:1695 +0x1 fp=0xc000076fe8 sp=0xc000076fe0 pc=0x4a4b81
created by runtime.init.6 in goroutine 1
	runtime/proc.go:314 +0x1a

goroutine 3 gp=0xc000009180 m=nil [GC sweep wait]:
runtime.gopark(0x1?, 0x0?, 0x0?, 0x0?, 0x0?)
	runtime/proc.go:402 +0xce fp=0xc000077780 sp=0xc000077760 pc=0x46c84e
runtime.goparkunlock(...)
	runtime/proc.go:408
runtime.bgsweep(0xc0000a0000)
	runtime/mgcsweep.go:318 +0xdf fp=0xc0000777c8 sp=0xc000077780 pc=0x45525f
runtime.gcenable.gowrap1()
	runtime/mgc.go:203 +0x25 fp=0xc0000777e0 sp=0xc0000777c8 pc=0x449a85
runtime.goexit({})
	runtime/asm_amd64.s:1695 +0x1 fp=0xc0000777e8 sp=0xc0000777e0 pc=0x4a4b81
created by runtime.gcenable in goroutine 1
	runtime/mgc.go:203 +0x66

...

goroutine 92605051 gp=0xc146e9b340 m=3853 mp=0xc16db1e008 [syscall, locked to thread]:
runtime.cgocall(0x226b190, 0xc0a719ebd8)
	runtime/cgocall.go:157 +0x4b fp=0xc0a719ebb0 sp=0xc0a719eb78 pc=0x432ceb
github.com/erigontech/mdbx-go/mdbx._Cfunc_mdbx_txn_begin(0x7f96fc0192d0, 0x0, 0x0, 0xc0e723dd48)
	_cgo_gotypes.go:939 +0x4b fp=0xc0a719ebd8 sp=0xc0a719ebb0 pc=0x9ee3ab
github.com/erigontech/mdbx-go/mdbx.beginTxn.func1(0xa4d225?, 0x0, 0x0, 0x43585e?)
	github.com/erigontech/mdbx-go@v0.27.24/mdbx/txn.go:103 +0xb2 fp=0xc0a719ec30 sp=0xc0a719ebd8 pc=0x9f5272
github.com/erigontech/mdbx-go/mdbx.beginTxn(0xc10199d1d0, 0x0, 0x0)
	github.com/erigontech/mdbx-go@v0.27.24/mdbx/txn.go:103 +0x176 fp=0xc0a719ec78 sp=0xc0a719ec30 pc=0x9f5076
github.com/erigontech/mdbx-go/mdbx.(*Env).BeginTxn(...)
	github.com/erigontech/mdbx-go@v0.27.24/mdbx/env.go:528
github.com/ledgerwatch/erigon-lib/kv/mdbx.(*MdbxKV).beginRw(0xc100560f00, {0x31ebc08, 0xc10199e6e0}, 0x0)
	github.com/ledgerwatch/erigon-lib@v1.0.0/kv/mdbx/kv_mdbx.go:798 +0x90 fp=0xc0a719ed30 sp=0xc0a719ec78 pc=0xa4de50
github.com/ledgerwatch/erigon-lib/kv/mdbx.(*MdbxKV).BeginRw(...)
	github.com/ledgerwatch/erigon-lib@v1.0.0/kv/mdbx/kv_mdbx.go:780
github.com/ledgerwatch/erigon-lib/kv/mdbx.(*MdbxKV).Update(0x10?, {0x31ebc08?, 0xc10199e6e0?}, 0xc0e723dd00)
	github.com/ledgerwatch/erigon-lib@v1.0.0/kv/mdbx/kv_mdbx.go:934 +0x45 fp=0xc0a719eda8 sp=0xc0a719ed30 pc=0xa4ebc5
github.com/ledgerwatch/erigon/p2p/enode.(*DB).storeInt64(0xc1019fedc0, {0xc0e721d980, 0x3f, 0x3f}, 0x95)
	github.com/ledgerwatch/erigon/p2p/enode/nodedb.go:263 +0x12c fp=0xc0a719ede8 sp=0xc0a719eda8 pc=0x13c0a8c
github.com/ledgerwatch/erigon/p2p/enode.(*DB).UpdateFindFails(0xc1019fedc0, {0xe5, 0xa0, 0x70, 0x50, 0x2f, 0x70, 0x11, 0x47, 0x30, ...}, ...)
	github.com/ledgerwatch/erigon/p2p/enode/nodedb.go:525 +0xf3 fp=0xc0a719ee58 sp=0xc0a719ede8 pc=0x13c3373
github.com/ledgerwatch/erigon/p2p/discover.(*lookup).query(0xc19ab5e120, 0xc15afbbc20, 0xc1b4d7f440)
	github.com/ledgerwatch/erigon/p2p/discover/lookup.go:171 +0x265 fp=0xc0a719efb8 sp=0xc0a719ee58 pc=0x13cff05
github.com/ledgerwatch/erigon/p2p/discover.(*lookup).startQueries.gowrap1()
	github.com/ledgerwatch/erigon/p2p/discover/lookup.go:128 +0x28 fp=0xc0a719efe0 sp=0xc0a719efb8 pc=0x13cfb08
runtime.goexit({})
	runtime/asm_amd64.s:1695 +0x1 fp=0xc0a719efe8 sp=0xc0a719efe0 pc=0x4a4b81
created by github.com/ledgerwatch/erigon/p2p/discover.(*lookup).startQueries in goroutine 92544942
	github.com/ledgerwatch/erigon/p2p/discover/lookup.go:128 +0x219

goroutine 92610822 gp=0xc146e9b500 m=nil [sync.Cond.Wait]:
runtime.gopark(0xc0803a9508?, 0xc162d88000?, 0x20?, 0x6f?, 0xc04a2d6f38?)
	runtime/proc.go:402 +0xce fp=0xc04a2d6eb8 sp=0xc04a2d6e98 pc=0x46c84e
runtime.goparkunlock(...)
	runtime/proc.go:408
sync.runtime_notifyListWait(0xc0e2fa6880, 0x0)
	runtime/sema.go:569 +0x159 fp=0xc04a2d6f08 sp=0xc04a2d6eb8 pc=0x4a0df9
sync.(*Cond).Wait(0x2e732a87e9d4940f?)
	sync/cond.go:70 +0x85 fp=0xc04a2d6f48 sp=0xc04a2d6f08 pc=0x4c4985
github.com/anacrolix/torrent/mse.(*handshake).writer(0xc0e2fa6780)
	github.com/anacrolix/torrent@v1.52.6-0.20231201115409-7ea994b6bbd8/mse/mse.go:261 +0x177 fp=0xc04a2d6fc8 sp=0xc04a2d6f48 pc=0xd6a6d7
github.com/anacrolix/torrent/mse.(*handshake).Do.gowrap1()
	github.com/anacrolix/torrent@v1.52.6-0.20231201115409-7ea994b6bbd8/mse/mse.go:517 +0x25 fp=0xc04a2d6fe0 sp=0xc04a2d6fc8 pc=0xd6d3e5
runtime.goexit({})
	runtime/asm_amd64.s:1695 +0x1 fp=0xc04a2d6fe8 sp=0xc04a2d6fe0 pc=0x4a4b81
created by github.com/anacrolix/torrent/mse.(*handshake).Do in goroutine 92610821
	github.com/anacrolix/torrent@v1.52.6-0.20231201115409-7ea994b6bbd8/mse/mse.go:517 +0xe5

Note that this erigon node is running in an AMD (Ryzen 5 7600x) system, other nodes on Intel were OK, although this could just be a coincidence...

[AskAlexSharov]

Reduce —db.reqd.concurrency

[keithchew]

Thanks @AskAlexSharov, it is interesting... The default value according to the code is:

	DBReadConcurrencyFlag = cli.IntFlag{
		Name:  "db.read.concurrency",
		Usage: "Does limit amount of parallel db reads. Default: equal to GOMAXPROCS (or number of CPU)",
		Value: cmp.Min(cmp.Max(10, runtime.GOMAXPROCS(-1)*64), 9_000),
	}

So with GOMAXPROCS = 12 (for 12 cores), the value will be 12*64=768, which is low compared to max value of 9000. I will try setting GOMAXPROCS to 4 to limit both max proc and db.read.concurrency to see if that helps.

[AskAlexSharov]

This limit is for main db only (it handling most of RPC requests, etc...).
But we also have many databases - they are unlimited but must not produce much threads. (but example in your trace shows p2p/enode/nodedb.go:525 it's small unlimited db).

Also maybe you faced some other bug. To cover most of possible cases do:

• set a bit smaller --db.read.concurrency
• set a bit smaller --torrent.conns.perfile
• rm -rf datadir/nodes/*
• rm -rf datadir/txpool/*
• start erigon

i think you will be fine. FYI: we have --metrics, can see amount of threads in metrics.

[keithchew]

Ugh, with GOMAXPROCS=4 (giving a derived db.read.concurrency of 256), got this crash again. Have now changed to use db.read.concurrency = 64 and see how it goes. torrent.conns.perfile is set to 4, will keep that the same for now. I believe one way to simulate this crash is to throttle the inbound/outbound network bandwidth for the node, I will give that a go as well to see if I can consistently reproduce the behavior.

[keithchew]

Hi @AskAlexSharov

Interesting, doing a thread count with ps -o nlwp <pid>, I can see that it starts up good with 75 threads. But a day later it is at 527. I will keep monitoring, but are there any other diagnostics tools/command I can use to help narrow down the issue?

[AskAlexSharov]

you can add --pprof and show:

curl -s -v http://localhost:6060/debug/pprof/goroutine?debug=1 > goroutine.txt

go tool pprof -png http://127.0.0.1:6060/debug/pprof/profile/?seconds\=20 > cpu.png

go tool pprof -alloc_objects -png http://127.0.0.1:6060/debug/pprof/heap?seconds\=20 > mem.png

[keithchew]

Hi @AskAlexSharov

I am still getting this error even with reduced db.read.concurrency.

I am attaching the full stack trace, hopefully there is something there which can help find the root cause. I can see a majority of concurrent threads are from p2p torrent calls. I do have --maxpeers=30 but perhaps there is something else unbounded in this section of the code?

erigon.zip

[AskAlexSharov]

do rm -rf datadir/nodes rm -rf datadir/txpool
here is the fix: #13218