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

[agnivade]

I am unable to reproduce this. Both programs show 5-6% CPU for me. And I have 4 CPUs. When you say 20-25%, how many CPUs do you have ?

[lni]

As described, all reported % figures are per process %CPU value reported in top.

I tried two servers, one with dual E5-2690v2 (10 cores X 2 with HT) and another server with a single E5-2696v4 (22 cores X 1 with HT). Other people have confirmed high CPU usage on their Mac OS machines as well, see below.

https://groups.google.com/forum/#!topic/golang-nuts/_XEuq69kUOY

[djadala]

Hi,
Same here,
Linux 4.9.0-8-amd64 #1 SMP Debian 4.9.110-3+deb9u4 (2018-08-21) x86_64 GNU/Linux,
4x AMD Phenom(tm) II X4 965 Processor,

top:

Tasks: 362 total,   1 running, 361 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.8 us,  0.4 sy,  0.0 ni, 98.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8142260 total,   607488 free,  2363780 used,  5170992 buff/cache
KiB Swap:  4194300 total,  4144460 free,    49840 used.  5385516 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                   
 1689 djadala   20   0    2476    708    520 S  22.8  0.0   0:01.90 ticker1                                                   

go version:
go version go1.10.3 linux/amd64

ticker1.go:

package main

import (
	"time"
)

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

[bcmills]

Dup of #25471?

[mbyio]

Percentage of CPU use is not very specific. Can you describe how it is actually affecting you? Is it preventing the program from working correctly somehow? Go is not necessarily specifically optimized for minimal CPU usage.

[bcmills]

Can you describe how it is actually affecting you? Is it preventing the program from working correctly somehow?

On a laptop or other mobile device, percentage of CPU is more-or-less equivalent to battery lifetime. We should not waste users' battery capacity needlessly.

(Using a lot more CPU than expected in a real program is a problem in and of itself: it doesn't need extra justification.)

[choleraehyq]

@bcmills I'd like to implement time.Ticker with timerfd to solve this issue, but timerfd_* APIs are merged into kernel 2.6.24, as our minimal kernel requirement is 2.6.23. When can we drop support of kernel 2.6.23?

[bcmills]

When can we drop support of kernel 2.6.23?

For that, you should probably file a proposal.

[ianlancetaylor]

@choleraehyq Can you sketch out how using the timerfd functions will help? It's not immediately obvious to me. Thanks.

[gmox]

I can confirm this behavior. It looks as if NewTicker is leaving futex locks open, and that drives up CPU/memory usage. Using After does not result in increased CPU/memory usage.

[djadala]

Hi,

Using After does not result in increased CPU/memory usage

Please include code that you use to measure.
Here is my code, sleep & timer use 10%cpu, ticker use 20%cpu :

package main

import (
	"flag"
	"fmt"
	"time"
)

func ticker() {

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

func timer() {
	t := time.NewTimer(time.Millisecond)
	for range t.C {
		t.Reset(time.Millisecond)
	}
}

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

func main() {
	t := flag.String("t", "timer", "use timer")
	flag.Parse()
	switch *t {
	case "timer":
		timer()
	case "ticker":
		ticker()
	case "sleep":
		sleep()
	default:
		fmt.Println("use  timer, ticker or sleep")
	}
}

I think that 10% is also high cpu usage.

[lni]

I tried djadala's program above on an Amazon EC2 a1.medium node with 1 ARM Cortex-A72 core, OS is Ubuntu 18.04LTS with a 4.15.0-1028-aws kernel, Go arm64 version 1.11.2. Interestingly, the CPU usage is only around 3% for ticker/timer/sleep.

[djadala]

for reference i included syscall and cgo variants, cgo use 2% cpu, and syscall use 12%

package main

import (
	"flag"
	"fmt"
	"time"

	"syscall"
)

// #include <unistd.h>
// //#include <errno.h>
// //int usleep(useconds_t usec);
import "C"

func usleep() {
	for {
		C.usleep(1000)
	}
}

func sysns() {
	for {
		v := syscall.Timespec{
			Sec:  0,
			Nsec: 1000,
		}
		syscall.Nanosleep(&v, &v)
	}
}

func ticker() {

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

func timer() {
	t := time.NewTimer(time.Millisecond)
	for range t.C {
		t.Reset(time.Millisecond)
	}
}

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

func main() {
	t := flag.String("t", "timer", "use timer")
	flag.Parse()
	switch *t {
	case "timer":
		timer()
	case "ticker":
		ticker()
	case "sleep":
		sleep()
	case "cgo":
		usleep()
	case "sys":
		sysns()
	default:
		fmt.Println("use  timer, ticker, sys, cgo or sleep")
	}
}

[robaho]

I did some testing on this, comparing Go, C, and Java. The Go uses time.Sleep(), C uses usleep(), and Java uses LockSupport.ParkNanos(). Interestingly, Java and Go use the same 'timeout on semaphore' to implement. The following shows CPU utilization (on OSX).

System	1 us	100 us	1 ms
Go	130%	23.0%	4.6%
Java	67%	6.0 %	1.5%
C	42%	0.6 %	0.0%

I believe the performance issue in Go is due to multiple threads being involved (the timerproc, and the user routine) causing a lot of overhead.

The simplest solution, although it doesn't work for channel select timeout, would be to have short duration time.Sleep() just invoke usleep(). There are probably very few threads using timers of this duration, so the overhead of allocating and blocking the thread shouldn't be that great. I would expect the resulting runtime to be superior to Java and on par with C.

In fact, it is doubtful a sleep request for less than 10 us should even sleep at all - just call runtime.Gosched() since the overhead of a context switch is probably longer than the sleep request.

[robaho]

I did some more testing by writing a CGo function USleep that calls C's usleep directly.

System	1 us	100 us	1 ms
CGo	50%	5.3%	1.3%

So this appears to be a viable alternative for polling with a short interval and low polling routine count.

[networkimprov]

@ianlancetaylor maybe this could be assigned to someone?

[ianlancetaylor]

I can't tell anybody to do anything. I can assign it to someone but that doesn't mean anything will happen.

Rereading this I would like to double-check that there is still something to do here. @dvyukov sped up the timer code quite a bit in the 1.12 release while working on #25729. To what extent is this still a problem?

[dvyukov]

We still handle timers on a separate thread, so there are like 4 excessive thread context switches per timer. Timers need to be part of scheduler/netpoll, i.e. call epoll_wait with the timers timeout.

[ianlancetaylor]

I wonder if it would make sense to say that if we call time.Sleep for a time <= 10 milliseconds, and the number of active goroutines is <= GOMAXPROCS, then we should just sleep rather than going through the timer thread. That might handle microbenchmarks like this, including client programs, without compromising servers. (I chose 10 milliseconds based on sysmon).

[robaho]

That was my proposal - I think it is a good one :) but I think 10 ms might be too high. Although I could see reasonable per platform defaults with an environment variable to override for special cases.

…

On Mar 8, 2019, at 8:30 AM, Ian Lance Taylor ***@***.***> wrote: I wonder if it would make sense to say that if we call time.Sleep for a time <= 10 milliseconds, and the number of active goroutines is <= GOMAXPROCS, then we should just sleep rather than going through the timer thread. That might handle microbenchmarks like this, including client programs, without compromising servers. (I chose 10 milliseconds based on sysmon). — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[ChrisHines]

This issue sounds similar to what I described in #28808. In that issue a lot of the unexpected CPU load was due to the work stealing code in the scheduler after goroutines go to sleep.

It would be nice if we could reduce that CPU load when there are short lived timers pending.

I wonder if it would make sense to say that if we call time.Sleep for a time <= 10 milliseconds, and the number of active goroutines is <= GOMAXPROCS, then we should just sleep rather than going through the timer thread.

What do you mean by "active goroutines <= GOMAXPROCS"? Does active mean "existing" or does it mean "in a runnable state"?

[gopherbot]

Change https://golang.org/cl/204800 mentions this issue: runtime: wake netpoller when dropping P, don't sleep too long in sysmon

[gopherbot]

Change https://golang.org/cl/206938 mentions this issue: runtime: acquire timersLocks around moveTimers

[gopherbot]

Change https://golang.org/cl/207348 mentions this issue: runtime: release timersLock while running timer

[ianlancetaylor]

The new timer code is committed for 1.14. This code reduces lock contention and context switches for timers. This seems to have a clearly beneficial effect for real programs.

With regard to this issue, these changes reduce the CPU requirements for the simple ticker program. They don't seem to affect the simple sleep program very much. Leaving this issue open for further investigation.

[robaho]

Great work !

[gopherbot]

Change https://golang.org/cl/209580 mentions this issue: runtime: use current P's race context in timer code

[gopherbot]

Change https://golang.org/cl/232298 mentions this issue: runtime: reduce timer latency

[ChrisHines]

While responding to review comments by @ianlancetaylor on https://golang.org/cl/232298 I discovered that it appears to improve the issue reported here. Specifically I compiled the following program with Go 1.13, 1.14 and that CL.

package main

import (
  "time"
)

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

I ran all three builds on the same machine at the same time. The machine has 56 hardware threads and was mostly idle. The OS is CentOS 7.4.1708.

With that setup top reported the following typical %CPU (of one hardware thread) for each program:

• Go 1.13: 9.6%
• Go 1.14: 11.6%
• CL 232298: 6.9%

So there is at least some evidence that the CL provides an improvement over both old and new timers.

[bukowa]

I don't know if this is related but i myself experienced high CPU usage while not using sleep. This is one of my loops. Without sleep in default case and 50 goroutines running below loop all 24 threads are at 100%. With sleep it's less than 0.2%.

for {
			select {
			default:
				// unnoticeable sleep to prevent high cpu usage
				time.Sleep(time.Microsecond)

			case <-exit:
				// crawler has completed
				return

			case response := <-crawl.Crawler.ResponseChan:
}

[andig]

Without the sleep your for/select loop will spin the default case, so this is expected. The code above would probably work fine with the default case removed entirely.

[LeGamerDc]

maybe heap structure is too heavy incase many goroutine is using timer/ticker/sleep and each with small sleep time(like < 10ms). i see much time used in siftdownTimer maintain the heap structure.
what if use timer wheel structure for small timer, or new timer lib might be same good.

also, i noticed that much time used in runtime.casgstatus doing cas, comment said its give way to goroutine gc. however, even i disable gc, the cas loop still use much time.

simple code are:

import _ "net/http/pprof"

func main() {
        for i := 0; i < 10000; i++ {
                go func() {
                        for {
                                time.Sleep(time.Millisecond * 5)
                        }
                }()
        }
        debug.SetGCPercent(-1)
        runtime.GC()
        fmt.Println(http.ListenAndServe("localhost:8081", nil))
}