sync: mutex profiling information is confusing (wrong?) for mutexes with >2 contenders

[jquirke]

go/src/runtime/sema.go

Line 340 in 2b2348a

t.acquiretime = now

Please answer these questions before submitting your issue. Thanks!

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

(lldb) plat sh go version go version go1.10.1 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

(lldb) plat sh go env
GOARCH="amd64"
GOBIN=""
GOCACHE="off"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.10.1/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.10.1/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build604482558=/tmp/go-build -gno-record-gcc-switches -fno-common"`

What did you do?

package main

import (
	"fmt"
	"os"
	"runtime"
	"runtime/pprof"
	"sync"
	"testing"
)

func TestMutex(t *testing.T) {
	runtime.SetMutexProfileFraction(1)
	fmt.Printf("Running with fraction = %v\n", runtime.SetMutexProfileFraction(1))
	ch := make(chan struct{}, 3)
	m := sync.Mutex{}
	go func1(ch, &m, 10)
	go func2(ch, &m, 10)
	go func3(ch, &m, 10)

	<-ch
	<-ch
	<-ch
	fmt.Println("Done waiting")
	profile := pprof.Lookup("mutex")
	profile.WriteTo(os.Stdout, 1)
}

func core(m *sync.Mutex, loops int) {
	m.Lock()

	for i := 0; i < loops*1000*1000*1000; i++ {
	}
	m.Unlock()
}
func func1(ch chan<- struct{}, m *sync.Mutex, loops int) {
	core(m, loops)
	fmt.Println("Done func1 loops=", loops)
	ch <- struct{}{}
}

func func2(ch chan<- struct{}, m *sync.Mutex, loops int) {
	core(m, loops)
	fmt.Println("Done func2 loops=", loops)
	ch <- struct{}{}
}

func func3(ch chan<- struct{}, m *sync.Mutex, loops int) {
	core(m, loops)
	fmt.Println("Done func3 loops=", loops)
	ch <- struct{}{}
}

What did you expect to see?

That one func was contended for twice as long as the other: e.g.

lldb) c
Process 90281 resuming
Running with fraction = 1
Done func3 loops= 10
Done func1 loops= 10
Done func2 loops= 10
Done waiting
--- mutex:
cycles/second=3096003024
sampling period=1
37586656890 1 @ 0x105ad75 0x10e7897 0x10e78e9 0x1053ac1
#       0x105ad74       sync.(*Mutex).Unlock+0x74       /usr/local/Cellar/go/1.10.1/libexec/src/sync/mutex.go:201
#       0x10e7896       testmutex.core+0x56             /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:34
#       0x10e78e8       testmutex.func1+0x38            /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:37

19168525985 1 @ 0x105ad75 0x10e7897 0x10e7ac9 0x1053ac1
#       0x105ad74       sync.(*Mutex).Unlock+0x74       /usr/local/Cellar/go/1.10.1/libexec/src/sync/mutex.go:201
#       0x10e7896       testmutex.core+0x56             /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:34
#       0x10e7ac8       testmutex.func3+0x38            /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:49

What did you see instead?

Running with fraction = 1
Done func3 loops= 10
Done func1 loops= 10
        Done func2 loops= 10
Done waiting
--- mutex:
cycles/second=3095995234
sampling period=1
20145330860 1 @ 0x105ad75 0x10e7897 0x10e7ac9 0x1053ac1
#       0x105ad74       sync.(*Mutex).Unlock+0x74       /usr/local/Cellar/go/1.10.1/libexec/src/sync/mutex.go:201
#       0x10e7896       testmutex.core+0x56             /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:34
#       0x10e7ac8       testmutex.func3+0x38            /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:49

19631603241 1 @ 0x105ad75 0x10e7897 0x10e78e9 0x1053ac1
#       0x105ad74       sync.(*Mutex).Unlock+0x74       /usr/local/Cellar/go/1.10.1/libexec/src/sync/mutex.go:201
#       0x10e7896       testmutex.core+0x56             /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:34
#       0x10e78e8       testmutex.func1+0x38            /Users/qjeremy/gocode/src/testmutex/testmutex_test.go:37

Analysis

I believe the cause is the linked line number, I am not sure why the next sudog (t) should be considered to have start waiting from the time first sudog (s) is released

[ianlancetaylor]

CC @pjweinbgo

[pjweinbgo]

rsc added this line on 10 Feb 2017.