runtime/pprof: TestMutexProfileRateAdjust failures

[gopherbot]

#!watchflakes
default <- pkg == "runtime/pprof" && test == "TestMutexProfileRateAdjust"

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestMutexProfileRateAdjust
    pprof_test.go:1346: parsed proto: PeriodType: contentions count
        Period: 1
        Time: 2024-05-21 21:18:01.20247723 +0000 UTC
        Samples:
        contentions/count delay/nanoseconds
                  1 102552218537: 1 2 
                  4   98039668: 3 4 5 6 7 8 
                  1   34212735: 1 9 
                  2   27714188: 10 11 12 13 14 15 16 
...
            53: 0x47bf6e M=1 runtime.schedule /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:3961 s=3914
        Mappings
        1: 0x400000/0x6c1000/0x0 /home/swarming/.swarming/w/ir/x/t/go-build426206143/b1123/pprof.test  [FN]
        2: 0x7fb508e0b000/0x7fb508f64000/0x22000 /lib/x86_64-linux-gnu/libc-2.31.so a3780b0b8a5bf5876e31d16b0a9d8fc6ba69a1f2 
        3: 0x7fb508fc3000/0x7fb508fd3000/0x6000 /lib/x86_64-linux-gnu/libpthread-2.31.so 255e355c207aba91a59ae1f808e3b4da443abf0c 
        4: 0x7fb508fe9000/0x7fb509009000/0x1000 /lib/x86_64-linux-gnu/ld-2.31.so 1b3277a419c3fa42b199e5a170ea215b32689793 
        5: 0x7fff93f7b000/0x7fff93f7d000/0x0 [vdso]  
        6: 0xffffffffff600000/0xffffffffff601000/0x0 [vsyscall]  
    pprof_test.go:1372: sample value changed: got [3, 36408740], want [2, 34236017]
--- FAIL: TestMutexProfileRateAdjust (0.12s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/pprof" && test == "TestMutexProfileRateAdjust"

2024-05-21 21:08 gotip-linux-amd64-longtest-race go@5a9dabc2 runtime/pprof.TestMutexProfileRateAdjust (log)

=== RUN   TestMutexProfileRateAdjust
    pprof_test.go:1346: parsed proto: PeriodType: contentions count
        Period: 1
        Time: 2024-05-21 21:18:01.20247723 +0000 UTC
        Samples:
        contentions/count delay/nanoseconds
                  1 102552218537: 1 2 
                  4   98039668: 3 4 5 6 7 8 
                  1   34212735: 1 9 
                  2   27714188: 10 11 12 13 14 15 16 
...
            53: 0x47bf6e M=1 runtime.schedule /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:3961 s=3914
        Mappings
        1: 0x400000/0x6c1000/0x0 /home/swarming/.swarming/w/ir/x/t/go-build426206143/b1123/pprof.test  [FN]
        2: 0x7fb508e0b000/0x7fb508f64000/0x22000 /lib/x86_64-linux-gnu/libc-2.31.so a3780b0b8a5bf5876e31d16b0a9d8fc6ba69a1f2 
        3: 0x7fb508fc3000/0x7fb508fd3000/0x6000 /lib/x86_64-linux-gnu/libpthread-2.31.so 255e355c207aba91a59ae1f808e3b4da443abf0c 
        4: 0x7fb508fe9000/0x7fb509009000/0x1000 /lib/x86_64-linux-gnu/ld-2.31.so 1b3277a419c3fa42b199e5a170ea215b32689793 
        5: 0x7fff93f7b000/0x7fff93f7d000/0x0 [vdso]  
        6: 0xffffffffff600000/0xffffffffff601000/0x0 [vsyscall]  
    pprof_test.go:1372: sample value changed: got [3, 36408740], want [2, 34236017]
--- FAIL: TestMutexProfileRateAdjust (0.12s)

— watchflakes

[rhysh]

Looking at 2024-05-21 21:08 gotip-linux-amd64-longtest-race go@5a9dabc2 runtime/pprof.TestMutexProfileRateAdjust (log)

The first profile has two Location entries that match "runtime/pprof.blockMutex.func1":

9: 0x69679b M=1 runtime/pprof.blockMutex.func1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1119 s=1117
32: 0x696791 M=1 runtime/pprof.blockMutex.func1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1118 s=1117

These show up in:

 1   34212735: 1 9 
 1      23282: 10 11 12 13 14 15 32 

The new profile also has two matching Location entries:

9: 0x69679b M=1 runtime/pprof.blockMutex.func1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1119 s=1117
39: 0x696791 M=1 runtime/pprof.blockMutex.func1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1118 s=1117

Those show up in

 1   34212735: 1 9 
 1    2172723: 18 19 20 12 21 22 23 24 1 9 
 1      23282: 10 11 12 13 14 15 39 

The new entry, 1 2172723: 18 19 20 12 21 22 23 24 1 9 , corresponds to the call stack

            18: 0x4ab00e M=1 runtime.unlock /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/lock_futex.go:160 s=159
                     runtime.wakep /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:3066 s=3037
            19: 0x4763c4 M=1 runtime.ready /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:1008 s=990
            20: 0x488bc4 M=1 runtime.readyWithTime.goready.func1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:413 s=412
            12: 0x4af129 M=1 runtime.systemstack /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:514 s=483
            21: 0x488b6d M=1 runtime.goready /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:412 s=411
                     runtime.readyWithTime /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/sema.go:99 s=95
            22: 0x4890cf M=1 runtime.semrelease1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/sema.go:231 s=175
            23: 0x4ac2b2 M=1 sync.runtime_Semrelease /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/sema.go:72 s=71
            24: 0x4bc75d M=1 sync.(*Mutex).unlockSlow /home/swarming/.swarming/w/ir/x/w/goroot/src/sync/mutex.go:246 s=227zx
             1: 0x4bc668 M=1 sync.(*Mutex).Unlock /home/swarming/.swarming/w/ir/x/w/goroot/src/sync/mutex.go:223 s=212
             9: 0x69679b M=1 runtime/pprof.blockMutex.func1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1119 s=1117

Which is showing contention on sched.lock (a runtime-internal mutex),

go/src/runtime/proc.go

Line 3066 in 5a9dabc

unlock(&sched.lock)

Looks like this test needs an update to only find growth in userspace sync.Mutex values (which are fully under the test's control), and to ignore contention reports for runtime-internal mutex values (which are not under the test's control).

[gopherbot]

Change https://go.dev/cl/586957 mentions this issue: runtime/pprof: ignore runtime-internal samples in test