runtime/pprof: TestMutexProfile failures

[gopherbot]

#!watchflakes
post <- pkg == "runtime/pprof" && test ~ `TestMutexProfile` && `profile samples total .*, want .*`

Issue created automatically to collect these failures.

Example (log):

--- FAIL: TestMutexProfile (0.23s)
    --- FAIL: TestMutexProfile/proto (0.00s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-16 21:15:15.609376 -0700 PDT
            Samples:
            contentions/count delay/nanoseconds
                      1 20537311749: 1 2 
                     99   47560262: 1 3 
            Locations
                 1: 0xd611c48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212
                 2: 0xd796ef8 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 3: 0xd796dd7 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0xd549000/0xd815000/0x0 /private/tmp/buildlet/tmp/go-build3396719100/b110/pprof.test  [FN]
            2: 0x149fe000/0x14a6a000/0xa8000 /usr/lib/dyld  
            3: 0x7ffffff58000/0x7ffffff59000/0x0   
        pprof_test.go:1312: profile samples total 20.584872011s, want 10s

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2023-08-17 01:30 darwin-amd64-race go@1c003540 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (0.23s)
    --- FAIL: TestMutexProfile/proto (0.00s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-16 21:15:15.609376 -0700 PDT
            Samples:
            contentions/count delay/nanoseconds
                      1 20537311749: 1 2 
                     99   47560262: 1 3 
            Locations
                 1: 0xd611c48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212
                 2: 0xd796ef8 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 3: 0xd796dd7 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0xd549000/0xd815000/0x0 /private/tmp/buildlet/tmp/go-build3396719100/b110/pprof.test  [FN]
            2: 0x149fe000/0x14a6a000/0xa8000 /usr/lib/dyld  
            3: 0x7ffffff58000/0x7ffffff59000/0x0   
        pprof_test.go:1312: profile samples total 20.584872011s, want 10s

— watchflakes

[bcmills]

(attn @dr2chase)

[bcmills]

Oof, looks like it's failing this way at almost every commit on linux-arm64-race too.

Probably a regression in https://go.dev/cl/506415? (attn @mknyszek, @rsc)

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`

2023-08-17 01:30 linux-arm64-race go@1c003540 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (0.21s)
    --- FAIL: TestMutexProfile/proto (0.00s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-17 01:42:14.815739145 +0000 UTC
            Samples:
            contentions/count delay/nanoseconds
                      1 20454926929: 1 2 
                     99   39188057: 1 3 
            Locations
                 1: 0xb3f8f M=1 sync.(*Mutex).Unlock /tmp/workdir/go/src/sync/mutex.go:223 s=212
                 2: 0x1f3f93 M=1 runtime/pprof.blockMutexN.func1 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 3: 0x1f3e6f M=1 runtime/pprof.blockMutexN.func2 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x10000/0x211000/0x0 /tmp/workdir/tmp/go-build2526654686/b001/pprof.test  [FN]
            2: 0xf85aaffe2000/0xf85ab013e000/0x0 /lib/aarch64-linux-gnu/libc-2.31.so 2e13b930500ba762a14ed8860bf259cb1da072b5 
            3: 0xf85ab0156000/0xf85ab0172000/0x0 /lib/aarch64-linux-gnu/libpthread-2.31.so 50698f111196e410c367ad6031b3cb34c4dfc1e4 
            4: 0xf85ab0187000/0xf85ab01a8000/0x0 /lib/aarch64-linux-gnu/ld-2.31.so ae4da2e572cddd8f08179a9bcda3dc37a146e2eb 
            5: 0xf85ab01b7000/0xf85ab01b8000/0x0 [vdso]  
        pprof_test.go:1312: profile samples total 20.494114986s, want 10s

2023-08-17 01:30 linux-s390x-ibm go@1c003540 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (1.54s)
    --- FAIL: TestMutexProfile/proto (0.00s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-16 23:14:37.428241438 -0400 EDT
            Samples:
            contentions/count delay/nanoseconds
                      1 153274842106: 1 
                     99   15044632: 2 
            Locations
                 1: 0x1b7d9f M=1 sync.(*Mutex).Unlock /data/golang/workdir/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func1 /data/golang/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 2: 0x1b7c2b M=1 sync.(*Mutex).Unlock /data/golang/workdir/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func2 /data/golang/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x10000/0x1d2000/0x0 /data/golang/workdir/tmp/go-build556235237/b001/pprof.test  [FN]
        pprof_test.go:1312: profile samples total 2m33.289886738s, want 10s

2023-08-17 05:23 freebsd-riscv64-unmatched go@2fcfdb96 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (0.22s)
    --- FAIL: TestMutexProfile/proto (0.01s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-17 15:14:34.019280798 +0800 CST
            Samples:
            contentions/count delay/nanoseconds
                      1 20455839430: 1 
                     99  125472832: 2 
            Locations
                 1: 0x155587 M=1 sync.(*Mutex).Unlock /tmp/workdir-host-freebsd-riscv64-unmatched/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func1 /tmp/workdir-host-freebsd-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 2: 0x155493 M=1 sync.(*Mutex).Unlock /tmp/workdir-host-freebsd-riscv64-unmatched/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func2 /tmp/workdir-host-freebsd-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x0/0x0/0x0   [FN]
        pprof_test.go:1312: profile samples total 20.581312262s, want 10s

2023-08-17 05:23 linux-arm64-race go@2fcfdb96 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (0.22s)
    --- FAIL: TestMutexProfile/proto (0.00s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-17 05:35:10.007836865 +0000 UTC
            Samples:
            contentions/count delay/nanoseconds
                      1 21261826649: 1 2 
                     99   37139328: 1 3 
            Locations
                 1: 0xb3f8f M=1 sync.(*Mutex).Unlock /tmp/workdir/go/src/sync/mutex.go:223 s=212
                 2: 0x1f3ef3 M=1 runtime/pprof.blockMutexN.func1 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 3: 0x1f3dcf M=1 runtime/pprof.blockMutexN.func2 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x10000/0x211000/0x0 /tmp/workdir/tmp/go-build1256645166/b001/pprof.test  [FN]
            2: 0xfd57b7915000/0xfd57b7a71000/0x0 /lib/aarch64-linux-gnu/libc-2.31.so 2e13b930500ba762a14ed8860bf259cb1da072b5 
            3: 0xfd57b7a89000/0xfd57b7aa5000/0x0 /lib/aarch64-linux-gnu/libpthread-2.31.so 50698f111196e410c367ad6031b3cb34c4dfc1e4 
            4: 0xfd57b7aba000/0xfd57b7adb000/0x0 /lib/aarch64-linux-gnu/ld-2.31.so ae4da2e572cddd8f08179a9bcda3dc37a146e2eb 
            5: 0xfd57b7aea000/0xfd57b7aeb000/0x0 [vdso]  
        pprof_test.go:1312: profile samples total 21.298965977s, want 10s

2023-08-17 16:36 freebsd-amd64-race go@36fc7214 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (0.21s)
    --- FAIL: TestMutexProfile/proto (0.00s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-17 16:49:59.187452666 +0000 UTC
            Samples:
            contentions/count delay/nanoseconds
                      1 20065021945: 1 2 
                     99   36045366: 1 3 
            Locations
                 1: 0x4cba88 M=1 sync.(*Mutex).Unlock /tmp/workdir/go/src/sync/mutex.go:223 s=212
                 2: 0x6500f8 M=1 runtime/pprof.blockMutexN.func1 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 3: 0x64ffd7 M=1 runtime/pprof.blockMutexN.func2 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x0/0x0/0x0   [FN]
        pprof_test.go:1312: profile samples total 20.101067311s, want 10s

2023-08-17 16:36 netbsd-arm64-bsiegert go@36fc7214 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (0.23s)
    --- FAIL: TestMutexProfile/proto (0.02s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-17 17:51:55.370629383 +0000 UTC
            Samples:
            contentions/count delay/nanoseconds
                      1 19985045519: 1 
                     99  201209643: 2 
            Locations
                 1: 0x156c4b M=1 sync.(*Mutex).Unlock /var/gobuilder/buildlet/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func1 /var/gobuilder/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 2: 0x156b0b M=1 sync.(*Mutex).Unlock /var/gobuilder/buildlet/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func2 /var/gobuilder/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x10000/0x16a000/0x0 /var/gobuilder/buildlet/tmp/go-build3270889078/b001/pprof.test  [FN]
        pprof_test.go:1312: profile samples total 20.186255162s, want 10s

— watchflakes

[mknyszek]

Oof. This looks like a test maybe wasn't updated. Looking.

[mknyszek]

No, the test was clearly updated, so perhaps it's wrong in some cases (or there's a bigger issue).

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`

2023-08-17 16:33 linux-s390x-ibm go@51fd0cb3 runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (1.13s)
    --- FAIL: TestMutexProfile/proto (0.00s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-17 14:22:43.244213624 -0400 EDT
            Samples:
            contentions/count delay/nanoseconds
                      1 71745991241: 1 
                     99   44506841: 2 
            Locations
                 1: 0x1b7c9f M=1 sync.(*Mutex).Unlock /data/golang/workdir/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func1 /data/golang/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 2: 0x1b7b2b M=1 sync.(*Mutex).Unlock /data/golang/workdir/go/src/sync/mutex.go:223 s=212
                         runtime/pprof.blockMutexN.func2 /data/golang/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x10000/0x1d2000/0x0 /data/golang/workdir/tmp/go-build3562684582/b001/pprof.test  [FN]
        pprof_test.go:1312: profile samples total 1m11.790498082s, want 10s

2023-08-17 16:36 linux-amd64-longtest-race go@ff47dd1d runtime/pprof.TestMutexProfile (log)

--- FAIL: TestMutexProfile (0.21s)
    --- FAIL: TestMutexProfile/proto (0.01s)
        pprof_test.go:1283: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2023-08-17 17:17:55.280958789 +0000 UTC
            Samples:
            contentions/count delay/nanoseconds
                      1 20154364168: 1 2 
                     99   33992994: 1 3 
            Locations
                 1: 0x4ae628 M=1 sync.(*Mutex).Unlock /workdir/go/src/sync/mutex.go:223 s=212
                 2: 0x6365b8 M=1 runtime/pprof.blockMutexN.func1 /workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132
                 3: 0x636497 M=1 runtime/pprof.blockMutexN.func2 /workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143
            Mappings
            1: 0x400000/0x65b000/0x0 /workdir/tmp/go-build2573774368/b001/pprof.test  [FN]
            2: 0x7f7a9cca2000/0x7f7a9cdfb000/0x22000 /lib/x86_64-linux-gnu/libc-2.31.so e15ec78d51a522023f9cfc58dc284f379d81860b 
            3: 0x7f7a9ce5a000/0x7f7a9ce6a000/0x6000 /lib/x86_64-linux-gnu/libpthread-2.31.so 255e355c207aba91a59ae1f808e3b4da443abf0c 
            4: 0x7f7a9ce80000/0x7f7a9cea0000/0x1000 /lib/x86_64-linux-gnu/ld-2.31.so e25570740d590e5cb7b1a20d86332a8d1bb3b65f 
            5: 0x7fffe8b91000/0x7fffe8b93000/0x0 [vdso]  
            6: 0xffffffffff600000/0xffffffffff601000/0x0 [vsyscall]  
        pprof_test.go:1312: profile samples total 20.188357162s, want 10s

— watchflakes

[mknyszek]

I see, the test didn't actually used to check how much contention accumulated, now it requires contention to be within [9 seconds, 20 seconds].

It may actually be that this is too flaky a condition to try and write a test about. A lot of these are only just over the threshold, but the s390x failure is waaaaay over.

[mknyszek]

Here's an idea: only check the lower-bound, not the upper bound. That's really all the new behavior is about anyway. OS scheduling can always interfere and make the timing go sky-high. It's much harder to make the time be less than that, though there is still an opportunity because the sleep happens before all the other goroutines have properly blocked.

OK, I have an idea. I will send a patch. At the very least it should downgrade this issue from Soon, even if it doesn't fully resolve the flakes.