runtime/pprof: TestCPUProfileMultithreadMagnitude rusage too low

[prattmic]

2021-12-06T19:10:14-7a84066/linux-s390x-ibm

--- FAIL: TestCPUProfileMultithreadMagnitude (0.83s)
    pprof_test.go:127: Running on Linux 4.18.0
    pprof_test.go:526: total 125 CPU profile samples collected:
        5: 0x1739ec (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog1:55) 0x173939 (runtime/pprof.cpuHogger:41) 0x174ea5 (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.1:176) 0x18893d (runtime/pprof.diffCPUTimeRUsage:27) 0x17614b (runtime/pprof.diffCPUTime:485) 0x174a9b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2:174) 0x175f2b (runtime/pprof.testCPUProfile:453) 0x174537 (runtime/pprof.TestCPUProfileMultithreadMagnitude:173) 0xf6661 (testing.tRunner:1410) labels: map[]
        
        2: 0x84c00 (runtime.asyncPreempt:7) 0x1739eb (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog1:55) 0x173939 (runtime/pprof.cpuHogger:41) 0x174ea5 (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.1:176) 0x18893d (runtime/pprof.diffCPUTimeRUsage:27) 0x17614b (runtime/pprof.diffCPUTime:485) 0x174a9b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2:174) 0x175f2b (runtime/pprof.testCPUProfile:453) 0x174537 (runtime/pprof.TestCPUProfileMultithreadMagnitude:173) 0xf6661 (testing.tRunner:1410) labels: map[]
        
        4: 0x1739fa (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog1:55) 0x173939 (runtime/pprof.cpuHogger:41) 0x174ea5 (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.1:176) 0x18893d (runtime/pprof.diffCPUTimeRUsage:27) 0x17614b (runtime/pprof.diffCPUTime:485) 0x174a9b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2:174) 0x175f2b (runtime/pprof.testCPUProfile:453) 0x174537 (runtime/pprof.TestCPUProfileMultithreadMagnitude:173) 0xf6661 (testing.tRunner:1410) labels: map[]
        
        5: 0x84c00 (runtime.asyncPreempt:7) 0x1739f9 (runtime/pprof.cpuHog0:62 runtime/pprof.cpuHog1:55) 0x173939 (runtime/pprof.cpuHogger:41) 0x174ea5 (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.1:176) 0x18893d (runtime/pprof.diffCPUTimeRUsage:27) 0x17614b (runtime/pprof.diffCPUTime:485) 0x174a9b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2:174) 0x175f2b (runtime/pprof.testCPUProfile:453) 0x174537 (runtime/pprof.TestCPUProfileMultithreadMagnitude:173) 0xf6661 (testing.tRunner:1410) labels: map[]
        
        34: 0x173a7a (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
        43: 0x173a6c (runtime/pprof.cpuHog0:61 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
        14: 0x84c00 (runtime.asyncPreempt:7) 0x173a6b (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
        1: 0x173a80 (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
        13: 0x84c00 (runtime.asyncPreempt:7) 0x173a79 (runtime/pprof.cpuHog0:62 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
        2: 0x173a5e (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
        1: 0x173a68 (runtime/pprof.cpuHog0:60 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
        1: 0x84c00 (runtime.asyncPreempt:7) 0x173a7f (runtime/pprof.cpuHog0:64 runtime/pprof.cpuHog3:83) 0x173939 (runtime/pprof.cpuHogger:41) 0x174d4b (runtime/pprof.TestCPUProfileMultithreadMagnitude.func2.2.1:188) labels: map[]
        
    pprof_test.go:597: runtime/pprof.cpuHog1: 16
    pprof_test.go:597: runtime/pprof.cpuHog3: 109
    --- FAIL: TestCPUProfileMultithreadMagnitude/serial_execution_OS_vs_pprof (0.00s)
        pprof_test.go:214: compare 86.706ms vs 160ms
        pprof_test.go:226: CPU usage reports are too different (limit -40.0%, got -45.8%)
    pprof_test.go:130: 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	7.818s

This failure is the opposite of #50097. Here, the rusage is lower than the pprof samples, which is rather surprising. It also seems like we have way too many cpuHog1 samples. I'd expect 10, but see 16.

cc @rhysh @bcmills

[gopherbot]

Change https://golang.org/cl/372800 mentions this issue: runtime/pprof: run TestCPUProfileMultithreadMagnitude subtests separately

[rhysh]

The CPU profiler asks for SIGPROF signals at 100Hz: https://github.com/golang/go/blob/go1.17.5/src/runtime/pprof/pprof.go#L771

The runtime allows goroutines to run for 10ms before preempting them (via SIGURG): https://github.com/golang/go/blob/go1.17.5/src/runtime/proc.go#L5476

Are we seeing this genre of failure—a small fraction of times the CPU profiler runs include many samples pointing to code in the scheduler—because those intervals are in sync?

[prattmic]

@rhysh did you intend to put that comment on #50097? The profile here has no samples in the scheduler.

[rhysh]

I meant it for both. This has samples "in" asyncPreempt.

[prattmic]

Ah true, good point.

[heschi]

ping @prattmic @laboger -- this needs a skip or a fix.

[bcmills]

This appears not to be specific to s390x. It has now also reproduced on linux/amd64 and linux/arm64, which are both first-class ports.

greplogs --dashboard -md -l -e 'CPU usage reports are too different' --since=2022-03-01

2022-03-16T20:10:07-91631bc/linux-amd64-wsl
2022-03-16T17:41:38-c0158b6/linux-arm64-aws