runtime: read scheduled on a different thread than a locked and associated with network namespace

difrost commented 4 years ago

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

Tested on 3 versions:

$ go version
go version go1.11.13 linux/amd64

$ go version
go version go1.12.9 linux/amd64

$ go version
go version go1.13 linux/amd64

Does this issue reproduce with the latest release?

Not tested with 1.13.1

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

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/root/go"
GOPROXY=""
GORACE=""
GOROOT="/root/golang/1.12.9"
GOTMPDIR=""
GOTOOLDIR="/root/golang/1.12.9/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/mnt/git/github/netns-go-proof/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build717114236=/tmp/go-build -gno-record-gcc-switches"

What did you do?

While working on a tool that resolves socket IDs of processes running inside Docker container I've found that reading data from procfs when a locked thread is associated with process network namespace is not deterministic. Sometimes it was reading correct data but quite ofter it was reading data from host namespace.

With following code I was able to reproduce this issue on RHEL 7.2 - 7.6: https://github.com/difrost/netns-go-proof

Steps to reproduce using proof code:

Find a container with a process that opens a bunch of network connections:

$ docker ps --format "{{.ID}} {{.Ports}} {{.Names}}"
96cc2a87e368 0.0.0.0:1358->1358/tcp cranky_sutherland
b78274b8892f 0.0.0.0:80->80/tcp, 0.0.0.0:443->443/tcp rancher

Get the processes running in b78274b8892f:

$ docker top b78274b8892f -o pid,cmd
PID                 CMD
29724               tini -- rancher --http-listen-port=80 --https-listen-port=443 --audit-log-path=/var/log/auditlog/rancher-api-audit.log --audit-level=0 --audit-log-maxage=10 --audit-log-maxbackup=10 --audit-log-maxsize=100
29763               rancher --http-listen-port=80 --https-listen-port=443 --audit-log-path=/var/log/auditlog/rancher-api-audit.log --audit-level=0 --audit-log-maxage=10 --audit-log-maxbackup=10 --audit-log-maxsize=100

Use nsenter from util-linux package to count lines in /proc/net/tcp:
```
$ sudo nsenter -n -t 29763 cat /proc/net/tcp |wc -l
797
```

Run proof code on 29763:

$ sudo ./NetNSBug -pid 29763
INFO[0000] Analysing 29763 in TID: 28877 PID: 28877
INFO[0000] We are in TID: 28877
INFO[0000] Got data for 29763:
INFO[0000] Got 0 lines loaded for UDP6
INFO[0000] Got 796 lines loaded for TCP
INFO[0000] Got 0 lines loaded for UDP
INFO[0000] Got 30 lines loaded for TCP6
INFO[0000] Namespace for 29763: net:[4026532507]
INFO[0000] Namespace for tid 28877: net:[4026532507]

For reference host namespace TCP:
```
$ cat /proc/net/tcp | wc -l
5
```

Run proof code again but this time force execution on a thread other than main one. This is done by calling dummy goroutine and granting it a bit of juice with runtime.Gosched.

$ sudo ./NetNSBug -pid 29763 -f
INFO[0000] Analysing 29763 in TID: 29224 PID: 29224
INFO[0000] Forcing schedule on a proper thread.
INFO[0000] We are in TID: 29226
INFO[0000] Got data for 29763:
INFO[0000] Got 6 lines loaded for UDP6
INFO[0000] Got 4 lines loaded for TCP
INFO[0000] Got 4 lines loaded for UDP
INFO[0000] Got 4 lines loaded for TCP6
INFO[0000] Namespace for 29763: net:[4026532507]
INFO[0000] Namespace for tid 29226: net:[4026532507]

What did you expect to see?

Correct data read from procfs while associated with a network namespace.

What did you see instead?

Data from host namespace.

difrost commented 4 years ago

Below is the schedtrace both for good and a bad read - I can't find anything that would help to spot the root cause: Good

SCHED 1ms: gomaxprocs=2 idleprocs=1 threads=6 spinningthreads=0 idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=1 syscalltick=18 m=-1 runqsize=0 gfreecnt=0
  P1: status=0 schedtick=2 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=-1 curg=5 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=5
  G1: status=4(semacquire) m=-1 lockedm=-1
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G4: status=4(finalizer wait) m=-1 lockedm=-1
  G5: status=3() m=0 lockedm=0 // performing syscall, Thread M0 (Processor P0?)
SCHED 2ms: gomaxprocs=2 idleprocs=1 threads=6 spinningthreads=0 idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=1 syscalltick=30 m=-1 runqsize=0 gfreecnt=0
  P1: status=0 schedtick=2 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=-1 curg=5 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=5
  G1: status=4(semacquire) m=-1 lockedm=-1
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G4: status=4(finalizer wait) m=-1 lockedm=-1
  G5: status=3() m=0 lockedm=0 // performing syscall, Thread M0 (Processor P0?)
SCHED 3ms: gomaxprocs=2 idleprocs=1 threads=6 spinningthreads=0 idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=1 syscalltick=41 m=-1 runqsize=0 gfreecnt=0
  P1: status=0 schedtick=2 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=-1 curg=5 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=5
  G1: status=4(semacquire) m=-1 lockedm=-1
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G4: status=4(finalizer wait) m=-1 lockedm=-1
  G5: status=2() m=0 lockedm=0 // running, Thread M0 (Processor P0?)
SCHED 4ms: gomaxprocs=2 idleprocs=1 threads=6 spinningthreads=0 idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=1 syscalltick=47 m=0 runqsize=0 gfreecnt=0
  P1: status=0 schedtick=2 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=0 curg=5 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=5
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G4: status=4(finalizer wait) m=-1 lockedm=-1
  G5: status=2() m=0 lockedm=0 // running, Thread M0 (Processor P0?)

Bad

SCHED 1ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=2 syscalltick=1 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 2ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=15 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 3ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=16 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 4ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=17 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 5ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=18 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 6ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=19 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 7ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=20 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 8ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=26 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 9ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=37 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 10ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=2 schedtick=3 syscalltick=46 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 11ms: gomaxprocs=2 idleprocs=1 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=0 schedtick=3 syscalltick=49 m=-1 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=-1 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=3() m=4 lockedm=4  // performing syscall, Thread M4 (Processor 0?) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);
SCHED 12ms: gomaxprocs=2 idleprocs=0 threads=6 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=3 syscalltick=50 m=4 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=3 syscalltick=7 m=0 runqsize=0 gfreecnt=0
  M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M4: p=0 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=19
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=1 curg=20 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1 // wg.Wait
  G17: status=6() m=1 lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G18: status=4(finalizer wait) m=-1 lockedm=-1
  G19: status=2() m=4 lockedm=4  // running, Thread M4 (Processor 0) - locked to M4
  G20: status=2() m=0 lockedm=-1 // running dummy goroutine, Thread M0 (Processor 1);

bcmills commented 4 years ago

CC @aclements

golang / go