odd benchmark results for time.Now() call inside vs outside mutex

[Jim Robinson]

Hi folks,

I was testing some code and I noticed something that struck me as little odd. In the following code:

https://play.golang.org/p/z8OOCrnZ85s

we have routines Set1, Set2, and Set3.  They do the same thing, but change where time.Now().Unix() is called.

Set1 calls for the time before it acquires a mutex, eventually passing that time onto a 3rd function

Set2 calls for the time after it's acquired the lock, and passes the value onto the 3rd function.

Set3 calls for the time after it's acquired the lock as part of its call to the 3rd function.

The benchmarks for these operations is different:

$ go test -bench .
goos: linux
goarch: amd64
BenchmarkStateSet1-64         1000000          1156 ns/op
BenchmarkStateSet2-64         1295552           833 ns/op
BenchmarkStateSet3-64         2348185           703 ns/op
PASS
ok      _/home/jimr/tmp/odd    5.739s
$ go test -bench .
goos: linux
goarch: amd64
BenchmarkStateSet1-64         1000000          1146 ns/op
BenchmarkStateSet2-64         3256602           603 ns/op
BenchmarkStateSet3-64         1439412           842 ns/op
PASS
ok      _/home/jimr/tmp/odd    5.983s
$ go test -bench .
goos: linux
goarch: amd64
BenchmarkStateSet1-64         1000000          1130 ns/op
BenchmarkStateSet2-64         1772056           772 ns/op
BenchmarkStateSet3-64         2637054           433 ns/op
PASS
ok      _/home/jimr/tmp/odd    6.325s

Based on the difference between Set2/Set3 I'm wondering if this is just a case of the numbers being small enough that it's hard to reliabily measure them, but I'm struck how much slower Set1 is than Set2/Set3, apparently due to whether or not the time.Now().Unix() call is made within the lock?  Why would that be?

Jim

[Sean Liao]

maybe it's just your system?

master » gotip test -bench .

goos: linux

goarch: amd64

pkg: testrepo-75

BenchmarkStateSet1-4    4173546       273 ns/op

BenchmarkStateSet2-4    4547119       261 ns/op

BenchmarkStateSet3-4    4556757       263 ns/op

PASS

ok  testrepo-75 4.899s

[Jim Robinson]

That's interesting!

My numbers earlier were from an AMD chip (2990WX) on Linux 5.3.11.

On an older Intel chip (i7-4960HQ) on macOS 10.15.3 I still see small a difference but it's much smaller.

$ go test -bench .

goos: darwin
goarch: amd64
BenchmarkStateSet1-8        2737468           441 ns/op
BenchmarkStateSet2-8        3514694           345 ns/op
BenchmarkStateSet3-8        3351747           356 ns/op
PASS
ok      _/Users/jimr/tmp/odd    5.253s

[Jake Montgomery]

FWIW, I also don't see any appreciable difference:

goos: windows
goarch: amd64
BenchmarkStateSet1-4     1368303               872 ns/op
BenchmarkStateSet2-4     1379320               887 ns/op
BenchmarkStateSet3-4     1343781               865 ns/op
PASS
ok      command-line-arguments  7.446s