Repository: go
Issue: sync: mutex profiling information is confusing (wrong?) for mutexes with >2 contenders
Labels: NeedsInvestigation,compiler/runtime

https://github.com/golang/go/blob/2b2348ab143368a35031a814a8d41eb5a437aa33/src/runtime/sema.go#L340

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