net: SetDeadline performance is poor

[sandyskies]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.10.2 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/svn/jessemjchen/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/svn/jessemjchen"
GORACE=""
GOROOT="/home/svn/go"
GOTMPDIR=""
GOTOOLDIR="/home/svn/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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-build019705885=/tmp/go-build"

What did you do?

I write a server in golang，and I use SetReadDeadline/SetWriteDeadline to set a timeout . But when I benchmark ,and use pprof to get cpu pprof ，I get a bad performance because of this two function.

What did you expect to see?

SetReadDeadline/SetWriteDeadline occupy less cpu time.

What did you see instead?

SetReadDeadline/SetWriteDeadline occupy lots of cpu time.

[ianlancetaylor]

Please show us the whole profile and/or show us the code so that we can recreate the problem ourselves. Thanks.

[sandyskies]

@ianlancetaylor Can I upload the svg file？

[davecheney]

yes, you can uploads the svg file

…

On 5 June 2018 at 16:55, ChenMingjie ***@***.***> wrote: @ianlancetaylor <https://github.com/ianlancetaylor> Can I upload the svg file？ — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#25729 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcA-q5Txv7XYhH-3Lk8XxECDNeyXmhks5t5it2gaJpZM4UaHJP> .

[sandyskies]

@ianlancetaylor @davecheney https://github.com/sandyskies/test/blob/master/profile003.svg

[valyala]

@sandyskies , could you build and profile the same program under go 1.9 ? This may be related to #15133

The svg file shows the program spends 15% of CPU time in a send syscall and 20% of CPU time in conn.SetWriteDeadline. The send syscall is usually fast, so it's usually OK if its' time share is comparable to conn.SetWriteDeadline time share.

It looks like the program calls tars/transport.ConnectHandler.send too frequently (hundreds thousands or even a million calls per second). Probably it would be better optimizing the program by reducing the frequency of tars/transport.ConnectHandler.send calls. For instance, process requests in batches. Additionally, conn.SetWriteDeadline may be called on each connection every timeout / 10 seconds instead of calling it before each send syscall. But even if conn.SetWriteDeadline overhead is completely eliminated, the program will run faster only by 1/(1-0.2) = 1.25 times.

[sandyskies]

@valyala Thanks for the answer. I have run it under go 1.9,and have a worse performance, because of the muti cpu timmer problem in the issue that u mentioned, I have to upgrade to 1.10 . I mentioned in my issue than I am performing a benchmark ,it's a sever and client model, which client send some data to server ,and server simply sends back. transport.ConnectHandler.send is the function that server use to sends the data back to client . Because it is a shot connection ,So I have to use SetDeadline in every socket/connection . Benchmark is use in this case ,so I should not change the program logic I used.

[davecheney]

Hello,

I had an opportunity to spend some time with the OP last week and I believe the following benchmark reproduces the issue they are seeing.

package ptheadwait

import (
        "io"
        "net"
        "testing"
        "time"
)

const BUFSIZ = 4096

func BenchmarkSetDeadline(b *testing.B) {
        l, err := net.Listen("tcp", "127.0.0.1:0")
        check(b, err)
        defer l.Close()
        go func() {
                c, err := l.Accept()
                check(b, err)
                _, err = io.Copy(c, c)
                check(b, err)
        }()
        c, err := net.Dial("tcp", l.Addr().String())
        check(b, err)

        b.ReportAllocs()
        b.SetBytes(BUFSIZ)
        b.ResetTimer()

        var buf [BUFSIZ]byte
        deadline := 1 * time.Second
        for i := 0; i < b.N; i++ {
                c.SetWriteDeadline(time.Now().Add(deadline))
                _, err := c.Write(buf[:])
                check(b, err)
                c.SetReadDeadline(time.Now().Add(deadline))
                _, err = c.Read(buf[:])
                check(b, err)
                deadline += 1 * time.Second
        }
}

func check(tb testing.TB, err error) {
        tb.Helper()
        if err != nil {
                tb.Fatal(err)
        }
}

On this laptop I see 18.95% of the time spent in pthread_cond_wait

zapf(~/src/pthreadwait) % go test -bench=.  -benchtime=5s -cpuprofile=c.p
goos: darwin
goarch: amd64
pkg: pthreadwait
BenchmarkSetDeadline-4            200000             37122 ns/op         110.34 MB/s         320 B/op          4 allocs/op
PASS
ok      pthreadwait     8.021s
zapf(~/src/pthreadwait) % go tool pprof -png c.p
Generating report in profile001.png

% go version
go version devel +2e9f0817f0 Tue Oct 30 04:39:53 2018 +0000 darwin/amd64

From the spelunking the OP and I did my interpretation of the trace is thrashing between the goroutine that owns the timer and the main goroutine which is needs to wake the former so it can wrestle control of the lock over the timer wheel.

[davecheney]

Some results on a different laptop

(~/src/pthreadtest) % go1.9 test -bench=. -cpu=1,2,4,8 -benchtime=5s
goos: darwin
goarch: amd64
pkg: pthreadtest
BenchmarkSetDeadline              200000             35134 ns/op         116.58 MB/s         288 B/op          4 allocs/op
BenchmarkSetDeadline-2            200000             34476 ns/op         118.80 MB/s         288 B/op          4 allocs/op
BenchmarkSetDeadline-4            200000             30776 ns/op         133.09 MB/s         288 B/op          4 allocs/op
BenchmarkSetDeadline-8            200000             30638 ns/op         133.69 MB/s         288 B/op          4 allocs/op
PASS
ok      pthreadtest     27.563s
(~/src/pthreadtest) % go1.11 test -bench=. -cpu=1,2,4,8 -benchtime=5s
goos: darwin
goarch: amd64
pkg: pthreadtest
BenchmarkSetDeadline              200000             37773 ns/op         108.44 MB/s         320 B/op          4 allocs/op
BenchmarkSetDeadline-2            200000             37212 ns/op         110.07 MB/s         320 B/op          4 allocs/op
BenchmarkSetDeadline-4            200000             33654 ns/op         121.71 MB/s         320 B/op          4 allocs/op
BenchmarkSetDeadline-8            200000             33783 ns/op         121.24 MB/s         320 B/op          4 allocs/op
PASS
ok      pthreadtest     29.961s

/cc @ianlancetaylor @dvyukov

[dvyukov]

A bunch of things to improve here. I am on it.