go: runtime/pprof: TestCPUProfileInlining failures with "got separate Location entries"

greplogs --dashboard -md -l -e 'FAIL: TestCPUProfileInlining .*(?:\n .*)* got separate Location entries' --since=2021-01-01

2022-02-03T16:58:29-f9b761a/windows-amd64-longtest

--- FAIL: TestCPUProfileInlining (5.13s)
    pprof_test.go:524: total 500 CPU profile samples collected:
        366: 0x94c524 (runtime/pprof.cpuHog0:64 runtime/pprof.inlinedCallee:304 runtime/pprof.inlinedCaller:299) 0x94add3 (runtime/pprof.cpuHogger:41) 0x94c189 (runtime/pprof.TestCPUProfileInlining.func1:278) 0x94cda2 (runtime/pprof.testCPUProfile:451) 0x94c2bb (runtime/pprof.TestCPUProfileInlining:277) 0x8dbf01 (testing.tRunner:1440) labels: map[]
        
        116: 0x94c51c (runtime/pprof.cpuHog0:64 runtime/pprof.inlinedCallee:304 runtime/pprof.inlinedCaller:299) 0x94add3 (runtime/pprof.cpuHogger:41) 0x94c189 (runtime/pprof.TestCPUProfileInlining.func1:278) 0x94cda2 (runtime/pprof.testCPUProfile:451) 0x94c2bb (runtime/pprof.TestCPUProfileInlining:277) 0x8dbf01 (testing.tRunner:1440) labels: map[]
        
        1: 0x857169 (runtime.nanotime:18) 0x8864b3 (time.Since:878) 0x94ae12 (runtime/pprof.cpuHogger:40) 0x94c189 (runtime/pprof.TestCPUProfileInlining.func1:278) 0x94cda2 (runtime/pprof.testCPUProfile:451) 0x94c2bb (runtime/pprof.TestCPUProfileInlining:277) 0x8dbf01 (testing.tRunner:1440) labels: map[]
        
        1: 0x94c501 (runtime/pprof.inlinedCaller:299) 0x94add3 (runtime/pprof.cpuHogger:41) 0x94c189 (runtime/pprof.TestCPUProfileInlining.func1:278) 0x94cda2 (runtime/pprof.testCPUProfile:451) 0x94c2bb (runtime/pprof.TestCPUProfileInlining:277) 0x8dbf01 (testing.tRunner:1440) labels: map[]
        
        14: 0x94c520 (runtime/pprof.cpuHog0:64 runtime/pprof.inlinedCallee:304) 0x94c501 (runtime/pprof.inlinedCaller:299) 0x94add3 (runtime/pprof.cpuHogger:41) 0x94c189 (runtime/pprof.TestCPUProfileInlining.func1:278) 0x94cda2 (runtime/pprof.testCPUProfile:451) 0x94c2bb (runtime/pprof.TestCPUProfileInlining:277) 0x8dbf01 (testing.tRunner:1440) labels: map[]
        
        1: 0x84722a (runtime.runqsteal:6108) 0x83fe91 (runtime.stealWork:3080) 0x83f375 (runtime.findrunnable:2788) 0x840918 (runtime.schedule:3376) 0x840e6c (runtime.park_m:3525) 0x865589 (runtime.mcall:425) labels: map[]
        
        1: 0x840b01 (runtime.checkTimers:3445) 0x8407d2 (runtime.schedule:3337) 0x840f64 (runtime.goschedImpl:3540) 0x841254 (runtime.gopreempt_m:3568) 0x84ee39 (runtime.newstack:1068) 0x8656f2 (runtime.morestack:547) labels: map[]
        
    pprof_test.go:595: runtime/pprof.inlinedCallee: 496
    pprof_test.go:595: runtime/pprof.inlinedCaller: 497
    pprof_test.go:293: want inlinedCallee followed by inlinedCaller, got separate Location entries:
        PeriodType: cpu nanoseconds
        Period: 10000000
        Time: 2022-02-03 17:20:19.3752399 +0000 GMT
        Duration: 5.1318594s
        Samples:
        samples/count cpu/nanoseconds
                366 3660000000: 1 2 3 4 5 6 
                116 1160000000: 7 2 3 4 5 6 
                  1   10000000: 8 9 10 3 4 5 6 
                  1   10000000: 11 2 3 4 5 6 
                 14  140000000: 12 11 2 3 4 5 6 
                  1   10000000: 13 14 15 16 17 18 
                  1   10000000: 19 20 21 22 23 24 
        Locations
             1: 0x94c524 M=1 runtime/pprof.cpuHog0 C:/workdir/go/src/runtime/pprof/pprof_test.go:64 s=0
                     runtime/pprof.inlinedCallee C:/workdir/go/src/runtime/pprof/pprof_test.go:304 s=0
                     runtime/pprof.inlinedCaller C:/workdir/go/src/runtime/pprof/pprof_test.go:299 s=0
             2: 0x94add3 M=1 runtime/pprof.cpuHogger C:/workdir/go/src/runtime/pprof/pprof_test.go:41 s=0
             3: 0x94c189 M=1 runtime/pprof.TestCPUProfileInlining.func1 C:/workdir/go/src/runtime/pprof/pprof_test.go:278 s=0
             4: 0x94cda2 M=1 runtime/pprof.testCPUProfile C:/workdir/go/src/runtime/pprof/pprof_test.go:451 s=0
             5: 0x94c2bb M=1 runtime/pprof.TestCPUProfileInlining C:/workdir/go/src/runtime/pprof/pprof_test.go:277 s=0
             6: 0x8dbf01 M=1 testing.tRunner C:/workdir/go/src/testing/testing.go:1440 s=0
             7: 0x94c51c M=1 runtime/pprof.cpuHog0 C:/workdir/go/src/runtime/pprof/pprof_test.go:64 s=0
                     runtime/pprof.inlinedCallee C:/workdir/go/src/runtime/pprof/pprof_test.go:304 s=0
                     runtime/pprof.inlinedCaller C:/workdir/go/src/runtime/pprof/pprof_test.go:299 s=0
             8: 0x857169 M=1 runtime.nanotime C:/workdir/go/src/runtime/time_nofake.go:18 s=0
             9: 0x8864b3 M=1 time.Since C:/workdir/go/src/time/time.go:878 s=0
            10: 0x94ae12 M=1 runtime/pprof.cpuHogger C:/workdir/go/src/runtime/pprof/pprof_test.go:40 s=0
            11: 0x94c501 M=1 runtime/pprof.inlinedCaller C:/workdir/go/src/runtime/pprof/pprof_test.go:299 s=0
            12: 0x94c520 M=1 runtime/pprof.cpuHog0 C:/workdir/go/src/runtime/pprof/pprof_test.go:64 s=0
                     runtime/pprof.inlinedCallee C:/workdir/go/src/runtime/pprof/pprof_test.go:304 s=0
            13: 0x84722a M=1 runtime.runqsteal C:/workdir/go/src/runtime/proc.go:6108 s=0
            14: 0x83fe91 M=1 runtime.stealWork C:/workdir/go/src/runtime/proc.go:3080 s=0
            15: 0x83f375 M=1 runtime.findrunnable C:/workdir/go/src/runtime/proc.go:2788 s=0
            16: 0x840918 M=1 runtime.schedule C:/workdir/go/src/runtime/proc.go:3376 s=0
            17: 0x840e6c M=1 runtime.park_m C:/workdir/go/src/runtime/proc.go:3525 s=0
            18: 0x865589 M=1 runtime.mcall C:/workdir/go/src/runtime/asm_amd64.s:425 s=0
            19: 0x840b01 M=1 runtime.checkTimers C:/workdir/go/src/runtime/proc.go:3445 s=0
            20: 0x8407d2 M=1 runtime.schedule C:/workdir/go/src/runtime/proc.go:3337 s=0
            21: 0x840f64 M=1 runtime.goschedImpl C:/workdir/go/src/runtime/proc.go:3540 s=0
            22: 0x841254 M=1 runtime.gopreempt_m C:/workdir/go/src/runtime/proc.go:3568 s=0
            23: 0x84ee39 M=1 runtime.newstack C:/workdir/go/src/runtime/stack.go:1068 s=0
            24: 0x8656f2 M=1 runtime.morestack C:/workdir/go/src/runtime/asm_amd64.s:547 s=0
        Mappings
        1: 0x0/0x0/0x0   [FN]
FAIL
FAIL	runtime/pprof	59.856s

2021-11-05T17:23:06-37951d8/linux-386-longtest 2021-10-31T02:24:29-0bef30d/linux-amd64-nocgo 2021-10-28T20:39:36-834e36e/windows-amd64-longtest 2021-08-06T20:44:03-63b968f/openbsd-mips64-jsing 2021-05-08T17:03:18-b38b1b2/linux-amd64-staticlockranking

May be related to #42862.

CC @cherrymui @prattmic @rhysh

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 15 (13 by maintainers)

Commits related to this issue

runtime/pprof: fix allFrames cache The compiler may choose to inline multiple layers of function call, such that A calling B calling C may end up with all of the instructions for B and C written as p... — committed to golang/go by rhysh 2 years ago

Most upvoted comments

Maybe another idea is to have the compiler to insert the NOPs at the end of a function so they never get executed.

cherrymui on Feb 16, 2022

That is what I am thinking, but I’ll need to find time to think about this more deeply. I’ve been swamped dealing with other issues for the past few days. 😃

prattmic on Feb 15, 2022