go threads aren't being re-used

[eyberg]

so I just checked this out and I think we need to figure out what go's expectation is here

• go has a default 10k thread limit and never recycles them

https://golang.org/pkg/runtime/debug/#SetMaxThreads
golang/go#14592

however. these threads should be re-used and it looks like when using curl it issues a thread per request and then exhausts itself - so we need to figure out how to get go to re-use them

[eyberg]

#451 (comment)

[eyberg]

ok - so i was able to replicate what I was guessing what was going wrong -->

eyberg@s1:~/gz$ ops run -p8083 -c config.json gz
Finding dependent shared libs
booting image ...
warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
assigned: 10.0.2.15
SCHED 0ms: gomaxprocs=1 idleprocs=0 threads=4 spinningthreads=0 idlethreads=1 runqueue=0 [1]
SCHED 1007ms: gomaxprocs=1 idleprocs=1 threads=5 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 2017ms: gomaxprocs=1 idleprocs=1 threads=5 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 3027ms: gomaxprocs=1 idleprocs=1 threads=5 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 4028ms: gomaxprocs=1 idleprocs=1 threads=5 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 5548ms: gomaxprocs=1 idleprocs=1 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 6564ms: gomaxprocs=1 idleprocs=1 threads=53 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 7565ms: gomaxprocs=1 idleprocs=0 threads=96 spinningthreads=0 idlethreads=0 runqueue=0 [0]
SCHED 8567ms: gomaxprocs=1 idleprocs=1 threads=138 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 9567ms: gomaxprocs=1 idleprocs=1 threads=180 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 10583ms: gomaxprocs=1 idleprocs=1 threads=222 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 11633ms: gomaxprocs=1 idleprocs=1 threads=239 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 12652ms: gomaxprocs=1 idleprocs=1 threads=280 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 13658ms: gomaxprocs=1 idleprocs=1 threads=305 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 14666ms: gomaxprocs=1 idleprocs=1 threads=305 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 15667ms: gomaxprocs=1 idleprocs=1 threads=305 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 16669ms: gomaxprocs=1 idleprocs=1 threads=329 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 17670ms: gomaxprocs=1 idleprocs=1 threads=369 spinningthreads=0 idlethreads=1 runqueue=0 [0]
SCHED 18679ms: gomaxprocs=1 idleprocs=1 threads=409 spinningthreads=0 idlethreads=1 runqueue=0 [0]
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
mmap error: failed to allocate physical memory, size 2101248
runtime/cgo: pthread_create failed: Resource temporarily unavailable
qemu-system-x86_64: terminating on signal 2

for some reason - go never re-uses one of the threads that it initially allocated for curl...

eyberg@s1:~/gz$ cat config.json
{
  "Env": {"GODEBUG": "schedtrace=1000"},
  "Dirs": ["stuff"]
}

eyberg@s1:~/gz$ cat b.sh
#!/bin/bash
for i in `seq 1 300`;
do
  curl -XGET http://127.0.0.1:8083/
done

even after 1200 requests on linux we still only have 12 threads ->

eyberg@s1:~/gz$ GODEBUG=schedtrace=1000 ./gz
SCHED 0ms: gomaxprocs=24 idleprocs=21 threads=6 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 1006ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 2010ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 3015ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 4019ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 5024ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 6029ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 7032ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 8035ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 9040ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 10042ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 11042ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 12045ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 13050ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 14055ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 15059ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 16064ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 17069ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 18074ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 19080ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 20085ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 21088ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 22090ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 23091ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 24096ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 25099ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 26101ms: gomaxprocs=24 idleprocs=24 threads=7 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 27103ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 28107ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 29112ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 30117ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 31122ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 32127ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 33132ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 34137ms: gomaxprocs=24 idleprocs=24 threads=12 spinningthreads=0 idlethreads=8 runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]

this also explains the huge difference we see with apache bench - where you can slap it with traffic and it doesn't spawn a ton of threads ->

$ ab -c 10 -n 100 http://127.0.0.1:8083/

SCHED 14068ms: gomaxprocs=1 idleprocs=1 threads=5 spinningthreads=0 idlethreads=1 runqueue=0 [0]

[tijoytom-zz]

If you look at the call stack of blocked M( go created OS threads), almost 90% of them are blocked in read system call. Go parks Ms when entering a blocking system call and since there are no available M(s) to service new requests it will spawn new OS threads(M). So the real problem is that read syscall call is slow under contention and it's blocked.Not that blocked threads do not count against gomaxprocs, it's number of simultaneously executing threads.

[wjhun]

Thanks Tijoy. It's probably something messed up with connection close and freeing up blockq waiters. I'll take a look.

[eyberg]

verified https://github.com/nanovms/nanos/pull/459/files this fixes this && #403

[wjhun]

resolved in #459