time: Now is somehow being very slow on Ubuntu 16.04

[wangcheng711]

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

go version go1.12.7 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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/golang/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/golang/gocode:/home/golang/work"
GOPROXY=""
GORACE=""
GOROOT="/home/golang/go"
GOTMPDIR=""
GOTOOLDIR="/home/golang/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build008341203=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Time: Aug 3, 2019 at 5:00pm (CST)
Duration: 4.91s, Total samples = 5s (101.92%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list time.now
Total: 5s
ROUTINE ======================== time.now in /home/golang/go/src/runtime/timestub.go
2.69s 2.70s (flat, cum) 54.00% of Total
. . 11:
. . 12:import _ "unsafe" // for go:linkname
. . 13:
. . 14://go:linkname time_now time.now
. . 15:func time_now() (sec int64, nsec int32, mono int64) {
1.42s 1.42s 16: sec, nsec = walltime()
1.27s 1.28s 17: return sec, nsec, nanotime()
. . 18:}
(pprof) top -cum
Showing nodes accounting for 4.43s, 88.60% of 5s total
Dropped 25 nodes (cum <= 0.03s)
Showing top 10 nodes out of 31
flat flat% sum% cum cum%
2.69s 53.80% 53.80% 2.70s 54.00% time.now
1.67s 33.40% 87.20% 1.71s 34.20% time.Since
0.01s 0.2% 87.40% 0.35s 7.00% main.main
0 0% 87.40% 0.35s 7.00% runtime.main
0.02s 0.4% 87.80% 0.29s 5.80% runtime.makeslice
0.03s 0.6% 88.40% 0.27s 5.40% runtime.mallocgc
0 0% 88.40% 0.19s 3.80% runtime.(*mcache).nextFree
0 0% 88.40% 0.19s 3.80% runtime.(*mcache).refill
0.01s 0.2% 88.60% 0.19s 3.80% runtime.(*mcentral).cacheSpan
0 0% 88.60% 0.18s 3.60% runtime.(*mcentral).grow
(pprof)

What did you expect to see?

What did you see instead?

[odeke-em]

Thank you for this report @wangcheng711 and welcome to the Go project!

That's quite odd, could you please perhaps share as much information about your machine?

• What version of Linux?
• Have you somehow turned off vDSO calls and are using old fashioned system calls?
• How consistently does this happen? At load?
• How can one reproduce it?

I shall kindly page some experts to take a look too @ianlancetaylor @aclements @randall77

[ianlancetaylor]

Can you show us the program that you are profiling?

[wangcheng711]

Thank you for this report @wangcheng711 and welcome to the Go project!

That's quite odd, could you please perhaps share as much information about your machine?

• What version of Linux?

golang@golang-pc:~$ cat /etc/issue
Ubuntu 16.04.6 LTS \n \l

golang@golang-pc:~$ uname -a
Linux golang-pc 4.15.0-55-generic #60~16.04.2-Ubuntu SMP Thu Jul 4 09:03:09 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
golang@golang-pc:~$ 

• Have you somehow turned off vDSO calls and are using old fashioned system calls?

i am not sure, is there some way to check this?

• How consistently does this happen? At load?

it's a program for test gc.
when i run build binary on other pc(Ubuntu server 18.04), it's fine
the pprof output is(Ubuntu server 18.04):
Type: cpu
Time: Aug 5, 2019 at 9:51am (CST)
Duration: 1.31s, Total samples = 1.48s (113.34%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 1030ms, 69.59% of 1480ms total
Showing top 10 nodes out of 76
      flat  flat%   sum%        cum   cum%
     520ms 35.14% 35.14%      520ms 35.14%  runtime.memclrNoHeapPointers
     100ms  6.76% 41.89%      110ms  7.43%  time.now
      90ms  6.08% 47.97%      100ms  6.76%  time.Since
      70ms  4.73% 52.70%      140ms  9.46%  runtime.scanobject
      60ms  4.05% 56.76%      830ms 56.08%  runtime.mallocgc
      50ms  3.38% 60.14%       80ms  5.41%  runtime.(*mheap).freeSpanLocked
      40ms  2.70% 62.84%      170ms 11.49%  runtime.(*mspan).sweep
      40ms  2.70% 65.54%      210ms 14.19%  runtime.sweepone
      30ms  2.03% 67.57%      910ms 61.49%  main.main
      30ms  2.03% 69.59%      660ms 44.59%  runtime.(*mcache).refill

• How can one reproduce it?
  test code

package main

import (
	"fmt"
	"log"
	"os"
	"runtime/pprof"
	"time"
)

type buffer [200000][]byte

func main() {
	f, err := os.Create("cpup.prof")
	if err != nil {
		log.Fatal(err)
	}
	pprof.StartCPUProfile(f)
	defer pprof.StopCPUProfile()

	pstart := time.Now()
	var (
		b     *buffer
		worst time.Duration
	)
	b = new(buffer)
	for i := 0; i < 1000000; i++ {
		start := time.Now()
		item := make([]byte, 1024)
		(*b)[i%200000] = item
		elapsed := time.Since(start)
		if elapsed > worst {
			worst = elapsed
		}
	}
	pruntime := time.Since(pstart)
	fmt.Println("Worst write time: ", worst, pruntime)
}

I shall kindly page some experts to take a look too @ianlancetaylor @aclements @randall77

[ianlancetaylor]

Your program calls time.Now in a tight loop, so it's not all that surprising that it's at the top of the profile.

Since item is not used outside of the loop, I expect that the compiler is simply removing it entirely, so there is no make or GC in this program.

When writing a micro-benchmark like this, always look at the generated code to make sure you are measuring that you think you are measuring. Micro-benchmarks are hard to write correctly.

[wangcheng711]

i have two pc
a(ubuntu desktop 16.04):
Intel(R) Core(TM) i3-3220 CPU @ 3.30GHz
b(ubuntu server 18.04):
Intel(R) Celeron(R) CPU J1900 @ 1.99GHz

the same binary (build on a), the program output is:
a:
Worst write time: 3.084604ms 4.946870825s
b:
Worst write time: 9.099695ms 1.149800703s

why a run so slow?

[wangcheng711]

it's quite odd, pc b is poor, why the total elapse time is small.
i disable gc, here is output
a:

$./exp 
Worst write time:  3.889676ms 4.833879671s
$ GOGC=off ./exp 
Worst write time:  345.506µs 4.609004056s

b:

$./exp 
Worst write time:  18.874639ms 1.170181352s
$ GOGC=off ./exp 
Worst write time:  1.058521ms 530.336465ms

[ianlancetaylor]

I don't think it's going to be very interesting to investigate the behavior of a Go program that just calls time.Now in a tight loop. If you want to dig into it, go ahead, but I'm skeptical that the results will actually help any real programs.

[wangcheng711]

@ianlancetaylor thanks for your suggestion!

[odeke-em]

@wangcheng711 I shall close this as there isn't much actionable here. However, when you get some findings, please feel free to report back and also please don't hesitate to report other issues.