Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

time: Now is somehow being very slow on Ubuntu 16.04 #33448

Closed
wangcheng711 opened this issue Aug 3, 2019 · 10 comments
Closed

time: Now is somehow being very slow on Ubuntu 16.04 #33448

wangcheng711 opened this issue Aug 3, 2019 · 10 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@wangcheng711
Copy link

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
Copy link
Member

odeke-em commented Aug 4, 2019

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

@odeke-em odeke-em added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Aug 4, 2019
@odeke-em odeke-em changed the title time.now very slow on ubuntu 16.04 time: Now is somehow being very slow on Ubuntu 16.04 Aug 4, 2019
@ianlancetaylor
Copy link
Contributor

Can you show us the program that you are profiling?

@wangcheng711
Copy link
Author

wangcheng711 commented Aug 5, 2019

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
Copy link
Contributor

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
Copy link
Author

wangcheng711 commented Aug 5, 2019

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
Copy link
Author

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
Copy link
Contributor

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
Copy link
Author

wangcheng711 commented Aug 6, 2019

@ianlancetaylor thanks for your suggestion!

@odeke-em
Copy link
Member

odeke-em commented Aug 7, 2019

@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.

@odeke-em odeke-em closed this as completed Aug 7, 2019
@wangcheng711
Copy link
Author

wangcheng711 commented Aug 18, 2019

@ianlancetaylor @odeke-em today, ubuntu 16.04 has update kernel to 4.15.0-58-generic,before is 4.15.0-55-generic
.And i test this program on pc A. program run fine,the output is :

$./exp 
$Worst write time:  4.03869ms 375.277545ms

so, there may be some trouble with kernel 4.15.0-55?

@golang golang locked and limited conversation to collaborators Aug 17, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

4 participants