Skip to content

Instantly share code, notes, and snippets.

@nirui

nirui/time_now_test.go

Created May 24, 2018 03:03
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save nirui/82608ab20e5aac3bd3c1eb5a8f78d23c to your computer and use it in GitHub Desktop.
Save nirui/82608ab20e5aac3bd3c1eb5a8f78d23c to your computer and use it in GitHub Desktop.
Download ZIP
Raw
time_now_test.go
package main
import (
"testing"
"time"
)
func BenchmarkTimeNow(b *testing.B) {
for i := 0; i < b.N; i++ {
time.Now()
}
}
// goos: linux
// goarch: amd64
// BenchmarkTimeNow-2 500000 3758 ns/op
@nirui
Copy link
Author

nirui commented May 24, 2018 •
edited 

(pprof) top 
Showing nodes accounting for 1.17s, 100% of 1.17s total
      flat  flat%   sum%        cum   cum%
     1.16s 99.15% 99.15%      1.16s 99.15%  time.now
     0.01s  0.85%   100%      0.01s  0.85%  time.Now
         0     0%   100%      0.01s  0.85%  BenchmarkTimeNow
         0     0%   100%      0.01s  0.85%  testing.(*B).launch
         0     0%   100%      0.01s  0.85%  testing.(*B).runN

(pprof) list time.now
Total: 1.17s
ROUTINE ======================== time.now in /go/src/runtime/timestub.go
     1.16s      1.16s (flat, cum) 99.15% of Total
         .          .     14:
         .          .     15:func walltime() (sec int64, nsec int32)
         .          .     16:
         .          .     17://go:linkname time_now time.now
         .          .     18:func time_now() (sec int64, nsec int32, mono int64) {
     590ms      590ms     19:	sec, nsec = walltime()
     570ms      570ms     20:	return sec, nsec, nanotime() - startNano
         .          .     21:}

(pprof) weblist nanotime
No source information for nanotime

(pprof) weblist walltime
No source information for walltime

@nirui
Copy link
Author

nirui commented May 24, 2018 •
edited

Discussion on the performance problem: https://groups.google.com/forum/#!topic/golang-nuts/7HybUAvUge4

Much more detail:

Total:       1.16s      1.16s (flat, cum) 97.48%
   11            .          .           package runtime 
   12            .          .            
   13            .          .           import _ "unsafe" // for go:linkname 
   14            .          .            
   15            .          .           //go:linkname time_now time.now 
   16         10ms       10ms           func time_now() (sec int64, nsec int32, mono int64) { 
   17        620ms      620ms           	sec, nsec = walltime() 
                 .          .   4469ed:             CALL runtime.walltime(SB)                                            timestub.go:17
             600ms      600ms   4469f2:             MOVQ 0(SP), AX                                                       timestub.go:17
              10ms       10ms   4469f6:             MOVQ AX, 0x18(SP)                                                    timestub.go:17
              10ms       10ms   4469fb:             MOVL 0x8(SP), CX                                                     timestub.go:17
                 .          .   4469ff:             MOVL CX, 0x14(SP)                                                    timestub.go:17

   18        530ms      530ms           	return sec, nsec, nanotime() - startNano 
                 .          .   446a03:             CALL runtime.nanotime(SB)                                            timestub.go:18
             530ms      530ms   446a08:             MOVQ 0(SP), AX                                                       timestub.go:18
                 .          .   446a0c:             SUBQ runtime.startNano(SB), AX                                       timestub.go:18
                 .          .   446a13:             MOVQ 0x18(SP), CX                                                    timestub.go:18
                 .          .   446a18:             MOVQ CX, 0x30(SP)                                                    timestub.go:18
                 .          .   446a1d:             MOVL 0x14(SP), CX                                                    timestub.go:18
                 .          .   446a21:             MOVL CX, 0x38(SP)                                                    timestub.go:18
                 .          .   446a25:             MOVQ AX, 0x40(SP)                                                    timestub.go:18
                 .          .   446a2a:             MOVQ 0x20(SP), BP                                                    timestub.go:18
                 .          .   446a2f:             ADDQ $0x28, SP                                                       timestub.go:18
                 .          .   446a33:             RET                                                                  timestub.go:18

   19            .          .           }

@nirui
Copy link
Author

nirui commented May 24, 2018 

> go version
go version devel +65c365bf0f Wed May 23 23:51:30 2018 +0000 linux/amd64

> go test -bench . -cpuprofile cpu.out
goos: linux
goarch: amd64
BenchmarkTimeNow-2   	  500000	      3753 ns/op
PASS
ok  	_/tmp/test	2.109s

> go tool pprof test.test cpu.out 
File: test.test
Type: cpu
Time: May 24, 2018 at 9:36pm (CST)
Duration: 2.10s, Total samples = 1.91s (90.78%!)(MISSING)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1910ms, 100% of 1910ms total
      flat  flat%   sum%        cum   cum%
    1890ms 98.95% 98.95%     1890ms 98.95%  time.now
      20ms  1.05%   100%       60ms  3.14%  time.Now
         0     0%   100%       60ms  3.14%  _/tmp/test.BenchmarkTimeNow
         0     0%   100%       60ms  3.14%  testing.(*B).autodetectN
         0     0%   100%       60ms  3.14%  testing.(*B).launch
         0     0%   100%       60ms  3.14%  testing.(*B).runN
(pprof) list time.Now
Total: 1.91s
ROUTINE ======================== time.Now in /home/rany/Development/Tools/go/src/time/time.go
      20ms       60ms (flat, cum)  3.14% of Total
         .          .   1050:// Provided by package runtime.
         .          .   1051:func now() (sec int64, nsec int32, mono int64)
         .          .   1052:
         .          .   1053:// Now returns the current local time.
         .          .   1054:func Now() Time {
      20ms       60ms   1055:	sec, nsec, mono := now()
         .          .   1056:	sec += unixToInternal - minWall
         .          .   1057:	if uint64(sec)>>33 != 0 {
         .          .   1058:		return Time{uint64(nsec), sec + minWall, Local}
         .          .   1059:	}
         .          .   1060:	return Time{hasMonotonic | uint64(sec)<<nsecShift | uint64(nsec), mono, Local}
(pprof) list time.now
Total: 1.91s
ROUTINE ======================== time.now in /home/rany/Development/Tools/go/src/runtime/timestub.go
     1.89s      1.89s (flat, cum) 98.95% of Total
         .          .     12:
         .          .     13:import _ "unsafe" // for go:linkname
         .          .     14:
         .          .     15://go:linkname time_now time.now
         .          .     16:func time_now() (sec int64, nsec int32, mono int64) {
     980ms      980ms     17:	sec, nsec = walltime()
     910ms      910ms     18:	return sec, nsec, nanotime() - startNano
         .          .     19:}
(pprof) exit

> export GOROOT=/tmp/go1.8
> export PATH=/tmp/go1.8/bin
> go version
go version go1.8 linux/amd64

> go test -bench . -cpuprofile cpu.out 
BenchmarkTimeNow-2   	 1000000	      1825 ns/op
PASS
ok  	_/tmp/test	1.853s

> go tool pprof test.test cpu.out 
Entering interactive mode (type "help" for commands)
(pprof) top
1.83s of 1.83s total (  100%)
      flat  flat%   sum%        cum   cum%
     1.78s 97.27% 97.27%      1.78s 97.27%  runtime._ExternalCode
     0.04s  2.19% 99.45%      0.05s  2.73%  time.Now
     0.01s  0.55%   100%      0.01s  0.55%  time.now
         0     0%   100%      0.05s  2.73%  _/tmp/test.BenchmarkTimeNow
         0     0%   100%      1.78s 97.27%  runtime._System
         0     0%   100%      0.05s  2.73%  runtime.goexit
         0     0%   100%      0.05s  2.73%  testing.(*B).launch
         0     0%   100%      0.05s  2.73%  testing.(*B).runN
(pprof) list time.Now
Total: 1.83s
ROUTINE ======================== time.Now in /tmp/go1.8/src/time/time.go
      40ms       50ms (flat, cum)  2.73% of Total
         .          .    792:
         .          .    793:// Provided by package runtime.
         .          .    794:func now() (sec int64, nsec int32)
         .          .    795:
         .          .    796:// Now returns the current local time.
      10ms       10ms    797:func Now() Time {
      20ms       30ms    798:	sec, nsec := now()
      10ms       10ms    799:	return Time{sec + unixToInternal, nsec, Local}
         .          .    800:}
         .          .    801:
         .          .    802:// UTC returns t with the location set to UTC.
         .          .    803:func (t Time) UTC() Time {
         .          .    804:	t.setLoc(&utcLoc)
(pprof) list time.now
Total: 1.83s
ROUTINE ======================== time.now in /tmp/go1.8/src/runtime/sys_linux_amd64.s
      10ms       10ms (flat, cum)  0.55% of Total
         .          .    146:	JEQ	fallback
         .          .    147:	MOVL	$0, DI // CLOCK_REALTIME
         .          .    148:	LEAQ	0(SP), SI
         .          .    149:	CALL	AX
         .          .    150:	MOVQ	0(SP), AX	// sec
      10ms       10ms    151:	MOVQ	8(SP), DX	// nsec
         .          .    152:	MOVQ	AX, sec+0(FP)
         .          .    153:	MOVL	DX, nsec+8(FP)
         .          .    154:	RET
         .          .    155:fallback:
         .          .    156:	LEAQ	0(SP), DI
(pprof)

@nirui
Copy link
Author

nirui commented May 24, 2018 •
edited

Also tested on Go 1.10.2 tarball downloaded directly from Golang website. It still slow but the profile information is differ.

> export GOROOT=/tmp/go1.10.2
> export PATH=/tmp/go1.10.2/bin
> go version
go version go1.10.2 linux/amd64

> go test -bench . -cpuprofile cpu.out
goos: linux
goarch: amd64
BenchmarkTimeNow-2   	  500000	      3632 ns/op
PASS
ok  	_/tmp/test	2.009s

> go tool pprof test.test cpu.out 
File: test.test
Type: cpu
Time: May 24, 2018 at 10:44pm (CST)
Duration: 2s, Total samples = 1.86s (92.86%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1.86s, 100% of 1.86s total
      flat  flat%   sum%        cum   cum%
     1.76s 94.62% 94.62%      1.76s 94.62%  runtime._ExternalCode
     0.04s  2.15% 96.77%      0.04s  2.15%  runtime.nanotime
     0.04s  2.15% 98.92%      0.07s  3.76%  time.now
     0.01s  0.54% 99.46%      0.08s  4.30%  _/tmp/test.BenchmarkTimeNow
     0.01s  0.54%   100%      0.01s  0.54%  runtime.walltime
         0     0%   100%      1.78s 95.70%  runtime._System
         0     0%   100%      0.08s  4.30%  testing.(*B).launch
         0     0%   100%      0.08s  4.30%  testing.(*B).runN
         0     0%   100%      0.07s  3.76%  time.Now
(pprof) list time.Now
Total: 1.86s
ROUTINE ======================== time.Now in /tmp/go1.10.2/src/time/time.go
         0       70ms (flat, cum)  3.76% of Total
         .          .   1039:// Provided by package runtime.
         .          .   1040:func now() (sec int64, nsec int32, mono int64)
         .          .   1041:
         .          .   1042:// Now returns the current local time.
         .          .   1043:func Now() Time {
         .       70ms   1044:	sec, nsec, mono := now()
         .          .   1045:	sec += unixToInternal - minWall
         .          .   1046:	if uint64(sec)>>33 != 0 {
         .          .   1047:		return Time{uint64(nsec), sec + minWall, Local}
         .          .   1048:	}
         .          .   1049:	return Time{hasMonotonic | uint64(sec)<<nsecShift | uint64(nsec), mono, Local}
(pprof) list time.now
Total: 1.86s
ROUTINE ======================== time.now in /tmp/go1.10.2/src/runtime/timestub.go
      40ms       70ms (flat, cum)  3.76% of Total
         .          .     14:
         .          .     15:func walltime() (sec int64, nsec int32)
         .          .     16:
         .          .     17://go:linkname time_now time.now
         .          .     18:func time_now() (sec int64, nsec int32, mono int64) {
      20ms       20ms     19:	sec, nsec = walltime()
      20ms       50ms     20:	return sec, nsec, nanotime() - startNano
         .          .     21:}
(pprof)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment