Created
May 24, 2018 03:03
-
-
Save nirui/82608ab20e5aac3bd3c1eb5a8f78d23c to your computer and use it in GitHub Desktop.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| 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 |
Author
nirui
commented
May 24, 2018
•
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 . . }
> 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)
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