search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
123.52k stars 17.6k forks source link

benchmark output meaning? #32523

Closed shaocongliang closed 5 years ago

shaocongliang commented 5 years ago

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

$ go version go1.9.4 linux/amd64

Does this issue reproduce with the latest release?

not sure

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

go env Output
$ go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/scliang/go:/home/scliang/iot"
GORACE=""
GOROOT="/usr/lib/golang"
GOTOOLDIR="/usr/lib/golang/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build640120252=/tmp/go-build -gno-record-gcc-switches"
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"

What did you do?

Run a benchmark case but the output time makes me feel puzzled. 

proto: duplicate proto type registered: device.LoginRequest
proto: duplicate proto type registered: device.LoginReply
proto: duplicate proto type registered: device.LogoutRequest
proto: duplicate proto type registered: device.LogoutReply
proto: duplicate proto type registered: device.PushRequest
proto: duplicate proto type registered: device.PushReply
proto: duplicate proto type registered: device.UploadRequest
proto: duplicate proto type registered: device.UploadReply
proto: duplicate proto type registered: device.PostRequest
proto: duplicate proto type registered: device.PostReply
goos: linux
goarch: amd64
pkg: gitlab.xfyun.cn/XIoT/core/test/rpc
BenchmarkPropertyDownload-48               5     252492668 ns/op
PASS
ok      gitlab.xfyun.cn/XIoT/core/test/rpc  3.828s

This bench case need some extra init job so I reset the timer. Here is the partial code

func BenchmarkPropertyDownload(b *testing.B) {
    flag.Parse()
    dvclist := getDevices(*numOfDvc)
    URL := protocol + *domainName + "/api/v1/commands/obtain/properties"
    perTimes := *numOfTimes / len(dvclist)
    var wg sync.WaitGroup
    b.ResetTimer()
    for i := 0; i < b.N; i++ {
        for j := 0; j < len(dvclist); j++ {
            go quest(&wg, perTimes, dvclist[j], URL)
        }
    }
    wg.Wait()
}

"ok" time is 3.828 and the "Download" time is 252492668*5 ~= 1.7s. Obviously there is a big gap. What's the meaning of "ok" time? The whole time of this bench execution? Or the time after reset timer?

One possible reason of the difference in "ok" and "Download" I think may be due to wg.Wait() . So I add a sleep statement after the wg.Wait()

     wg.Wait()
     time.Sleep(5*time.Second)

Here is the output 

proto: duplicate proto type registered: device.LoginRequest
proto: duplicate proto type registered: device.LoginReply
proto: duplicate proto type registered: device.LogoutRequest
proto: duplicate proto type registered: device.LogoutReply
proto: duplicate proto type registered: device.PushRequest
proto: duplicate proto type registered: device.PushReply
proto: duplicate proto type registered: device.UploadRequest
proto: duplicate proto type registered: device.UploadReply
proto: duplicate proto type registered: device.PostRequest
proto: duplicate proto type registered: device.PostReply
goos: linux
goarch: amd64
pkg: gitlab.xfyun.cn/XIoT/core/test/rpc
BenchmarkPropertyDownload-48               1    5297783950 ns/op
PASS
ok      gitlab.xfyun.cn/XIoT/core/test/rpc  6.201s

Why is the "Download" time increasing a lot?

Add a sleep before b.ResetTimber()

time.Sleep(5*time.Second)
b.ResetTimer()
proto: duplicate proto type registered: device.LoginRequest
proto: duplicate proto type registered: device.LoginReply
proto: duplicate proto type registered: device.LogoutRequest
proto: duplicate proto type registered: device.LogoutReply
proto: duplicate proto type registered: device.PushRequest
proto: duplicate proto type registered: device.PushReply
proto: duplicate proto type registered: device.UploadRequest
proto: duplicate proto type registered: device.UploadReply
proto: duplicate proto type registered: device.PostRequest
proto: duplicate proto type registered: device.PostReply
goos: linux
goarch: amd64
pkg: gitlab.xfyun.cn/XIoT/core/test/rpc
BenchmarkPropertyDownload-48               5     257106071 ns/op
PASS
ok      gitlab.xfyun.cn/XIoT/core/test/rpc  18.950s

18.950?

What did you expect to see?

May be you can give a link page explain the output meaning of test.bench. I can't find on https://golang.org/pkg/testing/

What did you see instead?

ianlancetaylor commented 5 years ago

The "ok" time is the total time it takes to run the test program. The time reported for the benchmark is the approximate time it takes to run just that code. The "ok" time is reported mainly for interest when running non-benchmark tests. When only running benchmarks, you may as well ignore it.

I'm going to close this issue because there is nothing to do. In general we don't use the issue tracker for questions, and you will get better answers on a forum. See https://golang.org/wiki/Questions.