runtime: unnecessary return in netpoll

[zhouguangyuan0718]

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

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

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/root/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/root/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/mnt/d/00.Tool/00.golang/go1.17"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/mnt/d/00.Tool/00.golang/go1.17/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.1"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/mnt/d/01.Project/03.go_performance/demo/go.mod"
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-build2033964888=/tmp/go-build -gno-record-gcc-switches"

What did you do?

server.go:

package main

import (
	"log"
	"net"
	"net/http"
	_ "net/http/pprof"
	"time"
)

func init() {
	go func() {
		http.ListenAndServe("127.0.0.1:6060", nil)
	}()
	// backend
	go func() {
		http.ListenAndServe("127.0.0.1:6061", nil)
	}()
}

func main() {

	l, err := net.Listen("tcp", "127.0.0.1:3000")
	if err != nil {
		panic(err)
	}
	for {
		c, err := l.Accept()
		if err != nil {
			panic(err)
		}
		r := make([]byte, 50)
		for {
			time.Sleep(50 * time.Millisecond)
			n, err := c.Read(r)
			log.Println(n, err)
		}
	}
}

client.go

package main

import (
	"net"
	"time"
)

func main() {
	c, err := net.Dial("tcp", "127.0.0.1:3000")
	if err != nil {
		panic(err)
	}
	for {
		time.Sleep(time.Millisecond)
		c.Write([]byte{'c'})
	}
}

And excute these command:

$ go run server.go
$ go run client.go
$ curl  http://127.0.0.1:6060/debug/pprof/trace?seconds=5 -o trace.data
$ go tool trace trace.data

What did you expect to see?

In trace view, the event "proc start" and "proc stop" should appear every 50 ms because of time.Sleep(50 * time.Millisecond).

What did you see instead?

The event "proc start" and "proc stop" appears every 1 ms because of client sends data every 1 ms.

[gopherbot]

Change https://golang.org/cl/356253 mentions this issue: runtime: reduce unnecessary return in netpoll

[cherrymui]

Could you explain more about why the return is unnecessary and why "[it] should appear every 50 ms"? What specific problem in real programs does it cause? Thanks.

cc @ianlancetaylor

[zhouguangyuan0718]

Could you explain more about why the return is unnecessary

“unnecessary” means that when the function netpoll return, there is no goroutine to run, no timer to run and the epollwait is not broken by "netpollbreak".

This situation occurs when the epollwait is broken by network data, but there is no goroutine is blocking on it, like the main funtion in server.go above. It sleep 50ms, then read some data from socket in the loop. If the data reached when it is sleeping, the epollwait will be broken and will return from netpoll. Then it will block on epollwait again. This return is unnecessary.

and why "[it] should appear every 50 ms"?

The main goroutine invoke time.Sleep(50 * time.Millisecond) in the loop, "proc start" every 50 ms is enough to wake up the main goroutine.

What specific problem in real programs does it cause?

This issue is about performance. Reducing the unnecessary return can reduce CPU usage.

[harshavardhana]

This issue is about performance. Reducing the unnecessary return can reduce CPU usage.

how is this measured? - is there a way to test this?

[And-ZJ]

I did a comparison test.

Test environment:

# go version
go version go1.17.2 linux/amd64

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/Hote/h/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/Hote/h"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr1/zhangjian/Go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr1/zhangjian/Go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.2"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="0"
GOMOD="/dev/null"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build583515172=/tmp/go-build -gno-record-gcc-switches

Test Code:

(1) server.go

package main

import (
	"log"
	"net"
	"net/http"
	_ "net/http/pprof"
	"time"
)

func init() {
	go func() {
		http.ListenAndServe("127.0.0.1:6060", nil)
	}()
	// backend
	go func() {
		http.ListenAndServe("127.0.0.1:6061", nil)
	}()
}

func main() {
	l, err := net.Listen("tcp", "127.0.0.1:3000")
	if err != nil {
		panic(err)
	}

	r := make([]byte, 1000)
	c, err := l.Accept()
	if err != nil {
		panic(err)
	}
	// Reads 600 times, sleeps for 50ms each time, and runs for about 30s.
	for i := 0; i < 600; i++ {
		time.Sleep(50 * time.Millisecond)
		if _, err := c.Read(r); err != nil {
			log.Println(err)
			break
		}
	}
	if err := c.Close(); err != nil {
		log.Println(err)
	}
}

(2) client.go

package main

import (
	"log"
	"net"
	_ "unsafe"
)

func main() {
	log.Println("tcp client start")
	for {
		c, err := net.Dial("tcp", "127.0.0.1:3000")
		if err != nil {
			// run client first, client will try to connect server.
			// sleep 200us for avoid high CPU usage.
			usleep(200)
			continue
		}
		for {
			usleep(200)
			if _, err := c.Write([]byte{'c'}); err != nil {
				log.Println(err)
				break
			}
		}
		if err := c.Close(); err != nil {
			log.Println(err)
		}
	}
}

//go:linkname usleep runtime.usleep
func usleep(usec uint32)

(3) stub.s

This file is empty.

Tests

Compilation and Test Commands:

Client and server code run separately to avoid client perturbation of server testing.

# run client first
go run client.go stub.s

# build server
go build server.go

# run and test server CPU usage
time ./server

Compile and test using go1.17.2. The results of the five tests are as follows:

real	0m30.146s
user	0m0.204s
sys	0m0.756s

real	0m30.150s
user	0m0.214s
sys	0m0.791s

real	0m30.145s
user	0m0.177s
sys	0m0.786s

real	0m30.152s
user	0m0.196s
sys	0m0.782s

real	0m30.156s
user	0m0.221s
sys	0m0.872s

Average of five tests:

real	30.1498s
user	0.2024s
sys	0.7974s

Compile and test using go1.17.2+CL356253(Patchset 4).The results of the five tests are as follows:

real	0m30.153s
user	0m0.076s
sys	0m0.795s

real	0m30.163s
user	0m0.071s
sys	0m0.905s

real	0m30.148s
user	0m0.055s
sys	0m0.824s

real	0m30.147s
user	0m0.067s
sys	0m0.778s

real	0m30.142s
user	0m0.051s
sys	0m0.800s

Average of five tests:

real	30.1506s
user	0.064s
sys	0.8204s

According to the test results, after using CL356253(Patchset 4), the user CPU time decreases by about 0.1384s, while the sys CPU time increases by only about 0.023s. The user CPU time benefits more.

[zhouguangyuan0718]

@cherrymui @harshavardhana
Thers is is a little bit decrease of CPU usage for the result of this test.
Should we accept this optimization for netpoll?