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
Output
$ 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.
About this issue
- Original URL
- State: closed
- Created a year ago
- Reactions: 1
- Comments: 16 (8 by maintainers)
This is the immediate problem. The kernel has decided that the TSC is not reliable and disabled its use.
There is nothing we can do in Go. I suggest reaching out on one of the kernel bugs. https://bugzilla.kernel.org/show_bug.cgi?id=202525 has the same kernel warnings, though a slightly different CPU model.