runtime/pprof: TestMutexProfile flakiness

[randall77]

On the builders, I see TestMutexProfile occasionally failing with

--- FAIL: TestMutexProfile (0.01s)
	pprof_test.go:532: expected 6 lines, got 3 "--- mutex:\ncycles/second=2362842166\nsampling period=1"
		--- mutex:
		cycles/second=2362842166
		sampling period=1
FAIL
FAIL	runtime/pprof	1.298s

Maybe freebsd only?

@pjweinb

Some builder logs:
https://build.golang.org/log/c625cca078dac40bc5f1f50b62891c04b52308c5
https://build.golang.org/log/118de984fc0903fe93c3e677962cd7965637a2a3

[pjweinb]

That's a remarkably uninformative error message, even if I wrote it. It should include "expected to see evidence of a contended mutex, but didn't" I'll try to figure out when this started and why.

…

On Fri, Feb 17, 2017 at 1:43 AM, Keith Randall ***@***.***> wrote: On the builders, I see TestMutexProfile occasionally failing with --- FAIL: TestMutexProfile (0.01s) pprof_test.go:532: expected 6 lines, got 3 "--- mutex:\ncycles/second=2362842166 <(236)%20284-2166>\nsampling period=1" --- mutex: cycles/second=2362842166 <(236)%20284-2166> sampling period=1 FAIL FAIL runtime/pprof 1.298s Maybe freebsd only? @pjweinb <https://github.com/pjweinb> Some builder logs: https://build.golang.org/log/c625cca078dac40bc5f1f50b62891c04b52308c5 https://build.golang.org/log/118de984fc0903fe93c3e677962cd7965637a2a3 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#19139>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFKAIztybRHcmJ3GgqtJvSV8-C2pLYPkks5rdUF8gaJpZM4MD7Xl> .

[bradfitz]

I also saw it on OpenBSD in #19146 (closed as dup of this).

[pjweinb]

Is there some way of scanning the builder logs to find all the occurrences?

…

On Fri, Feb 17, 2017 at 11:39 AM, Brad Fitzpatrick ***@***.*** > wrote: I also saw it on OpenBSD in #19146 <#19146> (closed as dup of this). — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#19139 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFKAI3_JmOy1T8ejJ2UVoDbIjfSZW1DAks5rdc1EgaJpZM4MD7Xl> .

[ianlancetaylor]

@aclements has a tool that scans the builder logs for test failures.

[aclements]

$ greplogs -dashboard -E "TestMutexProfile" -E "expected 6 lines" -l -md
2017-02-16T17:34:39-fc456c7/freebsd-386-gce101
2017-02-16T17:34:39-fc456c7/freebsd-amd64-race
2017-02-16T17:52:15-990124d/linux-386
2017-02-16T21:54:59-661e217/freebsd-amd64-gce93
2017-02-16T21:54:59-661e217/linux-ppc64le-buildlet
2017-02-16T22:42:36-794f1eb/freebsd-amd64-race
2017-02-17T06:16:44-708ba22/freebsd-amd64-gce93
2017-02-17T14:36:27-79f6a5c/windows-386-gce

$ greplogs -dashboard -E "TestMutexProfile" -E "expected 6 lines" -l | findflakes -paths
First observed fc456c7 16 Feb 17:34 2017 (8 commits ago)
Last observed  79f6a5c 17 Feb 14:36 2017 (1 commits ago)
29% chance failure is still happening
71% failure probability (6 of 8 commits)
Likely culprits:
   71% fc456c7 cmd/compile/internal/gc: drop unused src.XPos params in SSA builder
   20% 58d7621 runtime: run mutexevent profiling without holding semaRoot lock
No known past failures

[pjweinb]

Thank you. one suspects 58d7621 runtime: run mutexevent profiling without holding semaRoot lock .

…

On Fri, Feb 17, 2017 at 12:39 PM, Austin Clements ***@***.***> wrote: $ greplogs -dashboard -E "TestMutexProfile" -E "expected 6 lines" -l -md 2017-02-16T17:34:39-fc456c7/freebsd-386-gce101 <https://build.golang.org/log/650f030384a8cd59590aa45a7ba4b45162ecf13c> 2017-02-16T17:34:39-fc456c7/freebsd-amd64-race <https://build.golang.org/log/acda774eebe4d038055f9b18ef8b5fa7e65c2b8b> 2017-02-16T17:52:15-990124d/linux-386 <https://build.golang.org/log/c85606a6439012033aea7647cf65e7dfb99f565d> 2017-02-16T21:54:59-661e217/freebsd-amd64-gce93 <https://build.golang.org/log/118de984fc0903fe93c3e677962cd7965637a2a3> 2017-02-16T21:54:59-661e217/linux-ppc64le-buildlet <https://build.golang.org/log/c5f1775d3d40fb1dd1d050b0f3cf6213d93510c3> 2017-02-16T22:42:36-794f1eb/freebsd-amd64-race <https://build.golang.org/log/80a6635a54baaea90fac0f91d3aafa17b068e1b3> 2017-02-17T06:16:44-708ba22/freebsd-amd64-gce93 <https://build.golang.org/log/c625cca078dac40bc5f1f50b62891c04b52308c5> 2017-02-17T14:36:27-79f6a5c/windows-386-gce <https://build.golang.org/log/4ef0671c856abe449ef7aa8d2e5d75ef844c6e14> $ greplogs -dashboard -E "TestMutexProfile" -E "expected 6 lines" -l | findflakes -paths First observed fc456c7 16 Feb 17:34 2017 (8 commits ago) Last observed 79f6a5c 17 Feb 14:36 2017 (1 commits ago) 29% chance failure is still happening 71% failure probability (6 of 8 commits) Likely culprits: 71% fc456c7 cmd/compile/internal/gc: drop unused src.XPos params in SSA builder 20% 58d7621 runtime: run mutexevent profiling without holding semaRoot lock No known past failures — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#19139 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFKAIwd02Uc7BzETFHTi9pRFA35m_XbJks5rddthgaJpZM4MD7Xl> .

[mdempsky]

Seeing as it's also appearing on Linux and Windows, it appears OS agnostic.

[gopherbot]

CL https://golang.org/cl/37291 mentions this issue.