time.Now takes ~3758 ns/op, is that normal?

[ran...@gmail.com]

I been working on something performance intensive lately, one feature of it require me to calculate the time gap between operation which require time.Now to make time marks.

After I benchmark time.Now on my computer, I found that the time.Now takes about 3758 ns to perform one operation, which is not very fast. The benchmark is here (benchmarked on my Ubuntu 18.04 LTS machine).

So, I want to know is that normal to be this slow? If it is (slow), then does there is an alternative way to to that?

Thank you!

[Jan Mercl]

On Thu, May 24, 2018 at 10:08 AM <ran...@gmail.com> wrote:

> So, I want to know is that normal to be this slow?

I think it's not normal.

jnml@r550:~/src/tmp> cat x_test.go 

package main

import (

"testing"

"time"

)

func BenchmarkTimeNow(b *testing.B) {

for i := 0; i < b.N; i++ {

time.Now()

}

}

jnml@r550:~/src/tmp> go test -bench .

goos: linux

goarch: amd64

pkg: tmp

BenchmarkTimeNow-4    20000000         61.3 ns/op

PASS

ok  tmp 1.297s

jnml@r550:~/src/tmp> 

Here's openSUSE Leap, 42.3 64-bit, Linux 4.4.126-48-default x86_64, Intel® Xeon(R) CPU X5450 @ 3.00GHz × 4.

--

-j

[lafolle]

Don't know why but on my machine its faster:

goos: linux

goarch: amd64

pkg: playground/bench-time-now

BenchmarkTimeNow-8      30000000                49.3 ns/op

PASS

Showing top 10 nodes out of 16

      flat  flat%   sum%        cum   cum%

     1.02s 65.81% 65.81%      1.02s 65.81%  runtime._ExternalCode

     0.14s  9.03% 74.84%      0.14s  9.03%  runtime.nanotime

     0.12s  7.74% 82.58%      0.23s 14.84%  time.now

     0.11s  7.10% 89.68%      0.11s  7.10%  runtime.walltime

     0.11s  7.10% 96.77%      0.34s 21.94%  time.Now

     0.04s  2.58% 99.35%      0.38s 24.52%  playground/bench-time-now.BenchmarkTimeNow

     0.01s  0.65%   100%      0.01s  0.65%  runtime.scanblock

         0     0%   100%      1.16s 74.84%  runtime._System

         0     0%   100%      0.01s  0.65%  runtime.gcBgMarkWorker

         0     0%   100%      0.01s  0.65%  runtime.gcBgMarkWorker.func2

(pprof) list time.now

Total: 1.55s

ROUTINE ======================== playground/bench-time-now.BenchmarkTimeNow in /home/lafolle/src/playground/bench-time-now/main_test.go

      40ms      380ms (flat, cum) 24.52% of Total

         .          .      5:   "testing"

         .          .      6:   "time"

         .          .      7:)

         .          .      8:

         .          .      9:func BenchmarkTimeNow(b *testing.B) {

      20ms       20ms     10:   for i := 0; i < b.N; i++ {

      20ms      360ms     11:           time.Now()

         .          .     12:   }

         .          .     13:}

ROUTINE ======================== time.now in /usr/local/go/src/runtime/timestub.go

     120ms      230ms (flat, cum) 14.84% of Total

         .          .     13:import _ "unsafe" // for go:linkname

         .          .     14:

         .          .     15:func walltime() (sec int64, nsec int32)

         .          .     16:

         .          .     17://go:linkname time_now time.now

      20ms       20ms     18:func time_now() (sec int64, nsec int32, mono int64) {

      50ms      100ms     19:   sec, nsec = walltime()

      50ms      110ms     20:   return sec, nsec, nanotime() - startNano

         .          .     21:}

(pprof)

[Jakob Borg]

Are you using the latest version of Go? time.Now() has been optimized recently.

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[ran...@gmail.com]

Thanks guys, guess that's my machine or the OS.

[ran...@gmail.com]

What has been changed? And since when? I may need dig into it for more detail.

I've tested on both 1.10 and devel +65c365bf0f Wed May 23 23:51:30 2018 +0000 linux/amd64, the result is the same (slow).

On Thursday, May 24, 2018 at 4:37:47 PM UTC+8, Jakob Borg wrote:

Are you using the latest version of Go? time.Now() has been optimized recently.

[Jakob Borg]

Sorry, I think the change I was thinking of was macOS specific, and in any case it’s in Go 1.10.

[Jesper Louis Andersen]

On Thu, May 24, 2018 at 10:08 AM <ran...@gmail.com> wrote:

After I benchmark time.Now on my computer, I found that the time.Now takes about 3758 ns to perform one operation, which is not very fast. The benchmark is here (benchmarked on my Ubuntu 18.04 LTS machine).

What is the stack down to the hardware? My immediate hunch would be that something along that path interferes.

[ran...@gmail.com]

I was suspecting the hardware too, but I tested the benchmark on Go 1.8, and found it can do 1825 ns/op. It's still slow though (maybe related to problems on my OS/hardware), but it way faster than the one under Go 1.10.





I did the test on both my computer and Cloud 9 IDE, and able reproduce the result.





After dig into the code and I found they've changed the underlaying calls, maybe that's why newer version of time.Now is slower.


[Tamás Gulácsi]

Antivirus?

[Uli Kunitz]

The following explanation  might be relevant:

https://blog.packagecloud.io/eng/2017/03/08/system-calls-are-much-slower-on-ec2/

The Go runtime, at least for 1.10, supports VDSO on Linux.

[Uli Kunitz]

On my 9  year old Core i7 950 3 GHz on Ubuntu 16.04 I get 54 ns/op for your test using go1.10.2.

[ran...@gmail.com]

I ran the test code provided by the article, and got result:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000418           4       100           gettimeofday
------ ----------- ----------- --------- --------- ----------------
100.00    0.000418                   100           total

So I guess it's true that the problem is related to it?

[mfried...@gmail.com]

Hello,

I downloaded your gist and these are my results:

~/.Trash$ $ curl -s -O https://gist.githubusercontent.com/reinit/82608ab20e5aac3bd3c1eb5a8f78d23c/raw/bbc6fdb1ad0f137a66a986fe2af931ea477b5625/time_now_test.go ; go version ; go test -bench .
go version go1.10.2 darwin/amd64
goos: darwin
goarch: amd64
BenchmarkTimeNow-4 100000000 15.6 ns/op
PASS
ok _/Users/USERNAME/.Trash 1.587s

Modellname: MacBook Pro
Modell-Identifizierung: MacBookPro9,2
Prozessortyp: Intel Core i5
Prozessorgeschwindigkeit: 2,5 GHz
Anzahl der Prozessoren: 1
Gesamtanzahl der Kerne: 2
L2-Cache (pro Kern): 256 KB
L3-Cache: 3 MB
Speicher: 16 GB

Systemversion: macOS 10.13.4 (17E202)
Kernel-Version: Darwin 17.5.0

Regards
Mirko

[Rany]

Thank you!

I think at this point it is very clear that this problem is due to some
weird alternative normal of my computer. D:

I will found another time to test it on another OS.