Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
qiulaidongfeng opened this issue Oct 21, 2023 · 8 comments
Open

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

qiulaidongfeng opened this issue Oct 21, 2023 · 8 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@qiulaidongfeng
Copy link
Contributor

qiulaidongfeng commented Oct 21, 2023 •
edited

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
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Oct 21, 2023
@bcmills
Copy link
Contributor

bcmills commented Oct 23, 2023

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?

@bcmills bcmills added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Oct 23, 2023
@qiulaidongfeng
Copy link
Contributor Author

qiulaidongfeng commented Oct 25, 2023 •
edited

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.

@bcmills bcmills removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Oct 25, 2023
@rhysh
Copy link
Contributor

rhysh commented Oct 25, 2023

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
Copy link
Contributor Author

@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 cherrymui changed the title runtime/pprof: TestCPUProfileMultithreadMagnitude fail in linux6.2 ubuntu runtime/pprof: TestCPUProfileMultithreadMagnitude fail in linux6.2 ubuntu in VirtualBox Oct 30, 2023
@cherrymui
Copy link
Member

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

@cherrymui cherrymui added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Oct 30, 2023
@qiulaidongfeng
Copy link
Contributor Author

qiulaidongfeng commented Oct 31, 2023 via email •
edited

@qiulaidongfeng
Copy link
Contributor Author

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?

@seankhliao seankhliao added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Jan 28, 2024
@qiulaidongfeng
Copy link
Contributor Author 

└─$ 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
Go Compiler / Runtime
Status: No status
Milestone
No milestone
Development

No branches or pull requests
6 participants
@rhysh @bcmills @gopherbot @seankhliao @cherrymui @qiulaidongfeng