#!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
Comment From: 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 10sComment From: bcmills
(attn @dr2chase)
Comment From: 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)
Comment From: 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 10s2023-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 10s2023-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 10s2023-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 10s2023-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 10s2023-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 10sComment From: mknyszek
Oof. This looks like a test maybe wasn't updated. Looking.
Comment From: mknyszek
No, the test was clearly updated, so perhaps it's wrong in some cases (or there's a bigger issue).
Comment From: 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 10s2023-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 10sComment From: 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.
Comment From: 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.
Comment From: bcmills
Can the contention be bounded above by something else (maybe time.Since(start)*time.Duration(runtime.NumCPU())? (Or is it counting contention per-goroutine instead of per thread?)
Comment From: mknyszek
It's contention per goroutine. I didn't totally remove the upper bound, but it set it to be on the order of a test timeout.
Comment From: mknyszek
I think the only non-flaky way to really check the math would be to stub out time altogether, but that's pretty difficult to do.
Comment From: gopherbot
Change https://go.dev/cl/520635 mentions this issue: runtime/pprof: increase contention upper bound in TestMutexProfile
Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 21:51 linux-amd64-longtest-race go@639f6f7e 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 22:34:08.372696519 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20397767924: 1 2 99 37251393: 1 3 Locations 1: 0x4ae608 M=1 sync.(*Mutex).Unlock /workdir/go/src/sync/mutex.go:223 s=212 2: 0x638778 M=1 runtime/pprof.blockMutexN.func1 /workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x638657 M=1 runtime/pprof.blockMutexN.func2 /workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x400000/0x65d000/0x0 /workdir/tmp/go-build660364905/b001/pprof.test [FN] 2: 0x7f28c922b000/0x7f28c9384000/0x22000 /lib/x86_64-linux-gnu/libc-2.31.so e15ec78d51a522023f9cfc58dc284f379d81860b 3: 0x7f28c93e3000/0x7f28c93f3000/0x6000 /lib/x86_64-linux-gnu/libpthread-2.31.so 255e355c207aba91a59ae1f808e3b4da443abf0c 4: 0x7f28c9409000/0x7f28c9429000/0x1000 /lib/x86_64-linux-gnu/ld-2.31.so e25570740d590e5cb7b1a20d86332a8d1bb3b65f 5: 0x7ffd3f6e6000/0x7ffd3f6e8000/0x0 [vdso] 6: 0xffffffffff600000/0xffffffffff601000/0x0 [vsyscall] pprof_test.go:1312: profile samples total 20.435019317s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 22:56 linux-s390x-ibm go@ab3332ee runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.31s) --- FAIL: TestMutexProfile/proto (0.00s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-17 19:23:50.796930913 -0400 EDT Samples: contentions/count delay/nanoseconds 1 25705553206: 1 99 15537192: 2 Locations 1: 0x1b950f 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: 0x1b939b 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/0x1d4000/0x0 /data/golang/workdir/tmp/go-build502678389/b001/pprof.test [FN] pprof_test.go:1312: profile samples total 25.721090398s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 21:35 darwin-amd64-race go@bcf83825 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.26s) --- FAIL: TestMutexProfile/proto (0.00s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-17 22:56:23.359275 -0700 PDT Samples: contentions/count delay/nanoseconds 1 24579493209: 1 2 99 17306819: 1 3 Locations 1: 0xab9dc48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212 2: 0xad23018 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0xad22ef7 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0xaad5000/0xada1000/0x0 /private/tmp/buildlet/tmp/go-build86030298/b110/pprof.test [FN] 2: 0x11456000/0x114c2000/0xa8000 /usr/lib/dyld 3: 0x7ffffff67000/0x7ffffff68000/0x0 pprof_test.go:1312: profile samples total 24.596800028s, want 10s2023-08-17 21:35 netbsd-arm64-bsiegert go@bcf83825 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.24s) --- FAIL: TestMutexProfile/proto (0.03s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-18 05:47:23.402517499 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20179548979: 1 99 196012420: 2 Locations 1: 0x15734b 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: 0x15720b 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/0x16b000/0x0 /var/gobuilder/buildlet/tmp/go-build92626304/b001/pprof.test [FN] pprof_test.go:1312: profile samples total 20.375561399s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 14:32 openbsd-arm-jsing go@99b80993 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.25s) --- FAIL: TestMutexProfile/proto (0.01s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-15 17:04:36.409093314 +1000 AEST Samples: contentions/count delay/nanoseconds 1 20417582156: 1 2 99 171911950: 1 3 Locations 1: 0x8ecf7 M=1 sync.(*Mutex).Unlock /home/gopher/build/go/src/sync/mutex.go:223 s=212 2: 0x1839f3 M=1 runtime/pprof.blockMutexN.func1 /home/gopher/build/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x1838ef M=1 runtime/pprof.blockMutexN.func2 /home/gopher/build/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x0/0x0/0x0 [FN] pprof_test.go:1312: profile samples total 20.589494106s, want 10s2023-08-17 20:40 openbsd-arm-jsing go@11390998 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.26s) --- FAIL: TestMutexProfile/proto (0.01s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-15 22:28:11.314696725 +1000 AEST Samples: contentions/count delay/nanoseconds 1 21229002989: 1 2 99 177799006: 1 3 Locations 1: 0x8ecf7 M=1 sync.(*Mutex).Unlock /home/gopher/build/go/src/sync/mutex.go:223 s=212 2: 0x183afb M=1 runtime/pprof.blockMutexN.func1 /home/gopher/build/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x1839ef M=1 runtime/pprof.blockMutexN.func2 /home/gopher/build/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x0/0x0/0x0 [FN] pprof_test.go:1312: profile samples total 21.406801995s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-18 11:58 windows-amd64-race go@925d2fb3 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-18 12:17:36.1928387 +0000 GMT Samples: contentions/count delay/nanoseconds 1 20328548220: 1 2 99 77086809: 1 3 Locations ... 10: 0x7fff5e6e0000/0x7fff5e6eb000/0x0 C:\Windows\SYSTEM32\CRYPTBASE.DLL C:\Windows\SYSTEM32\CRYPTBASE.DLL2016-07-16 13:18:43.0047202 +0000 GMT 11: 0x7fff5ed90000/0x7fff5edfc000/0x0 C:\Windows\System32\bcryptPrimitives.dll C:\Windows\System32\bcryptPrimitives.dll2021-11-02 01:16:14.8741335 +0000 GMT 12: 0x7fff5cff0000/0x7fff5d013000/0x0 C:\Windows\SYSTEM32\winmm.dll C:\Windows\SYSTEM32\winmm.dll2016-07-16 13:18:49.6296658 +0000 GMT 13: 0x510000/0x53b000/0x0 C:\Windows\SYSTEM32\WINMMBASE.dll C:\Windows\SYSTEM32\WINMMBASE.dll2016-07-16 13:18:49.6296658 +0000 GMT 14: 0x7fff5f3e0000/0x7fff5f422000/0x0 C:\Windows\System32\cfgmgr32.dll C:\Windows\System32\cfgmgr32.dll2016-07-16 13:18:41.957854 +0000 GMT 15: 0x7fff61680000/0x7fff616ea000/0x0 C:\Windows\System32\ws2_32.dll C:\Windows\System32\ws2_32.dll2023-05-09 18:48:28.347363 +0000 GMT 16: 0x7fff5ec90000/0x7fff5ecdc000/0x0 C:\Windows\System32\powrprof.dll C:\Windows\System32\powrprof.dll2016-07-16 13:18:41.942229 +0000 GMT 17: 0x7fff5eec0000/0x7fff5efb4000/0x0 C:\Windows\System32\ucrtbase.dll C:\Windows\System32\ucrtbase.dll2023-05-09 18:47:57.3556825 +0000 GMT 18: 0x7fff61960000/0x7fff61968000/0x0 C:\Windows\System32\psapi.dll C:\Windows\System32\psapi.dll2016-07-16 13:18:30.4579491 +0000 GMT pprof_test.go:1312: profile samples total 20.405635029s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-18 11:58 linux-arm64-race go@925d2fb3 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-18 12:10:24.367224839 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20244824518: 1 2 99 35187075: 1 3 Locations 1: 0xb3f3f M=1 sync.(*Mutex).Unlock /tmp/workdir/go/src/sync/mutex.go:223 s=212 2: 0x1f59d3 M=1 runtime/pprof.blockMutexN.func1 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x1f58af M=1 runtime/pprof.blockMutexN.func2 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x213000/0x0 /tmp/workdir/tmp/go-build3262245566/b001/pprof.test [FN] 2: 0xfd6380c62000/0xfd6380dbe000/0x0 /lib/aarch64-linux-gnu/libc-2.31.so 2e13b930500ba762a14ed8860bf259cb1da072b5 3: 0xfd6380dd6000/0xfd6380df2000/0x0 /lib/aarch64-linux-gnu/libpthread-2.31.so 50698f111196e410c367ad6031b3cb34c4dfc1e4 4: 0xfd6380e07000/0xfd6380e28000/0x0 /lib/aarch64-linux-gnu/ld-2.31.so ae4da2e572cddd8f08179a9bcda3dc37a146e2eb 5: 0xfd6380e37000/0xfd6380e38000/0x0 [vdso] pprof_test.go:1312: profile samples total 20.280011593s, want 10s2023-08-18 11:59 linux-arm64-race go@d63c88d6 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-18 12:20:43.265556245 +0000 UTC Samples: contentions/count delay/nanoseconds 1 21344460707: 1 2 99 34875574: 1 3 Locations 1: 0xb3f3f M=1 sync.(*Mutex).Unlock /tmp/workdir/go/src/sync/mutex.go:223 s=212 2: 0x1f59c3 M=1 runtime/pprof.blockMutexN.func1 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x1f589f M=1 runtime/pprof.blockMutexN.func2 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x213000/0x0 /tmp/workdir/tmp/go-build1644680536/b001/pprof.test [FN] 2: 0xf804e7ee7000/0xf804e8043000/0x0 /lib/aarch64-linux-gnu/libc-2.31.so 2e13b930500ba762a14ed8860bf259cb1da072b5 3: 0xf804e805b000/0xf804e8077000/0x0 /lib/aarch64-linux-gnu/libpthread-2.31.so 50698f111196e410c367ad6031b3cb34c4dfc1e4 4: 0xf804e808c000/0xf804e80ad000/0x0 /lib/aarch64-linux-gnu/ld-2.31.so ae4da2e572cddd8f08179a9bcda3dc37a146e2eb 5: 0xf804e80bc000/0xf804e80bd000/0x0 [vdso] pprof_test.go:1312: profile samples total 21.379336281s, want 10s2023-08-18 15:53 linux-arm64-race go@b65e34f0 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-18 16:08:06.035666693 +0000 UTC Samples: contentions/count delay/nanoseconds 1 21261935986: 1 2 99 36459523: 1 3 Locations 1: 0xb3f3f M=1 sync.(*Mutex).Unlock /tmp/workdir/go/src/sync/mutex.go:223 s=212 2: 0x1f59c3 M=1 runtime/pprof.blockMutexN.func1 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x1f589f M=1 runtime/pprof.blockMutexN.func2 /tmp/workdir/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x213000/0x0 /tmp/workdir/tmp/go-build786627159/b001/pprof.test [FN] 2: 0xf7ffea14a000/0xf7ffea2a6000/0x0 /lib/aarch64-linux-gnu/libc-2.31.so 2e13b930500ba762a14ed8860bf259cb1da072b5 3: 0xf7ffea2be000/0xf7ffea2da000/0x0 /lib/aarch64-linux-gnu/libpthread-2.31.so 50698f111196e410c367ad6031b3cb34c4dfc1e4 4: 0xf7ffea2ef000/0xf7ffea310000/0x0 /lib/aarch64-linux-gnu/ld-2.31.so ae4da2e572cddd8f08179a9bcda3dc37a146e2eb 5: 0xf7ffea31f000/0xf7ffea320000/0x0 [vdso] pprof_test.go:1312: profile samples total 21.298395509s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-18 11:59 darwin-amd64-race go@d63c88d6 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-18 05:27:14.836617 -0700 PDT Samples: contentions/count delay/nanoseconds 1 21432279722: 1 2 99 24893959: 1 3 Locations 1: 0x4da1c48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212 2: 0x4f26ef8 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x4f26dd7 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x4cd9000/0x4fa5000/0x0 /private/tmp/buildlet/tmp/go-build4239751926/b110/pprof.test [FN] 2: 0xc339000/0xc3a5000/0xa8000 /usr/lib/dyld 3: 0x7fffffe26000/0x7fffffe27000/0x0 pprof_test.go:1312: profile samples total 21.457173681s, want 10sComment From: mknyszek
All these failures are from commits earlier than https://github.com/golang/go/commit/e8a767b609a32972aca848b806700b3f7ddd34d3.
Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-18 11:59 linux-riscv64-unmatched go@d63c88d6 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.51s) --- FAIL: TestMutexProfile/proto (0.01s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-18 13:22:49.357129981 +0000 UTC Samples: contentions/count delay/nanoseconds 1 24477945904: 1 99 110852993: 2 Locations 1: 0x15a98f M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x15a893 M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x16e000/0x0 /tmp/workdir-host-linux-riscv64-unmatched/tmp/go-build3749658387/b001/pprof.test [FN] 2: 0x3fbf2a0000/0x3fbf2a2000/0x0 [vdso] pprof_test.go:1312: profile samples total 24.588798897s, want 10s2023-08-18 15:53 linux-riscv64-unmatched go@b65e34f0 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.58s) --- FAIL: TestMutexProfile/proto (0.01s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-18 17:26:24.391396294 +0000 UTC Samples: contentions/count delay/nanoseconds 1 38654930964: 1 99 102699308: 2 Locations 1: 0x15a98f M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x15a893 M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x16e000/0x0 /tmp/workdir-host-linux-riscv64-unmatched/tmp/go-build195465704/b001/pprof.test [FN] 2: 0x3fa71c6000/0x3fa71c8000/0x0 [vdso] pprof_test.go:1312: profile samples total 38.757630272s, want 10sComment From: mknyszek
Both from earlier commits as well.
Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 19:37 darwin-amd64-race go@2c51ea11 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-19 13:08:43.466793 -0700 PDT Samples: contentions/count delay/nanoseconds 1 21184505026: 1 2 99 28783829: 1 3 Locations 1: 0xef43c48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212 2: 0xf0c9018 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0xf0c8ef7 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0xee7b000/0xf147000/0x0 /private/tmp/buildlet/tmp/go-build22291991/b110/pprof.test [FN] 2: 0x16a4d000/0x16ab9000/0xa8000 /usr/lib/dyld 3: 0x7ffffff56000/0x7ffffff57000/0x0 pprof_test.go:1312: profile samples total 21.213288855s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 19:36 darwin-amd64-race go@7e2e648a runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.24s) --- FAIL: TestMutexProfile/proto (0.00s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-19 13:34:43.821269 -0700 PDT Samples: contentions/count delay/nanoseconds 1 22038497046: 1 2 99 28197973: 1 3 Locations 1: 0x24a4c48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212 2: 0x262a018 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x2629ef7 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x23dc000/0x26a8000/0x0 /private/tmp/buildlet/tmp/go-build2552119484/b110/pprof.test [FN] 2: 0x113e7000/0x11453000/0xa8000 /usr/lib/dyld 3: 0x7ffffff9a000/0x7ffffff9b000/0x0 pprof_test.go:1312: profile samples total 22.066695019s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 16:36 darwin-amd64-race go@ff47dd1d 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-19 15:40:38.965607 -0700 PDT Samples: contentions/count delay/nanoseconds 1 20923732641: 1 2 99 37334042: 1 3 Locations 1: 0x8a6ac48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212 2: 0x8befe38 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x8befd17 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x89a2000/0x8c6e000/0x0 /private/tmp/buildlet/tmp/go-build1297540383/b110/pprof.test [FN] 2: 0xbeb6000/0xbf22000/0xa8000 /usr/lib/dyld 3: 0x7fffffefd000/0x7fffffefe000/0x0 pprof_test.go:1312: profile samples total 20.961066683s, want 10sComment From: mknyszek
These are all from old Go versions, because they don't have the new failure output.
Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 16:23 darwin-amd64-race go@469d9e26 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-19 21:08:47.227638 -0700 PDT Samples: contentions/count delay/nanoseconds 1 20642859122: 1 2 99 18382567: 1 3 Locations 1: 0x54ebc48 M=1 sync.(*Mutex).Unlock /tmp/buildlet/go/src/sync/mutex.go:223 s=212 2: 0x5670e38 M=1 runtime/pprof.blockMutexN.func1 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1135 s=1132 3: 0x5670d17 M=1 runtime/pprof.blockMutexN.func2 /tmp/buildlet/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x5423000/0x56ef000/0x0 /private/tmp/buildlet/tmp/go-build2086276054/b110/pprof.test [FN] 2: 0xed65000/0xedd1000/0xa8000 /usr/lib/dyld 3: 0x7ffffffb9000/0x7ffffffba000/0x0 pprof_test.go:1312: profile samples total 20.661241689s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-18 15:53 ios-arm64-corellium go@b65e34f0 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-26 13:06:55.684488 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20304504165: 1 99 23691027: 2 Locations 1: 0x10421bccb M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x10421bb8b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x1040d0000/0x104274000/0x0 /private/var/tmp/workdir-host-ios-arm64-corellium-ios/tmp/go-build3930827924/b108/pprof.test [FN] 2: 0x104404000/0x104410000/0x4000 /usr/lib/pspawn_payload.dylib 3: 0x10441c000/0x104434000/0x4000 /usr/lib/libsubstitute.dylib 4: 0x104474000/0x10447c000/0x4000 /usr/lib/libsubstrate.dylib 5: 0x104488000/0x10448c000/0x0 /private/var/preferences/Logging/.plist-cache.2gj3zp4S 6: 0x10448c000/0x104490000/0x0 /private/var/preferences/Logging/.plist-cache.2gj3zp4S 7: 0x104490000/0x104494000/0x0 /private/var/preferences/Logging/.plist-cache.2gj3zp4S 8: 0x104494000/0x104498000/0x0 /private/var/preferences/Logging/.plist-cache.2gj3zp4S 9: 0x1045f0000/0x10465c000/0x0 /usr/lib/dyld 10: 0x1046dc000/0x104980000/0x4000 /usr/lib/substitute-loader.dylib 11: 0x1d48a0000/0x1d48a4000/0x0 12: 0x1d48c0000/0x1d48c4000/0x0 13: 0x1f0f98000/0x1f0f9c000/0x0 pprof_test.go:1312: profile samples total 20.328195192s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 20:02 ios-arm64-corellium go@b75ac7a8 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.20s) --- FAIL: TestMutexProfile/proto (0.00s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-08-28 11:16:50.602912 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20226499621: 1 99 25312761: 2 Locations 1: 0x1041f7ceb M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x1041f7bab M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x1040ac000/0x104250000/0x0 /private/var/tmp/workdir-host-ios-arm64-corellium-ios/tmp/go-build868964319/b108/pprof.test [FN] 2: 0x1043e0000/0x1043ec000/0x4000 /usr/lib/pspawn_payload.dylib 3: 0x1043f8000/0x104410000/0x4000 /usr/lib/libsubstitute.dylib 4: 0x104450000/0x104458000/0x4000 /usr/lib/libsubstrate.dylib 5: 0x104464000/0x104468000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 6: 0x104468000/0x10446c000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 7: 0x10446c000/0x104470000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 8: 0x104470000/0x104474000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 9: 0x104568000/0x1045d4000/0x0 /usr/lib/dyld 10: 0x104654000/0x1048f8000/0x4000 /usr/lib/substitute-loader.dylib 11: 0x1b1ea4000/0x1b1ea8000/0x0 12: 0x1b1ec4000/0x1b1ec8000/0x0 13: 0x1ce59c000/0x1ce5a0000/0x0 pprof_test.go:1312: profile samples total 20.251812382s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 19:36 ios-arm64-corellium go@5c6fbd2c 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-28 13:21:59.083352 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20499574363: 1 99 27696053: 2 Locations 1: 0x10311806b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x103117f2b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x102fcc000/0x103170000/0x0 /private/var/tmp/workdir-host-ios-arm64-corellium-ios/tmp/go-build745420378/b108/pprof.test [FN] 2: 0x10330c000/0x1035b0000/0x4000 /usr/lib/substitute-loader.dylib 3: 0x103654000/0x103660000/0x4000 /usr/lib/pspawn_payload.dylib 4: 0x10366c000/0x103684000/0x4000 /usr/lib/libsubstitute.dylib 5: 0x1036b4000/0x1036bc000/0x4000 /usr/lib/libsubstrate.dylib 6: 0x1036c8000/0x103734000/0x0 /usr/lib/dyld 7: 0x1037b4000/0x1037b8000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 8: 0x1037b8000/0x1037bc000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 9: 0x1037bc000/0x1037c0000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 10: 0x1037c0000/0x1037c4000/0x0 /private/var/preferences/Logging/.plist-cache.t2QfIQMP 11: 0x1b1ea4000/0x1b1ea8000/0x0 12: 0x1b1ec4000/0x1b1ec8000/0x0 13: 0x1ce59c000/0x1ce5a0000/0x0 pprof_test.go:1312: profile samples total 20.527270416s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 16:33 ios-arm64-corellium go@f278ae61 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-29 04:18:49.528931 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20948087307: 1 99 27324259: 2 Locations 1: 0x10275804b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x102757f0b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10260c000/0x1027b0000/0x0 /private/var/tmp/workdir-host-ios-arm64-corellium-ios/tmp/go-build3406153023/b108/pprof.test [FN] 2: 0x102948000/0x102bec000/0x4000 /usr/lib/substitute-loader.dylib 3: 0x102c9c000/0x102ca8000/0x4000 /usr/lib/pspawn_payload.dylib 4: 0x102cb4000/0x102ccc000/0x4000 /usr/lib/libsubstitute.dylib 5: 0x102cf4000/0x102cfc000/0x4000 /usr/lib/libsubstrate.dylib 6: 0x102d08000/0x102d0c000/0x0 /usr/lib/dyld 7: 0x102d0c000/0x102d10000/0x0 /usr/lib/dyld 8: 0x102d10000/0x102d14000/0x0 /usr/lib/dyld 9: 0x102d14000/0x102d18000/0x0 /usr/lib/dyld 10: 0x102d2c000/0x102d98000/0x0 /usr/lib/dyld 11: 0x1d9edc000/0x1d9ee0000/0x0 12: 0x1d9efc000/0x1d9f00000/0x0 13: 0x1f65d4000/0x1f65d8000/0x0 pprof_test.go:1312: profile samples total 20.975411566s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 16:33 ios-arm64-corellium go@51fd0cb3 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-29 05:15:14.6361 +0000 UTC Samples: contentions/count delay/nanoseconds 1 21120267578: 1 99 23500313: 2 Locations 1: 0x1029c004b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x1029bff0b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x102874000/0x102a18000/0x0 /private/var/tmp/workdir-host-ios-arm64-corellium-ios/tmp/go-build2929635281/b108/pprof.test [FN] 2: 0x102ba8000/0x102bb4000/0x4000 /usr/lib/pspawn_payload.dylib 3: 0x102bc0000/0x102bd8000/0x4000 /usr/lib/libsubstitute.dylib 4: 0x102c18000/0x102c20000/0x4000 /usr/lib/libsubstrate.dylib 5: 0x102c2c000/0x102c30000/0x0 /private/var/preferences/Logging/.plist-cache.wCdl0iIa 6: 0x102c30000/0x102c34000/0x0 /private/var/preferences/Logging/.plist-cache.wCdl0iIa 7: 0x102c34000/0x102c38000/0x0 /private/var/preferences/Logging/.plist-cache.wCdl0iIa 8: 0x102c38000/0x102c3c000/0x0 /private/var/preferences/Logging/.plist-cache.wCdl0iIa 9: 0x102eb0000/0x102f1c000/0x0 /usr/lib/dyld 10: 0x102f9c000/0x103240000/0x4000 /usr/lib/substitute-loader.dylib 11: 0x1d9edc000/0x1d9ee0000/0x0 12: 0x1d9efc000/0x1d9f00000/0x0 13: 0x1f65d4000/0x1f65d8000/0x0 pprof_test.go:1312: profile samples total 21.143767891s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 14:27 linux-riscv64-unmatched go@4e336b8e runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.33s) --- FAIL: TestMutexProfile/proto (0.01s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-09-02 18:33:49.77187342 +0000 UTC Samples: contentions/count delay/nanoseconds 1 25514869306: 1 99 119148451: 2 Locations 1: 0x15979f M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x1596ab M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x16d000/0x0 /tmp/workdir-host-linux-riscv64-unmatched/tmp/go-build3341094814/b001/pprof.test [FN] 2: 0x3f9e216000/0x3f9e218000/0x0 [vdso] pprof_test.go:1312: profile samples total 25.634017757s, want 10s2023-08-17 16:21 linux-riscv64-unmatched go@7af31076 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-09-02 17:18:17.58940251 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20330653492: 1 99 105657867: 2 Locations 1: 0x15979f M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x1596ab M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x16d000/0x0 /tmp/workdir-host-linux-riscv64-unmatched/tmp/go-build2447695979/b001/pprof.test [FN] 2: 0x3fb3d46000/0x3fb3d48000/0x0 [vdso] pprof_test.go:1312: profile samples total 20.436311359s, want 10s2023-08-17 19:37 linux-riscv64-unmatched go@48e05ee7 runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.26s) --- FAIL: TestMutexProfile/proto (0.01s) pprof_test.go:1283: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-09-01 11:01:32.155170845 +0000 UTC Samples: contentions/count delay/nanoseconds 1 24982658462: 1 99 109070381: 2 Locations 1: 0x159a8f M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x159993 M=1 sync.(*Mutex).Unlock /tmp/workdir-host-linux-riscv64-unmatched/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-linux-riscv64-unmatched/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x16d000/0x0 /tmp/workdir-host-linux-riscv64-unmatched/tmp/go-build3923738751/b001/pprof.test [FN] 2: 0x3f8db4f000/0x3f8db51000/0x0 [vdso] pprof_test.go:1312: profile samples total 25.091728843s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-08-17 14:27 ios-arm64-corellium go@4e336b8e 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-09-02 18:56:55.335473 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20623488546: 1 99 26409261: 2 Locations 1: 0x104cdc04b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x104cdbf0b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x104b90000/0x104d34000/0x0 /private/var/tmp/workdir-host-ios-arm64-corellium-ios/tmp/go-build2710989375/b108/pprof.test [FN] 2: 0x104ec4000/0x104ed0000/0x4000 /usr/lib/pspawn_payload.dylib 3: 0x104edc000/0x104ef4000/0x4000 /usr/lib/libsubstitute.dylib 4: 0x104f34000/0x104f3c000/0x4000 /usr/lib/libsubstrate.dylib 5: 0x104f48000/0x104f4c000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 6: 0x104f4c000/0x104f50000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 7: 0x104f50000/0x104f54000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 8: 0x104f54000/0x104f58000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 9: 0x10516c000/0x1051d8000/0x0 /usr/lib/dyld 10: 0x105258000/0x1054fc000/0x4000 /usr/lib/substitute-loader.dylib 11: 0x1c5cf8000/0x1c5cfc000/0x0 12: 0x1c5d18000/0x1c5d1c000/0x0 13: 0x1e23f0000/0x1e23f4000/0x0 pprof_test.go:1312: profile samples total 20.649897807s, want 10s2023-08-17 16:21 ios-arm64-corellium go@7af31076 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-09-02 16:14:40.634892 +0000 UTC Samples: contentions/count delay/nanoseconds 1 20823866088: 1 99 23780052: 2 Locations 1: 0x104e9c04b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x104e9bf0b M=1 sync.(*Mutex).Unlock /tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x104d50000/0x104ef4000/0x0 /private/var/tmp/workdir-host-ios-arm64-corellium-ios/tmp/go-build4152390833/b108/pprof.test [FN] 2: 0x105084000/0x105090000/0x4000 /usr/lib/pspawn_payload.dylib 3: 0x10509c000/0x1050b4000/0x4000 /usr/lib/libsubstitute.dylib 4: 0x1050f4000/0x1050fc000/0x4000 /usr/lib/libsubstrate.dylib 5: 0x105108000/0x10510c000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 6: 0x10510c000/0x105110000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 7: 0x105110000/0x105114000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 8: 0x105114000/0x105118000/0x0 /private/var/preferences/Logging/.plist-cache.sYLzUhbW 9: 0x1052a0000/0x10530c000/0x0 /usr/lib/dyld 10: 0x10538c000/0x105630000/0x4000 /usr/lib/substitute-loader.dylib 11: 0x1c5cf8000/0x1c5cfc000/0x0 12: 0x1c5d18000/0x1c5d1c000/0x0 13: 0x1e23f0000/0x1e23f4000/0x0 pprof_test.go:1312: profile samples total 20.84764614s, want 10sComment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test == "TestMutexProfile" && `profile samples total .*, want .*`
2023-09-08 19:14 linux-mipsle-rtrk go@dfbf809f runtime/pprof.TestMutexProfile (log)
--- FAIL: TestMutexProfile (0.16s) --- FAIL: TestMutexProfile/proto (0.00s) pprof_test.go:1285: parsed proto: PeriodType: contentions count Period: 1 Time: 2023-09-10 11:37:45.370963617 +0200 CEST Samples: contentions/count delay/nanoseconds 1 6947561992: 1 99 24846108: 2 Locations 1: 0x1d636f M=1 sync.(*Mutex).Unlock /tmp/gobuilder-mips64le/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func1 /tmp/gobuilder-mips64le/go/src/runtime/pprof/pprof_test.go:1135 s=1132 2: 0x1d61d7 M=1 sync.(*Mutex).Unlock /tmp/gobuilder-mips64le/go/src/sync/mutex.go:223 s=212 runtime/pprof.blockMutexN.func2 /tmp/gobuilder-mips64le/go/src/runtime/pprof/pprof_test.go:1146 s=1143 Mappings 1: 0x10000/0x1f1000/0x0 /tmp/gobuilder-mips64le/tmp/go-build3322728179/b001/pprof.test [FN] 2: 0x200000/0x351000/0x1f0000 /tmp/gobuilder-mips64le/tmp/go-build3322728179/b001/pprof.test 3: 0x360000/0x37b000/0x350000 /tmp/gobuilder-mips64le/tmp/go-build3322728179/b001/pprof.test 4: 0x37b000/0x392000/0x0 [heap] 5: 0x7ffb9000/0x7ffba000/0x0 [vdso] pprof_test.go:1325: sample: 6.947561992s pprof_test.go:1325: sample: 24.846108ms pprof_test.go:1327: profile samples total 6.9724081s, want within range [9s, 17.11477702s] (target: 10s)Comment From: mknyszek
This last one from linux-mipsle-rtrk is real. All the other ones are from before the fix.
Comment From: mknyszek
Removed release-blocker and Soon labels because this has only appeared on linux-mipsle-rtrk after the test fix. The rate of failures is also clearly very low at this point.
Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test ~ `TestMutexProfile` && `profile samples total .*, want .*`
2024-01-26 17:17 gotip-windows-arm64 go@c21d118a runtime/pprof.TestMutexProfile/proto (log)
=== RUN TestMutexProfile/proto pprof_test.go:1285: parsed proto: PeriodType: contentions count Period: 1 Time: 2024-01-26 17:29:03.4293581 +0000 UTC Samples: contentions/count delay/nanoseconds 1 11847929070: 1 99 8200547: 2 Locations 1: 0x7ff64f896cab M=1 sync.(*Mutex).Unlock C:/Users/swarming/.swarming/w/ir/x/w/goroot/src/sync/mutex.go:223 s=212 ... 10: 0x7fff228f0000/0x7fff228fe000/0x0 C:\Windows\System32\psapi.dll C:\Windows\System32\psapi.dll2022-05-07 07:56:13.0524618 +0000 UTC 11: 0x7fff23050000/0x7fff23190000/0x0 C:\Windows\System32\advapi32.dll C:\Windows\System32\advapi32.dll2024-01-05 20:15:35.6909346 +0000 UTC 12: 0x7fff20b90000/0x7fff20cd4000/0x0 C:\Windows\System32\msvcrt.dll C:\Windows\System32\msvcrt.dll2024-01-05 20:17:07.5822522 +0000 UTC 13: 0x7fff20370000/0x7fff2049e000/0x0 C:\Windows\System32\sechost.dll C:\Windows\System32\sechost.dll2024-01-05 20:17:08.1134994 +0000 UTC 14: 0x7fff1e990000/0x7fff1e9db000/0x0 C:\Windows\System32\bcrypt.dll C:\Windows\System32\bcrypt.dll2024-01-05 20:17:09.0041528 +0000 UTC 15: 0x7fff1e360000/0x7fff1e456000/0x0 C:\Windows\system32\apphelp.dll C:\Windows\system32\apphelp.dll2024-01-05 20:17:19.2698821 +0000 UTC pprof_test.go:1325: sample: 11.84792907s pprof_test.go:1325: sample: 8.200547ms pprof_test.go:1327: profile samples total 11.856129617s, want within range [9s, 11.801526s] (target: 10s) --- FAIL: TestMutexProfile/proto (0.01s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "runtime/pprof" && test ~ `TestMutexProfile` && `profile samples total .*, want .*`