golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
123.86k stars 17.65k forks source link

runtime/pprof: TestCPUProfileMultithreadMagnitude fail in linux6.2 ubuntu in VirtualBox #63650

Open qiulaidongfeng opened 1 year ago

qiulaidongfeng commented 1 year ago

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

$ go version
tip

Does this issue reproduce with the latest release?

yes.

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

go env Output
$ go env
GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/gocache'
GOENV='/home/qiulaidongfeng/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/gofile/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/gofile'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/home/qiulaidongfeng/.go/current'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/home/qiulaidongfeng/.go/current/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.21.3'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='0'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -fno-caret-diagnostics -Qunused-arguments -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build3509559278=/tmp/go-build -gno-record-gcc-switches'

What did you do?

In virtualbox

The physical machine is a GOOS=amd64 machine, and the virtual machine is also a GOOS=amd64 machine, both with 16 threads.

Virtual machine 4.5GB memory.

go test runtime/pprof

What did you expect to see?

Test passed.

What did you see instead?

--- FAIL: TestCPUProfileMultithreadMagnitude (322.67s) pprof_test.go:120: Running on Linux 6.2 --- FAIL: TestCPUProfileMultithreadMagnitude/parallel (317.55s) pprof_test.go:186: Running with 16 workers pprof_test.go:557: total 2064 CPU profile samples collected: 1547: 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 155: 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 241: 0x46c700 (runtime.asyncPreempt:8) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 23: 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46d083 (runtime.futex:558) 0x433a0f (runtime.futexwakeup:82) 0x40c124 (runtime.notewakeup:145) 0x43e088 (runtime.startm:2635) 0x43e56b (runtime.wakep:2746) 0x44025d (runtime.resetspinning:3473) 0x44068e (runtime.schedule:3607) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x414353 (runtime.findObject:344) 0x4200cb (runtime.scanobject:1365) 0x41f999 (runtime.gcDrain:1133) 0x41c2b4 (runtime.gcDrainMarkWorkerDedicated:1027 runtime.gcBgMarkWorker.func2:1391) 0x469449 (runtime.systemstack:509) 0x41be91 (runtime.gcBgMarkWorker:1363) labels: map[] 23: 0x46c700 (runtime.asyncPreempt:8) 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 40: 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 6: 0x46c700 (runtime.asyncPreempt:8) 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 17: 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x46c700 (runtime.asyncPreempt:8) 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x458a0c (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x47fb44 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x46c700 (runtime.asyncPreempt:8) 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x44083b (runtime.checkTimers:3670) 0x43ebb3 (runtime.findRunnable:2898) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x440ea4 (runtime.gopreempt_m:3795) 0x4693cd (runtime.mcall:458) labels: map[] pprof_test.go:628: found 2057 samples in expected function runtime/pprof.cpuHog1 pprof_test.go:214: compare 1m13.387525s user + 5.416163s system = 1m18.803688s vs 20.64s pprof_test.go:216: compare got CPU usage reports are too different (limit -10.0%, got -73.8%) want nil pprof_test.go:494: retrying with 10s duration pprof_test.go:557: total 3577 CPU profile samples collected: 79: 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2591: 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 257: 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 486: 0x46c700 (runtime.asyncPreempt:8) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 17: 0x46c700 (runtime.asyncPreempt:8) 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 7: 0x46c700 (runtime.asyncPreempt:8) 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 57: 0x46c700 (runtime.asyncPreempt:8) 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46afa9 (runtime.procyield:780) 0x40bf2c (runtime.lock2:88) 0x440bca (runtime.lockWithRank:24 runtime.lock:48 runtime.goschedImpl:3763) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x46cb56 (runtime.tgkill:177) 0x434746 (runtime.signalM:559) 0x445659 (runtime.preemptM:385 runtime.preemptone:5804) 0x4455ae (runtime.preemptall:5766) 0x43ce24 (runtime.forEachP:1824) 0x463fe4 (runtime.gcMarkDone.func1:834) 0x469449 (runtime.systemstack:509) 0x41ab9e (runtime.gcMarkDone:827) 0x41bfe4 (runtime.gcBgMarkWorker:1435) labels: map[] 1: 0x451d70 (runtime.gcComputeStartingStackSize:1321) 0x41acbe (runtime.gcMarkDone:907) 0x41bfe4 (runtime.gcBgMarkWorker:1435) labels: map[] 4: 0x46d057 (runtime.madvise:544) 0x4171f5 (runtime.sysUnusedOS:63) 0x4235ee (runtime.sysUnused:62 runtime.(*pageAlloc).scavengeOne:780) 0x4231ae (runtime.(*pageAlloc).scavenge.func1:683) 0x469449 (runtime.systemstack:509) 0x423104 (runtime.(*pageAlloc).scavenge:682) 0x463c87 (runtime.(*scavengerState).init.func2:395) 0x422e6f (runtime.(*scavengerState).run:602) 0x422fe7 (runtime.bgscavenge:656) labels: map[] 39: 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 25: 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 4: 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x46c700 (runtime.asyncPreempt:8) 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x458a0c (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x55a32a (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x458a01 (runtime.nanotime:18) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x47fb44 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] pprof_test.go:628: found 3564 samples in expected function runtime/pprof.cpuHog1 pprof_test.go:214: compare 2m20.54274s user + 17.627246s system = 2m38.169986s vs 35.77s pprof_test.go:216: compare got CPU usage reports are too different (limit -10.0%, got -77.4%) want nil pprof_test.go:494: retrying with 20s duration pprof_test.go:557: total 7173 CPU profile samples collected: 5278: 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46cb56 (runtime.tgkill:177) 0x434746 (runtime.signalM:559) 0x445659 (runtime.preemptM:385 runtime.preemptone:5804) 0x4455ae (runtime.preemptall:5766) 0x43c349 (runtime.stopTheWorldWithSema:1369) 0x464157 (runtime.gcStart.func1:681) 0x469449 (runtime.systemstack:509) 0x41a744 (runtime.gcStart:681) 0x40dbd6 (runtime.mallocgc:1240) 0x40de04 (runtime.newobject:1322) 0x52468d (compress/gzip.NewWriterLevel:64) 0x550905 (runtime/pprof.newProfileBuilder:260) 0x54d264 (runtime/pprof.profileWriter:806) labels: map[] 922: 0x46c700 (runtime.asyncPreempt:8) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x427004 (runtime.getempty:352) 0x42472f (runtime.(*stackScanState).putPtr:213) 0x420304 (runtime.scanConservative:1447) 0x41f6dd (runtime.scanframeworker:941) 0x41f086 (runtime.scanstack:803) 0x41df14 (runtime.markroot.func1:240) 0x41dba7 (runtime.markroot:214) 0x41fb5c (runtime.gcDrain:1099) 0x41c204 (runtime.gcDrainMarkWorkerDedicated:1027 runtime.gcBgMarkWorker.func2:1376) 0x469449 (runtime.systemstack:509) 0x41be91 (runtime.gcBgMarkWorker:1363) labels: map[] 4: 0x46d057 (runtime.madvise:544) 0x4171f5 (runtime.sysUnusedOS:63) 0x4235ee (runtime.sysUnused:62 runtime.(*pageAlloc).scavengeOne:780) 0x4231ae (runtime.(*pageAlloc).scavenge.func1:683) 0x469449 (runtime.systemstack:509) 0x423104 (runtime.(*pageAlloc).scavenge:682) 0x463c87 (runtime.(*scavengerState).init.func2:395) 0x422e6f (runtime.(*scavengerState).run:602) 0x422fe7 (runtime.bgscavenge:656) labels: map[] 1: 0x46cb56 (runtime.tgkill:177) 0x434746 (runtime.signalM:559) 0x445659 (runtime.preemptM:385 runtime.preemptone:5804) 0x4455ae (runtime.preemptall:5766) 0x43cce4 (runtime.forEachP:1778) 0x463fe4 (runtime.gcMarkDone.func1:834) 0x469449 (runtime.systemstack:509) 0x41ab9e (runtime.gcMarkDone:827) 0x41bfe4 (runtime.gcBgMarkWorker:1435) labels: map[] 90: 0x46c700 (runtime.asyncPreempt:8) 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 538: 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 156: 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 32: 0x46c700 (runtime.asyncPreempt:8) 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 50: 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 62: 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 7: 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x4510e3 (runtime.newstack:1044) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 6: 0x46c700 (runtime.asyncPreempt:8) 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 9: 0x46c700 (runtime.asyncPreempt:8) 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x440ea4 (runtime.gopreempt_m:3795) 0x45116a (runtime.newstack:1070) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x46d081 (runtime.futex:557) 0x43394f (runtime.futexsleep:69) 0x40c226 (runtime.notesleep:160) 0x43ddcb (runtime.mPark:1633 runtime.stopm:2522) 0x43f6bb (runtime.findRunnable:3235) 0x440630 (runtime.schedule:3589) 0x44152d (runtime.goexit0:3932) 0x4693cd (runtime.mcall:458) labels: map[] 4: 0x458a0c (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46cc16 (runtime.nanotime1:239) labels: map[] 1: 0x469545 (runtime.morestack_noctxt:600) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x440eb5 (runtime.gopreempt_m:3796) 0x45116a (runtime.newstack:1070) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x446664 (runtime.pidlegetSpinning:6165) 0x43e4e4 (runtime.wakep:2731) 0x440c29 (runtime.goschedImpl:3768) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x411a94 (runtime.mapaccess1_fast64:29) 0x548a8f (runtime/pprof.(*profMap).lookup:41) 0x550c07 (runtime/pprof.(*profileBuilder).addCPUData:338) 0x54d2c4 (runtime/pprof.profileWriter:811) labels: map[] 1: 0x46c700 (runtime.asyncPreempt:8) 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43ea0b (runtime.execute:2836) 0x4407bb (runtime.schedule:3639) 0x44152d (runtime.goexit0:3932) 0x4693cd (runtime.mcall:458) labels: map[] pprof_test.go:628: found 7151 samples in expected function runtime/pprof.cpuHog1 pprof_test.go:214: compare 4m41.461315s user + 35.227014s system = 5m16.688329s vs 1m11.73s pprof_test.go:216: compare got CPU usage reports are too different (limit -10.0%, got -77.3%) want nil pprof_test.go:494: retrying with 40s duration pprof_test.go:557: total 13951 CPU profile samples collected: 10248: 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1787: 0x46c700 (runtime.asyncPreempt:8) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 107: 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x46d057 (runtime.madvise:544) 0x4171f5 (runtime.sysUnusedOS:63) 0x4235ee (runtime.sysUnused:62 runtime.(*pageAlloc).scavengeOne:780) 0x4231ae (runtime.(*pageAlloc).scavenge.func1:683) 0x469449 (runtime.systemstack:509) 0x423104 (runtime.(*pageAlloc).scavenge:682) 0x463c87 (runtime.(*scavengerState).init.func2:395) 0x422e6f (runtime.(*scavengerState).run:602) 0x422fe7 (runtime.bgscavenge:656) labels: map[] 1063: 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 197: 0x46c700 (runtime.asyncPreempt:8) 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 14: 0x46c700 (runtime.asyncPreempt:8) 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46cb56 (runtime.tgkill:177) 0x434746 (runtime.signalM:559) 0x445659 (runtime.preemptM:385 runtime.preemptone:5804) 0x4455ae (runtime.preemptall:5766) 0x43c349 (runtime.stopTheWorldWithSema:1369) 0x4640b7 (runtime.gcMarkDone.func2:872) 0x469449 (runtime.systemstack:509) 0x41ac39 (runtime.gcMarkDone:872) 0x41bfe4 (runtime.gcBgMarkWorker:1435) labels: map[] 51: 0x46c700 (runtime.asyncPreempt:8) 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 320: 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x40beb7 (runtime.lock2:61) 0x440bca (runtime.lockWithRank:24 runtime.lock:48 runtime.goschedImpl:3763) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 96: 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 19: 0x46c700 (runtime.asyncPreempt:8) 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x46d081 (runtime.futex:557) 0x43394f (runtime.futexsleep:69) 0x40c226 (runtime.notesleep:160) 0x43ddcb (runtime.mPark:1633 runtime.stopm:2522) 0x43f6bb (runtime.findRunnable:3235) 0x440630 (runtime.schedule:3589) 0x44152d (runtime.goexit0:3932) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x438714 (runtime.asyncPreempt2:307) 0x46c7da (runtime.asyncPreempt:53) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 6: 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43eb9a (runtime.findRunnable:2890) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 3: 0x47fb44 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 3: 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 8: 0x458a0c (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 3: 0x55a32a (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 4: 0x46c700 (runtime.asyncPreempt:8) 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46c700 (runtime.asyncPreempt:8) 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x44083b (runtime.checkTimers:3670) 0x43ebb3 (runtime.findRunnable:2898) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x447eed (runtime.(*profBuf).read:512) 0x4656ca (runtime/pprof.readProfile:234) 0x54d28e (runtime/pprof.profileWriter:810) labels: map[] 4: 0x46cc16 (runtime.nanotime1:239) labels: map[] 1: 0x46cc00 (runtime.nanotime1:223) labels: map[] 1: 0x46cc2f (runtime.nanotime1:245) labels: map[] 1: 0x40c0a7 (runtime.unlock2:129) 0x440c1b (runtime.unlockWithRank:34 runtime.unlock:112 runtime.goschedImpl:3765) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x446664 (runtime.pidlegetSpinning:6165) 0x43e4e4 (runtime.wakep:2731) 0x440c29 (runtime.goschedImpl:3768) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x450da8 (runtime.newstack:962) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46c7da (runtime.asyncPreempt:53) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x4510e3 (runtime.newstack:1044) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] pprof_test.go:628: found 13911 samples in expected function runtime/pprof.cpuHog1 pprof_test.go:214: compare 9m11.324968s user + 1m19.955264s system = 10m31.280232s vs 2m19.51s pprof_test.go:216: compare got CPU usage reports are too different (limit -10.0%, got -77.9%) want nil pprof_test.go:494: retrying with 1m20s duration pprof_test.go:557: total 27686 CPU profile samples collected: 20666: 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 3376: 0x46c700 (runtime.asyncPreempt:8) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46d083 (runtime.futex:558) 0x43394f (runtime.futexsleep:69) 0x40c226 (runtime.notesleep:160) 0x43ddcb (runtime.mPark:1633 runtime.stopm:2522) 0x43f6bb (runtime.findRunnable:3235) 0x440630 (runtime.schedule:3589) 0x44152d (runtime.goexit0:3932) 0x4693cd (runtime.mcall:458) labels: map[] 332: 0x46c700 (runtime.asyncPreempt:8) 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2114: 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46cb56 (runtime.tgkill:177) 0x434746 (runtime.signalM:559) 0x445659 (runtime.preemptM:385 runtime.preemptone:5804) 0x4455ae (runtime.preemptall:5766) 0x43ce24 (runtime.forEachP:1824) 0x463fe4 (runtime.gcMarkDone.func1:834) 0x469449 (runtime.systemstack:509) 0x41ab9e (runtime.gcMarkDone:827) 0x41bfe4 (runtime.gcBgMarkWorker:1435) labels: map[] 110: 0x46c700 (runtime.asyncPreempt:8) 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 570: 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 9: 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 23: 0x46c700 (runtime.asyncPreempt:8) 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 198: 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 37: 0x46c700 (runtime.asyncPreempt:8) 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 182: 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 6: 0x46c700 (runtime.asyncPreempt:8) 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 3: 0x4510e3 (runtime.newstack:1044) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x438714 (runtime.asyncPreempt2:307) 0x46c7da (runtime.asyncPreempt:53) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 5: 0x46d081 (runtime.futex:557) 0x43394f (runtime.futexsleep:69) 0x40c226 (runtime.notesleep:160) 0x43ddcb (runtime.mPark:1633 runtime.stopm:2522) 0x43f6bb (runtime.findRunnable:3235) 0x440630 (runtime.schedule:3589) 0x44152d (runtime.goexit0:3932) 0x4693cd (runtime.mcall:458) labels: map[] 5: 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x40c0a7 (runtime.unlock2:129) 0x440c1b (runtime.unlockWithRank:34 runtime.unlock:112 runtime.goschedImpl:3765) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 13: 0x458a0c (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x447fbc (runtime.(*profBuf).read:536) 0x4656ca (runtime/pprof.readProfile:234) 0x54d28e (runtime/pprof.profileWriter:810) labels: map[] 1: 0x55a3c4 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x55a334 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x446664 (runtime.pidlegetSpinning:6165) 0x43e4e4 (runtime.wakep:2731) 0x440c29 (runtime.goschedImpl:3768) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x411b58 (runtime.mapaccess1_fast64:45) 0x548a8f (runtime/pprof.(*profMap).lookup:41) 0x550c07 (runtime/pprof.(*profileBuilder).addCPUData:338) 0x54d2c4 (runtime/pprof.profileWriter:811) labels: map[] 1: 0x458a1e (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x440ab2 (runtime.park_m:3741) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x55a32a (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43bae1 (runtime.casgstatus:1045) 0x440b9b (runtime.goschedImpl:3761) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x46c700 (runtime.asyncPreempt:8) 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43ea0b (runtime.execute:2836) 0x4407bb (runtime.schedule:3639) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x458a1a (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x469545 (runtime.morestack_noctxt:600) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 7: 0x47fb44 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x446186 (runtime.globrunqget:6024) 0x43edd3 (runtime.findRunnable:2949) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x43bb70 (runtime.casgstatus:1062) 0x440b9b (runtime.goschedImpl:3761) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x46b1e7 (runtime.memhash64:1560) 0x411aa3 (runtime.mapaccess1_fast64:29) 0x548a8f (runtime/pprof.(*profMap).lookup:41) 0x550c07 (runtime/pprof.(*profileBuilder).addCPUData:338) 0x54d2c4 (runtime/pprof.profileWriter:811) labels: map[] 1: 0x450ea6 (runtime.newstack:1023) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43ebb9 (runtime.findRunnable:2898) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x440b6b (runtime.goschedImpl:3755) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 2: 0x46cc16 (runtime.nanotime1:239) labels: map[] 1: 0x43eb9a (runtime.findRunnable:2890) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x46d081 (runtime.futex:557) 0x43394f (runtime.futexsleep:69) 0x40c226 (runtime.notesleep:160) 0x43ddcb (runtime.mPark:1633 runtime.stopm:2522) 0x43f6bb (runtime.findRunnable:3235) 0x440630 (runtime.schedule:3589) 0x440b3e (runtime.park_m:3752) 0x4693cd (runtime.mcall:458) labels: map[] pprof_test.go:628: found 27625 samples in expected function runtime/pprof.cpuHog1 pprof_test.go:214: compare 18m32.427318s user + 2m33.162633s system = 21m5.589951s vs 4m36.86s pprof_test.go:216: compare got CPU usage reports are too different (limit -10.0%, got -78.1%) want nil pprof_test.go:494: retrying with 2m40s duration pprof_test.go:557: total 55652 CPU profile samples collected: 1: 0x414336 (runtime.spanOf:705 runtime.findObject:340) 0x4200cb (runtime.scanobject:1365) 0x41f999 (runtime.gcDrain:1133) 0x41c204 (runtime.gcDrainMarkWorkerDedicated:1027 runtime.gcBgMarkWorker.func2:1376) 0x469449 (runtime.systemstack:509) 0x41be91 (runtime.gcBgMarkWorker:1363) labels: map[] 41102: 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 7223: 0x46c700 (runtime.asyncPreempt:8) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x423e67 (runtime.(*scavengeIndex).find:1089) 0x4230a4 (runtime.(*pageAlloc).scavenge:678) 0x463c87 (runtime.(*scavengerState).init.func2:395) 0x422e6f (runtime.(*scavengerState).run:602) 0x422fe7 (runtime.bgscavenge:656) labels: map[] 1: 0x46cb56 (runtime.tgkill:177) 0x434746 (runtime.signalM:559) 0x445659 (runtime.preemptM:385 runtime.preemptone:5804) 0x4455ae (runtime.preemptall:5766) 0x43cce4 (runtime.forEachP:1778) 0x463fe4 (runtime.gcMarkDone.func1:834) 0x469449 (runtime.systemstack:509) 0x41ab9e (runtime.gcMarkDone:827) 0x41e686 (runtime.gcAssistAlloc:484) 0x40dd13 (runtime.deductAssistCredit:1285) 0x40d528 (runtime.mallocgc:1000) 0x40de04 (runtime.newobject:1322) 0x55092a (runtime/pprof.newProfileBuilder:261) 0x54d264 (runtime/pprof.profileWriter:806) labels: map[] 13: 0x46d081 (runtime.futex:557) 0x43394f (runtime.futexsleep:69) 0x40c226 (runtime.notesleep:160) 0x43ddcb (runtime.mPark:1633 runtime.stopm:2522) 0x43f6bb (runtime.findRunnable:3235) 0x440630 (runtime.schedule:3589) 0x44152d (runtime.goexit0:3932) 0x4693cd (runtime.mcall:458) labels: map[] 2: 0x46d083 (runtime.futex:558) 0x433a0f (runtime.futexwakeup:82) 0x40c124 (runtime.notewakeup:145) 0x43e088 (runtime.startm:2635) 0x43e56b (runtime.wakep:2746) 0x44025d (runtime.resetspinning:3473) 0x44068e (runtime.schedule:3607) 0x44152d (runtime.goexit0:3932) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x46cb56 (runtime.tgkill:177) 0x434746 (runtime.signalM:559) 0x445659 (runtime.preemptM:385 runtime.preemptone:5804) 0x4455ae (runtime.preemptall:5766) 0x43ce24 (runtime.forEachP:1824) 0x463fe4 (runtime.gcMarkDone.func1:834) 0x469449 (runtime.systemstack:509) 0x41ab9e (runtime.gcMarkDone:827) 0x41e686 (runtime.gcAssistAlloc:484) 0x40dd13 (runtime.deductAssistCredit:1285) 0x40d528 (runtime.mallocgc:1000) 0x40de04 (runtime.newobject:1322) 0x55092a (runtime/pprof.newProfileBuilder:261) 0x54d264 (runtime/pprof.profileWriter:806) labels: map[] 1174: 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 235: 0x46c700 (runtime.asyncPreempt:8) 0x55a3db (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 708: 0x46c700 (runtime.asyncPreempt:8) 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 18: 0x46d057 (runtime.madvise:544) 0x4171f5 (runtime.sysUnusedOS:63) 0x4235ee (runtime.sysUnused:62 runtime.(*pageAlloc).scavengeOne:780) 0x4231ae (runtime.(*pageAlloc).scavenge.func1:683) 0x469449 (runtime.systemstack:509) 0x423104 (runtime.(*pageAlloc).scavenge:682) 0x463c87 (runtime.(*scavengerState).init.func2:395) 0x422e6f (runtime.(*scavengerState).run:602) 0x422fe7 (runtime.bgscavenge:656) labels: map[] 4144: 0x55a3e3 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 13: 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 407: 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 326: 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43871e (runtime.asyncPreempt2:309) 0x46c7da (runtime.asyncPreempt:53) 0x55a3d3 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x4510e3 (runtime.newstack:1044) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 33: 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 33: 0x458a0c (runtime.nanotime:19) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 74: 0x46c700 (runtime.asyncPreempt:8) 0x55a3df (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x446664 (runtime.pidlegetSpinning:6165) 0x43e4e4 (runtime.wakep:2731) 0x440c29 (runtime.goschedImpl:3768) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 59: 0x46c700 (runtime.asyncPreempt:8) 0x55a3c7 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 8: 0x46cc16 (runtime.nanotime1:239) labels: map[] 7: 0x46c700 (runtime.asyncPreempt:8) 0x55a3ce (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 8: 0x55a32a (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46cc00 (runtime.nanotime1:223) labels: map[] 3: 0x55a334 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x40bee1 (runtime.lock2:62) 0x43e4dc (runtime.lockWithRank:24 runtime.lock:48 runtime.wakep:2730) 0x440c29 (runtime.goschedImpl:3768) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x46afa9 (runtime.procyield:780) 0x40bf2c (runtime.lock2:88) 0x440bca (runtime.lockWithRank:24 runtime.lock:48 runtime.goschedImpl:3763) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x450e86 (runtime.canPreemptM:287 runtime.newstack:1023) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 2: 0x44083b (runtime.checkTimers:3670) 0x43ebb3 (runtime.findRunnable:2898) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x469545 (runtime.morestack_noctxt:600) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x40a28d (runtime.(*timeHistogram).record:135) 0x43bd86 (runtime.casgstatus:1136) 0x43ea7a (runtime.execute:2847) 0x4407bb (runtime.schedule:3639) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 12: 0x47fb44 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x465680 (runtime/pprof.readProfile:226) 0x54d28e (runtime/pprof.profileWriter:810) labels: map[] 2: 0x447fbc (runtime.(*profBuf).read:536) 0x4656ca (runtime/pprof.readProfile:234) 0x54d28e (runtime/pprof.profileWriter:810) labels: map[] 1: 0x47fb63 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x40c0a7 (runtime.unlock2:129) 0x440c1b (runtime.unlockWithRank:34 runtime.unlock:112 runtime.goschedImpl:3765) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x46c700 (runtime.asyncPreempt:8) 0x55a3c2 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43ed59 (runtime.runqget:6331 runtime.findRunnable:2942) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x458a00 (runtime.nanotime:18) 0x47fb67 (time.Since:932) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x46c700 (runtime.asyncPreempt:8) 0x548e09 (runtime/pprof.(*profMap).lookup:46) 0x550c07 (runtime/pprof.(*profileBuilder).addCPUData:338) 0x54d2c4 (runtime/pprof.profileWriter:811) labels: map[] 2: 0x43f4f3 (runtime.runqget:6337 runtime.findRunnable:2942) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x450ea6 (runtime.newstack:1023) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x439f44 (runtime.gopark:383) 0x468434 (time.Sleep:195) 0x54d289 (runtime/pprof.profileWriter:809) labels: map[] 1: 0x446124 (runtime.globrunqget:6006) 0x43edd3 (runtime.findRunnable:2949) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 2: 0x46c700 (runtime.asyncPreempt:8) 0x55a32f (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 3: 0x55a3c2 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x55a32e (runtime/pprof.cpuHogger:41) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x40be84 (runtime.lock2:51) 0x440bca (runtime.lockWithRank:24 runtime.lock:48 runtime.goschedImpl:3763) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x548ab8 (runtime/pprof.(*profMap).lookup:42) 0x550c07 (runtime/pprof.(*profileBuilder).addCPUData:338) 0x54d2c4 (runtime/pprof.profileWriter:811) labels: map[] 1: 0x43e4c6 (runtime.wakep:2730) 0x440c29 (runtime.goschedImpl:3768) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x4405ff (runtime.schedule:3585) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x40beb7 (runtime.lock2:61) 0x440bca (runtime.lockWithRank:24 runtime.lock:48 runtime.goschedImpl:3763) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x43bdc7 (runtime.casgstatus:1087) 0x440b9b (runtime.goschedImpl:3761) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x46c700 (runtime.asyncPreempt:8) 0x55a334 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x44083b (runtime.checkTimers:3670) 0x43ebb3 (runtime.findRunnable:2898) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x456f24 (runtime.dodeltimer0:413) 0x458084 (runtime.runOneTimer:868) 0x457f19 (runtime.runtimer:792) 0x44093a (runtime.checkTimers:3700) 0x43ebb3 (runtime.findRunnable:2898) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x43ed59 (runtime.runqget:6331 runtime.findRunnable:2942) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x43bae1 (runtime.casgstatus:1045) 0x440b9b (runtime.goschedImpl:3761) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x440b84 (runtime.goschedImpl:3757) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x47fbe7 (time.Since:929) 0x55a365 (runtime/pprof.cpuHogger:40) 0x55bece (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:232) labels: map[] 1: 0x43eb9a (runtime.findRunnable:2890) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x4693cd (runtime.mcall:458) labels: map[] 1: 0x440872 (runtime.nanotime:19 runtime.checkTimers:3681) 0x43ebb3 (runtime.findRunnable:2898) 0x440630 (runtime.schedule:3589) 0x440c2e (runtime.goschedImpl:3771) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] 1: 0x40be84 (runtime.lock2:51) 0x43e4dc (runtime.lockWithRank:24 runtime.lock:48 runtime.wakep:2730) 0x440c29 (runtime.goschedImpl:3768) 0x440eee (runtime.gopreempt_m:3799) 0x45116a (runtime.newstack:1070) 0x46952e (runtime.morestack:593) labels: map[] pprof_test.go:628: found 55497 samples in expected function runtime/pprof.cpuHog1 pprof_test.go:214: compare 36m56.60984s user + 5m11.787409s system = 42m8.397249s vs 9m16.52s pprof_test.go:216: compare got CPU usage reports are too different (limit -10.0%, got -78.0%) want nil pprof_test.go:123: Failure of this test may indicate that your system suffers from a known Linux kernel bug fixed on newer kernels. See https://golang.org/issue/49065. FAIL FAIL runtime/pprof 381.962s
bcmills commented 1 year ago

In virtualbox

Please fill out the complete issue template, including the output from go env in the environment in which the test fails.

Please also include details about the virtualbox configuration — what kind of hardware is the physical machine running, and what kind of hardware is VirtualBox emulating?

qiulaidongfeng commented 1 year ago

In virtualbox

Please fill out the complete issue template, including the output from go env in the environment in which the test fails.

Please also include details about the virtualbox configuration — what kind of hardware is the physical machine running, and what kind of hardware is VirtualBox emulating?

Done. On my virtualbox machine, the same test for go1.21.3 also failed. The version of gotip is go version devel go1.22-eeadf0853e Sat Oct 21 12:11:22 2023+0800 Linux/amd64.

rhysh commented 1 year ago

From the first failure in the issue report:

pprof_test.go:214: compare 1m13.387525s user + 5.416163s system = 1m18.803688s vs 20.64s

The first round of the test asks NumCPU workers to each do 5 seconds of work. The view from getrusage(2) shows 1m18.8s = 78.8s of on-CPU time, which is close to 16 workers * 5 seconds per worker.

The CPU profiler saw 20.64s worth of samples, 2064 samples each representing 10ms of on-CPU time. That's close to 4 workers worth of on-CPU time, or 2.5 ms between successful SIGPROF deliveries (a bit faster than a common CONFIG_HZ setting of 250Hz / 4ms).


I'm not set up for VirtualBox, so I haven't tried to reproduce that aspect. Are there any useful hints in the last "profiling broken on VirtualBox" issue? https://github.com/golang/go/issues/18856#issuecomment-276686977


I'm not able to reproduce the issue on a remote machine running Ubuntu 22.04.3 with Linux kernel 6.2 and go1.21.3:

$ go1.21 version                                 
go version go1.21.3 darwin/arm64

$ ssh ubuntu@${addr} 'uname -a'                                                         
Linux ip-172-31-18-227 6.2.0-1012-aws #12~22.04.1-Ubuntu SMP Thu Sep  7 14:01:24 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

$ ssh ubuntu@${addr} 'cat /etc/lsb-release'
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=22.04
DISTRIB_CODENAME=jammy
DISTRIB_DESCRIPTION="Ubuntu 22.04.3 LTS"

$ GOOS=linux GOARCH=amd64 go1.21 test -o /tmp/pprof.test -c runtime/pprof

$ scp /tmp/pprof.test ubuntu@${addr}:.                                   
pprof.test                                                                                                                                                                        100% 4513KB   1.6MB/s   00:02

$ ssh ubuntu@${addr} './pprof.test -test.run=TestCPUProfileMultithreadMagnitude -test.v'
=== RUN   TestCPUProfileMultithreadMagnitude
    pprof_test.go:121: Running on Linux 6.2
=== RUN   TestCPUProfileMultithreadMagnitude/serial
    pprof_test.go:187: Running with 1 workers
    pprof_test.go:558: total 500 CPU profile samples collected:
        368: 0x553143 (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        129: 0x55313b (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        1: 0x4582cc (runtime.nanotime:19) 0x47f16d (time.Since:915) 0x5530c5 (runtime/pprof.cpuHogger:41) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        1: 0x55313f (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        1: 0x46c1e0 (runtime.asyncPreempt:8) 0x553143 (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

    pprof_test.go:629: found 499 samples in expected function runtime/pprof.cpuHog1
    pprof_test.go:215: compare 5.00444s user + 4.875ms system = 5.009315s vs 5s
=== RUN   TestCPUProfileMultithreadMagnitude/parallel
    pprof_test.go:187: Running with 16 workers
    pprof_test.go:558: total 7988 CPU profile samples collected:
        2975: 0x553143 (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        2381: 0x55313b (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        2581: 0x553124 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        5: 0x553127 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        32: 0x553130 (runtime/pprof.cpuHog0:62 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        6: 0x55313f (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        1: 0x40b1b7 (runtime.lock2:61) 0x440268 (runtime.lockWithRank:24 runtime.lock:48 runtime.goschedImpl:3756) 0x44058e (runtime.gopreempt_m:3788) 0x468f0d (runtime.mcall:458) labels: map[]

        1: 0x46c1e0 (runtime.asyncPreempt:8) 0x553143 (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        2: 0x46c1e0 (runtime.asyncPreempt:8) 0x553124 (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        2: 0x46c1e0 (runtime.asyncPreempt:8) 0x55313b (runtime/pprof.cpuHog0:65 runtime/pprof.cpuHog1:56) 0x55308e (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

        1: 0x46c783 (runtime.nanotime1:282) labels: map[]

        1: 0x553082 (runtime/pprof.cpuHogger:42) 0x554c8e (runtime/pprof.TestCPUProfileMultithreadMagnitude.func3.2.1.1:233) labels: map[]

    pprof_test.go:629: found 7985 samples in expected function runtime/pprof.cpuHog1
    pprof_test.go:215: compare 1m19.917177s user + 51.998ms system = 1m19.969175s vs 1m19.88s
--- PASS: TestCPUProfileMultithreadMagnitude (10.31s)
    --- PASS: TestCPUProfileMultithreadMagnitude/serial (5.11s)
    --- PASS: TestCPUProfileMultithreadMagnitude/parallel (5.20s)
PASS
qiulaidongfeng commented 1 year ago

@rhysh After attempting https://github.com/golang/go/issues/18856#issuecomment-276686977, the test still failed.

My machine uses the command output mentioned in your comment.

$  uname -a
Linux qiulaidongfeng-VirtualBox 6.2.0-35-generic #35-Ubuntu SMP PREEMPT_DYNAMIC Tue Oct  3 13:14:56 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=23.04
DISTRIB_CODENAME=lunar
DISTRIB_DESCRIPTION="Ubuntu 23.04"
$ go version
go version go1.21.3 linux/amd64
cherrymui commented 1 year ago

@qiulaidongfeng are you able to reproduce this on a non-virtualized environment? Thanks.

qiulaidongfeng commented 1 year ago

I don't have any non virtualized Linux machines right now.

qiulaidongfeng commented 1 year ago

If necessary, I can try using the same Ubuntu image to install Windows and Ubuntu dual system testing on my own computer. Do you need to do this?

qiulaidongfeng commented 9 months ago
└─$ uname -a
Linux kali 6.6.9-amd64 #1 SMP PREEMPT_DYNAMIC Kali 6.6.9-1kali1 (2024-01-08) x86_64 GNU/Linux

└─$ go version
go version go1.21.6 linux/amd64

The CPU is 8 cores and 16 threads. The virtual machine running with virtualbox is set to have 16 processors. kail get from here: https://www.kali.org/get-kali/#kali-virtual-machines

if export GOMAXPROCS=6 ,test pass. if export GOMAXPROCS=8 ,test fail. if no set GOMAXPROCS environment variable ,test fail.