RWMutex.Unlock() appearing in mutex contention profiles

[arussellsaw]

Please answer these questions before submitting your issue. Thanks!

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

go1.8rc3

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/alex/dev/go"
GORACE=""
GOROOT="/Users/alex/sdk/go1.8rc3"
GOTOOLDIR="/Users/alex/sdk/go1.8rc3/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/l5/x43qw4sd10j_459gxsy9h3j80000gn/T/go-build886344651=/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?

built a contrived test to profile mutex contention using RWMutex (without realising that RWMutex was not supported).

if required i can create a new version using only public code but for now the library being profiled is closed source.

What did you expect to see?

No contention shown in pprof list output for RWMutex

What did you see instead?

(pprof) list
Total: 1.06s
ROUTINE ======================== code.avct.io/services/lru.(*Map).Get in /Users/alex/dev/go/src/code.avct.io/services/lru/lru.go
         0    34.01us (flat, cum) 0.0032% of Total
         .          .    137:	m.em.RLock()
         .          .    138:	if e, exists := m.exist[k]; exists {
         .          .    139:		m.em.RUnlock()
         .          .    140:		m.vm.Lock()
         .          .    141:		m.values.MoveToFront(e)
         .    34.01us    142:		m.vm.Unlock()
         .          .    143:		return e.Value.(mapElement).V, true
         .          .    144:	}
         .          .    145:	m.em.RUnlock()
         .          .    146:	return nil, false
         .          .    147:}
ROUTINE ======================== code.avct.io/services/lru.(*Map).Set in /Users/alex/dev/go/src/code.avct.io/services/lru/lru.go
         0      1.06s (flat, cum)   100% of Total
         .          .    159:
         .          .    160:	// never panics because we always ensure the list has instances of mapElement
         .          .    161:	me := e.Value.(mapElement)
         .          .    162:	delete(m.exist, me.K)
         .          .    163:	m.exist[k] = m.values.PushFront(mapElement{K: k, V: v})
         .      1.01s    164:	m.em.Unlock()
         .          .    165:
         .          .    166:	m.values.Remove(e)
         .    49.82ms    167:	m.vm.Unlock()
         .          .    168:
         .          .    169:	// Run registered eviction function, if any
         .          .    170:	if me.Fn != nil {
         .          .    171:		me.Fn()
         .          .    172:	}
ROUTINE ======================== main.main.func2 in /Users/alex/dev/go/src/code.avct.io/services/cmd/scratch/main.go
         0      1.06s (flat, cum)   100% of Total
         .          .     46:		ctx := context.Background()
         .          .     47:		r.Wait(ctx)
         .          .     48:		go func() {
         .          .     49:			start := time.Now()
         .          .     50:			id := ids[rand.Intn(150000)]
         .    34.01us     51:			v, ok := m.Get(id)
         .          .     52:			if !ok {
         .      1.06s     53:				m.Set(id, users[id], nil)
         .          .     54:			}
         .          .     55:			if v == -1 {
         .          .     56:				panic("no")
         .          .     57:			}
         .          .     58:			tChan <- time.Since(start)
ROUTINE ======================== runtime.goexit in /Users/alex/sdk/go1.8rc3/src/runtime/asm_amd64.s
         0      1.06s (flat, cum)   100% of Total
         .          .   2192:	RET
         .          .   2193:
         .          .   2194:// The top-most function running on a goroutine
         .          .   2195:// returns to goexit+PCQuantum.
         .          .   2196:TEXT runtime·goexit(SB),NOSPLIT,$0-0
         .      1.06s   2197:	BYTE	$0x90	// NOP
         .          .   2198:	CALL	runtime·goexit1(SB)	// does not return
         .          .   2199:	// traceback from goexit1 must hit code range of goexit
         .          .   2200:	BYTE	$0x90	// NOP
         .          .   2201:
         .          .   2202:TEXT runtime·prefetcht0(SB),NOSPLIT,$0-8
ROUTINE ======================== sync.(*Mutex).Unlock in /Users/alex/sdk/go1.8rc3/src/sync/mutex.go
     1.06s      1.06s (flat, cum)   100% of Total
         .          .    121:			return
         .          .    122:		}
         .          .    123:		// Grab the right to wake someone.
         .          .    124:		new = (old - 1<<mutexWaiterShift) | mutexWoken
         .          .    125:		if atomic.CompareAndSwapInt32(&m.state, old, new) {
     1.06s      1.06s    126:			runtime_Semrelease(&m.sema)
         .          .    127:			return
         .          .    128:		}
         .          .    129:		old = m.state
         .          .    130:	}
         .          .    131:}
ROUTINE ======================== sync.(*RWMutex).Unlock in /Users/alex/sdk/go1.8rc3/src/sync/rwmutex.go
         0      1.06s (flat, cum)   100% of Total
         .          .    120:	// Unblock blocked readers, if any.
         .          .    121:	for i := 0; i < int(r); i++ {
         .          .    122:		runtime_Semrelease(&rw.readerSem)
         .          .    123:	}
         .          .    124:	// Allow other writers to proceed.
         .      1.06s    125:	rw.w.Unlock()
         .          .    126:	if race.Enabled {
         .          .    127:		race.Enable()
         .          .    128:	}
         .          .    129:}

[arussellsaw]

i realised this profiling is just due to the sync.Mutex inside the RWMutex, so this issue is incorrect