time: excessive CPU usage when using Ticker and Sleep

[lni]

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

go1.11 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

GOARCH="amd64" GOBIN="" GOCACHE="/home/lni/.cache/go-build" GOEXE="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOOS="linux" GOPATH="/home/lni/golang_ws" GOPROXY="" GORACE="" GOROOT="/usr/local/go" GOTMPDIR="" GOTOOLDIR="/usr/local/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-build440058908=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I need to call a function roughly every millisecond, there is no real time requirement, as long as it is called roughly every millisecond everything is fine. However, I realised that both time.Ticker and time.Sleep() are causing excessive CPU overhead, probably due to runtime scheduling.

The following Go program uses 20-25% %CPU as reported by top on Linux.

package main

import (
  "time"
)

func main() {
  ticker := time.NewTicker(time.Millisecond)
  defer ticker.Stop()
  for {
    select {
    case <-ticker.C:
    }
  }
}

for loop with range is causing similar overhead

package main

import (
  "time"
)

func main() {
  ticker := time.NewTicker(time.Millisecond)
  defer ticker.Stop()
  for range ticker.C {
  }
}

while the following program is showing 10-15% %CPU in top

package main

import (
  "time"
)

func main() {
  for {
    time.Sleep(time.Millisecond)
  }
}

To workaround the issue, I had to move the ticker/sleep part to C and let the C code to call the Go function that need to be invoked every millisecond. Such a cgo based ugly hack reduced %CPU in top to 2-3%. Please see the proof of concept code below.

ticker.h

#ifndef TEST_TICKER_H
#define TEST_TICKER_H

void cticker();

#endif // TEST_TICKER_H

ticker.c

#include <unistd.h>
#include "ticker.h"
#include "_cgo_export.h"

void cticker()
{
  for(int i = 0; i < 30000; i++)
  {
    usleep(1000);
    Gotask();
  }
}

ticker.go

package main

/*
#include "ticker.h"
*/
import "C"
import (
  "log"
)

var (
  counter uint64 = 0
)

//export Gotask
func Gotask() {
  counter++
}

func main() {
  C.cticker()
  log.Printf("Gotask called %d times", counter)
}

What did you expect to see?

Much lower CPU overhead when using time.Ticker or time.Sleep()

What did you see instead?

20-25% %CPU in top

[gopherbot]

Change https://golang.org/cl/169970 mentions this issue: runtime: add new resettimer function

[gopherbot]

Change https://golang.org/cl/169965 mentions this issue: runtime: steal timers from unpreemptible P's

[gopherbot]

Change https://golang.org/cl/169963 mentions this issue: runtime: wake sleeping P when there are no idle P's

[gopherbot]

Change https://golang.org/cl/170099 mentions this issue: runtime: implement time.Sleep for new timers

[gopherbot]

Change https://golang.org/cl/169962 mentions this issue: runtime: initial support for timers in P's

[gopherbot]

Change https://golang.org/cl/169969 mentions this issue: runtime: add new modtimer function

[gopherbot]

Change https://golang.org/cl/169974 mentions this issue: runtime: add new adjusttimers function

[gopherbot]

Change https://golang.org/cl/169968 mentions this issue: runtime: add new deltimer function

[gopherbot]

Change https://golang.org/cl/169961 mentions this issue: runtime, syscall, time: add and use resettimer

[gopherbot]

Change https://golang.org/cl/169971 mentions this issue: runtime: add new dodeltimer and dodeltimer0 functions

[gopherbot]

Change https://golang.org/cl/169976 mentions this issue: runtime: update timejump function for new timers

[gopherbot]

Change https://golang.org/cl/170098 mentions this issue: runtime: add race detector support for new timers

[gopherbot]

Change https://golang.org/cl/169967 mentions this issue: runtime: add new addtimer function

[gopherbot]

Change https://golang.org/cl/170097 mentions this issue: runtime: add osRelax support for new timers

[gopherbot]

Change https://golang.org/cl/169966 mentions this issue: runtime, syscall, time: prepare for adding timers to P's

[gopherbot]

Change https://golang.org/cl/169964 mentions this issue: runtime: when shrinking number of P's, move timers

[gopherbot]

Change https://golang.org/cl/170101 mentions this issue: runtime, syscall, time: remove old timer code

[gopherbot]

Change https://golang.org/cl/170100 mentions this issue: runtime: switch to using new timer code

[networkimprov]

@ianlancetaylor, curious to hear the patchset's results for the tests posted previously here...

[ianlancetaylor]

I'm reworking the patches based on suggestions from @dvyukov .

The tests that I see posted in this issue are somewhat imprecise, in that they discuss how much CPU time is used based on looking in top. On that basis, my earlier patchset is somewhat better but not all that much better. Most of the CPU time that I see reported by top is actually the system monitor thread, which wakes up every 10ms to see if there is anything to do. So while I continue to think that the patches I'm working on will be beneficial, I do not expect them to make a large difference on CPU time as shown by top. I'm not sure how useful that measurement is, and I don't know if there is a way to help very simple programs like the ones shown without hurting more realistic programs. In any case I suspect that tackling it will require a somewhat different approach, orthogonal to this patch set.

I do not intend to close this issue even if my patches are committed to the tree.

[robaho]

I don’t think that analysis of the existing tests is correct. If the majority of the cpu was used by the sysmon thread that is constant at 10 ms, then there would not be a huge change in cpu measurement as the polling interval changed.

On Apr 6, 2019, at 1:25 PM, Ian Lance Taylor notifications@github.com wrote:

I'm reworking the patches based on suggestions from @dvyukov .

The tests that I see posted in this issue are somewhat imprecise, in that they discuss how much CPU time is used based on looking in top. On that basis, my earlier patchset is somewhat better but not all that much better. Most of the CPU time that I see reported by top is actually the system monitor thread, which wakes up every 10ms to see if there is anything to do. So while I continue to think that the patches I'm working on will be beneficial, I do not expect them to make a large difference on CPU time as shown by top. I'm not sure how useful that measurement is, and I don't know if there is a way to help very simple programs like the ones shown without hurting more realistic programs. In any case I suspect that tackling it will require a somewhat different approach, orthogonal to this patch set.

I do not intend to close this issue even if my patches are committed to the tree.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[dvyukov]

Doing a limited amount of work every 10ms should not produce any visible CPU consumption on Linux. But sysmon base frequency is 20us, at that frequency it can consume ~10% of a CPU. But it can cool down to 10ms as well. Which one do you mean? 20us? In a synthetic time.Sleep loop test, sysmon should be able to cool down to 10ms and stop consuming CPU.

[networkimprov]

Maybe relevant: https://github.com/golang/go/issues/18236#issuecomment-265600185 - frequent blocking syscalls cause high sysmon overhead

[robaho]

@dvyukov I was referring to @ianlancetaylor comment where that was stated. Not sure if your comment was to me or him.

[dvyukov]

At least to @ianlancetaylor. I don't fully understand your comment (what analysis? what polling interval change?), so I don't know if it applies to your comment or not :)

[robaho]

The perf polling timings I reported had intervals of 1 ms, 100 us and 1 us. That is the “changes”.

Ian commented that “most of the cpu that I see reported by top is due to the sysmon polling thread ... wakes up every 10 ms” and so was suspect of the timings I reported I assume.

I was arguing that I could not rectify Ian’s analysis with my timings.

[ianlancetaylor]

Sorry, I should have made clear that I didn't do a serious analysis, and that I could be wrong.

I ran the program under the GNU/Linux perf tool and looked at where it was spending its CPU time. It seemed to be in the sysmon thread. But I didn't look any further.

[dvyukov]

I ran the program under the GNU/Linux perf tool and looked at where it was spending its CPU time. It seemed to be in the sysmon thread. But I didn't look any further.

We could extend schedtrace facility to print the current sysmon frequency (and maybe some timers state). Historically it was a very useful thing to understand actual scheduler state in benchmarks and real programs, which is also very easy to use. E.g. it would immediate answer the question: does sysmon cool down to 10ms in this particular benchmark, or something unexpected holds it at 20us?

[gopherbot]

Change https://golang.org/cl/171824 mentions this issue: runtime: add netpollBreak and netpollReset

[gopherbot]

Change https://golang.org/cl/171877 mentions this issue: runtime: add new adjusttimers function

[gopherbot]

Change https://golang.org/cl/171827 mentions this issue: runtime: add wasm support for timers on P's

[gopherbot]

Change https://golang.org/cl/171829 mentions this issue: runtime, syscall, time: prepare for adding timers to P's

[gopherbot]

Change https://golang.org/cl/171833 mentions this issue: runtime: add new resettimer function

[gopherbot]

Change https://golang.org/cl/171879 mentions this issue: runtime: implement time.Sleep for new timers

[gopherbot]

Change https://golang.org/cl/171830 mentions this issue: runtime: add new addtimer function

[gopherbot]

Change https://golang.org/cl/171878 mentions this issue: runtime: add new runtimer function

[gopherbot]

Change https://golang.org/cl/171883 mentions this issue: runtime: switch to using new timer code

[gopherbot]

Change https://golang.org/cl/171828 mentions this issue: runtime: handle timers on P's in procresize

[gopherbot]

Change https://golang.org/cl/171823 mentions this issue: runtime: change read and write to return negative errno value

[gopherbot]

Change https://golang.org/cl/171834 mentions this issue: runtime: add new dodeltimer and dodeltimer0 functions

[gopherbot]

Change https://golang.org/cl/171881 mentions this issue: runtime: implement timeSleepUntil for new timers

[gopherbot]

Change https://golang.org/cl/171826 mentions this issue: runtime: initial scheduler changes for timers on P's

[gopherbot]

Change https://golang.org/cl/171882 mentions this issue: runtime: add race detector support for new timers

[gopherbot]

Change https://golang.org/cl/171880 mentions this issue: runtime: update timejump function for new timers

[gopherbot]

Change https://golang.org/cl/171835 mentions this issue: runtime: add new cleantimers function

[gopherbot]

Change https://golang.org/cl/171836 mentions this issue: runtime: implement new movetimers function

[gopherbot]

Change https://golang.org/cl/171825 mentions this issue: runtime, syscall, time: add and use resettimer

[gopherbot]

Change https://golang.org/cl/171832 mentions this issue: runtime: add new modtimer function

[gopherbot]

Change https://golang.org/cl/171821 mentions this issue: runtime: change netpoll to take an amount of time to block

[gopherbot]

Change https://golang.org/cl/171884 mentions this issue: runtime, syscall, time: remove old timer code