runtime: contended mutex profiling doesn't work for sync.RWMutex

[vcabbage]

What version of Go are you using (go version)?

go version devel +9def857072 Mon Jan 2 20:21:02 2017 +0000 darwin/amd64

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/kale/go"
GORACE=""
GOROOT="/Users/kale/gomaster"
GOTOOLDIR="/Users/kale/gomaster/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/jv/fp0q8rhx427f6p892mh4mpx40000gn/T/go-build367788226=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

Ran a benchmark with a RWMutex and -mutexprofile enabled.

Example:

func BenchmarkRWMutex(b *testing.B) {
	var mu sync.RWMutex
	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			mu.RLock()
			mu.RUnlock()
		}
	})
}

What did you expect to see?

Mutex contention information.

Example from a similar test using Lock/Unlock:

go tool pprof ./mutex.test mutex.out
Entering interactive mode (type "help" for commands)
(pprof) top10
1.60s of 1.60s total (  100%)
      flat  flat%   sum%        cum   cum%
     1.60s   100%   100%      1.60s   100%  sync.(*Mutex).Unlock
         0     0%   100%      1.60s   100%  github.com/vcabbage/mutexprofile-repro.BenchmarkMutex.func1
         0     0%   100%      1.60s   100%  runtime.goexit
         0     0%   100%      1.60s   100%  testing.(*B).RunParallel.func1

What did you see instead?

go tool pprof ./mutex.test mutex.out
Entering interactive mode (type "help" for commands)
(pprof) top10
profile is empty

I see that sync.Mutex was changed to use runtime_SemacquireMutex instead of runtime_Semacquire in https://golang.org/cl/29650/, but sync.RWMutex continues to use runtime_Semacquire.

I'm unsure if sync.RWMutex was excluded from profiling intentionally, but the lack of profiling information was surprising to me.

[vcabbage]

Some profiling information is collected when using the Lock/Unlock methods of a sync.RWMutex, presumably because sync.RWMutex.Lock() locks an underlying sync.Mutex.

[rsc]

This is probably an oversight but I am not willing to change it at this point in the release cycle. Let's fix it early in Go 1.9.

/cc @pjweinb

[vcabbage]

Is it worth a note in the documentation or is this issue good enough?

[rsc]

Sent https://go-review.googlesource.com/34831 for the docs. Thanks.

[gopherbot]

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

[pjweinbgo]

I will produce a CL for 1.9.

[odeke-em]

How's it going @pjweinbgo, still interested in working on this issue?

[panicfarm]

Has this been fixed? One can use kill -ABRT pid to dump deadlocked goroutines

[pjweinb]

i don't think so.

…

On Tue, Nov 7, 2017 at 2:02 AM, Alec Matusis ***@***.***> wrote: Has this been fixed? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#18496 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFKAIxXi-Xhdv8N6lEXC10nGJNeK3rCNks5s0AB8gaJpZM4LZP_2> .

[gopherbot]

Change https://golang.org/cl/87095 mentions this issue: sync: Enable profiling of RWMutex

[lmb]

I've created a "straw man" CL based on the comments in this issue. Testing with the following makes pprof report contention on both RWMutex.Unlock and RWMutex.RUnlock.

func BenchmarkRWMutex(b *testing.B) {
	var mu sync.RWMutex

	mu.Lock()
	go func() {
		for {
			time.Sleep(10 * time.Millisecond)
			mu.Unlock()
			time.Sleep(10 * time.Millisecond)
			mu.Lock()
		}
	}()

	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			mu.RLock()
			time.Sleep(10 * time.Millisecond)
			mu.RUnlock()
		}
	})
}

I'm not sure whether the measurements are attributed to the right call stack though.