go: time: Now is "slow"

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

$ go version
go version go1.20rc2 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/pierre/.cache/go-build"
GOENV="/home/pierre/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/pierre/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/pierre/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/pierre/.gimme/versions/go1.20rc2.src"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/pierre/.gimme/versions/go1.20rc2.src/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.20rc2"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1508083160=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Disclaimer: yes I know, I’m trying to do something “silly” (benchmarking time.Now()). But it has a real impact in production for me.

Context: I’m trying to measure the execution time of a function that is “fast” (below 1 microsecond).

I ran a benchmark on my function (with testing.B), so I know it’s fast (below 1 microsecond). But I want to measure its execution time while it’s running in production (and report it in my metrics).

So I did something simple:

start := time.Now()
// call my function
dur := time.Since(start)
// report in my metrics

Then I noticed that the measured duration was much higher than the time measured in my benchmark (around 5 microseconds, vs 1 microsecond in my benchmark).

So I did a benchmark that calls time.Now():

func BenchmarkTimeNow(b *testing.B) {
	var res time.Time
	for i := 0; i < b.N; i++ {
		res = time.Now()
	}
	benchRes = res
}

➜  timebench go test -v -bench=.
goos: linux
goarch: amd64
pkg: timebench
cpu: AMD Ryzen 7 PRO 4750U with Radeon Graphics
BenchmarkTimeNow
BenchmarkTimeNow-16       543583              2249 ns/op
PASS
ok      timebench       1.249s

(Yes I closed all other running apps)

I’m very surprised, because this time (2249ns) is very high. If I remember correctly, on my other computer it was 2 orders of magnitude lower (30ns)

I did a profiling of my benchmark. All the CPU time is spent in time.now() (yes, lower case now)

My question: how can I measure the execution time of a function, if calling time.Now() is slower than calling my function ?

Feel free to close this issue if you think it’s not a problem.

What did you expect to see?

Calling time.Now() should take approximately 30ns.

This is the benchmark result on my other computer:

➜  timebench go test -v -bench=.
goos: linux
goarch: amd64
pkg: timebench
cpu: Intel(R) Core(TM) i7-8750H CPU @ 2.20GHz
BenchmarkTimeNow
BenchmarkTimeNow-12     35953132                31.34 ns/op
PASS
ok      timebench       1.164s
➜  timebench go version
go version go1.20rc2 linux/amd64

What did you see instead?

Calling time.Now() takes 2249ns, which is slower than the execution time of the function I’m trying to measure.