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

[qiulaidongfeng]

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]

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]

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]

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? #18856 (comment)

---

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]

@rhysh After attempting #18856 (comment), 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]

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

[qiulaidongfeng]

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

[qiulaidongfeng]

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?