runtime: general runtime slowdown from 1.3 to 1.4 to 1.5

[gopherbot]

by dippo6905:

I tested release 1.4rc1 and i noticed very slow performance compared to version 1.3. The
code runs almost twice as slow compared to version 1.3. The only thing i noticed is that
when a Go routine is started the performance drops, even when a Go routine almost
contains nothing, it still drops.

This is the code i was currently working on :

package main

import (
    "fmt"
    "time"
)

func main() {
    start := time.Now()
    input := make(chan int)
    output := input
    err := make(chan bool)
    errormsg := make(chan error)
    go func(c chan int) { c <- 1 }(input)
    for {
        go func(input <-chan int, output chan<- int, err chan<- bool, errormsg chan<- error) {
            err <- false
            value := <-input
            value++
            output <- value
            if value == 100000 {
                err <- true
                errormsg <- fmt.Errorf("An error arise with output containing : %v", value)
            }
        }(input, output, err, errormsg)
        if <-err {
            break
        }
        input = output
    }
    e := <-errormsg
    if e != nil {
        fmt.Println(e)
    }
    fmt.Printf("Took %v to run.\n", time.Since(start))
}

This code is just a toy to test what Go is good at, concurrent programming and channels.
This example is just a "over the top" daisychain of channels, based on the
work of Rob Pike. It's simply a counter that puts in number into a channel (input),
increase it with one and put this into a different channel (output). The Go routine must
check if a value have been reached (100.000) and if that have been reached, a error must
send in a different channel. 

This is the performance on 1.3 :

path is set to :
PATH=C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;c:\program files\nvidia gpu
computing toolkit\cuda\v3.2\bi
n\;C:\Windows\system32;C:\Windows;C:\Windows\system32\wbem;C:\Windows\system32\windowspowershell\v1.0\;c:\program
file
s (x86)\microsoft asp.net\asp.net web pages\v1.0\;c:\program files (x86)\common
files\adobe\agl;c:\program files\ibm\g
sk8\lib;C:\PROGRA~1\IBM\DB2\BIN;C:\PROGRA~1\IBM\DB2\FUNCTION;C:\PROGRA~1\IBM\DB2\SAMPLES\REPL;C:\Program
Files (x86)\G
it\cmd;C:\TDM-GCC-64\bin;C:\Android\android-sdk\tools;C:\Android\android-sdk;C:\Android\android-sdk\platform-tools;C:\
Go\bin

GOROOT is set to :
GOROOT=C:\Go\

GOPATH is set to :
GOPATH=C:\Users\Dippo\Dropbox\GO

GO version is set to :
go version go1.3 windows/amd64

Microsoft Windows [versie 6.1.7601]
Copyright (c) 2009 Microsoft Corporation. Alle rechten voorbehouden.

C:\Users\Dippo\Dropbox\GO>cd io

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 93.0053ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 93.0053ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 92.0053ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 94.0054ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 94.0054ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 94.0053ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 94.0053ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 93.0053ms to run.

This is the performance on 1.4rc1 :

path is set to :
PATH=C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;c:\program files\nvidia gpu
computing toolkit\cuda\v3.2\bi
n\;C:\Windows\system32;C:\Windows;C:\Windows\system32\wbem;C:\Windows\system32\windowspowershell\v1.0\;c:\program
file
s (x86)\microsoft asp.net\asp.net web pages\v1.0\;c:\program files (x86)\common
files\adobe\agl;c:\program files\ibm\g
sk8\lib;C:\PROGRA~1\IBM\DB2\BIN;C:\PROGRA~1\IBM\DB2\FUNCTION;C:\PROGRA~1\IBM\DB2\SAMPLES\REPL;C:\Program
Files (x86)\G
it\cmd;C:\TDM-GCC-64\bin;C:\Android\android-sdk\tools;C:\Android\android-sdk;C:\Android\android-sdk\platform-tools;C:\
Go1.4rc1\bin

GOROOT is set to :
GOROOT=C:\Go1.4rc1\

GOPATH is set to :
GOPATH=C:\Users\Dippo\Dropbox\GO

GO version is set to :
go version go1.4rc1 windows/amd64

Microsoft Windows [versie 6.1.7601]
Copyright (c) 2009 Microsoft Corporation. Alle rechten voorbehouden.

C:\Users\Dippo\Dropbox\GO>cd io

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 176.01ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 181.0103ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 178.0102ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 176.0101ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 177.0101ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 175.0101ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 176.0101ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 178.0102ms to run.

C:\Users\Dippo\Dropbox\GO\io>go run daisychain3.go
An error arise with output containing : 100000
Took 176.0101ms to run.

Good luck with this one. :) And keep up the good work! You are the best!

[egonelbre]

Comment 1:

I'm seeing about 20% performance drop with github.com/egonelbre/spexs2
To get a longer running example, in "proteins/conf.json" change "Matches(fore)" to {
"min" : 1 }. And then in _examples directory run "make proteins.30k". 
1.4rc1 : 9.5745477s
1.3    : 7.2964173s

[ianlancetaylor]

Comment 2:

Labels changed: added repo-main, release-go1.4maybe.

[unclejack]

It seems I'm also running into this problem. It might also have something to do with memory allocations. The amount of allocated memory has grown 4 times from Go 1.3.3 for a benchmark which was using bytes.Buffer.

Other tests and programs have also taken a 20-33% performance hit which might be connected to goroutines, channels and memory allocations.

This makes Go even slower, burdens the garbage collector with more garbage and increases memory usage for everything using Go.

[nkev]

Would anyone from the Go team care to comment on @unclejack's remark?

[adg]

@unclejack @nkev provide concrete details and we can investigate.

[tssajo]

Well, my pretty complex Go program (sorry, it's not open source) consistently completes in about 32 seconds when compiled with Go 1.4.2. Note: the first line of my code is this: runtime.GOMAXPROCS(runtime.NumCPU()) The exact same and unmodified(!) code compiled with Go 1.5 (released today!) not only compiles a bit slower but consistently completes in about 50 seconds on every run. Platform is Windows 7 (64-bit). I'm sorry, but I cannot provide example code. My program is highly optimized (I used to write programs in Assembly language before, so I know what I am talking about) and it is a converter program. I use the folllowing 3rd party library extensively: goquery I was extremely excited that Go 1.5 got released today (was looking for this release for over 2 months) but I'll downgrade back to Go 1.4.2 tomorrow because of this extreme performance degradation... I am sorry, that I cannot provide the source code of my program, but it is not public. :(

[davecheney]

@tssajo I'm sorry that Go 1.5 is causing problems for you. Could I ask you to consider opening a new issue. I understand that you cannot provide the source of your program, but perhaps if you can provide some code derived from your program which demonstrates the issue some progress can be made.

[unclejack]

The slowdowns encountered when switching to Go 1.4 from Go 1.3 were pretty difficult to pinpoint. Some were just goroutines behaving differently.

Go 1.5 has made Docker's compilation slower and test execution is also slower.

make binary with Go 1.5 real 0m48.332s user 0m0.420s sys 0m0.992s

make binary with Go 1.4.2 real 0m21.154s user 0m0.832s sys 0m0.692s

make cross with Go 1.5 real 4m1.818s user 0m0.756s sys 0m0.740s

make cross with Go 1.4.2 real 1m44.250s user 0m0.848s sys 0m0.720s

make test-unit with Go 1.5 real 10m0.920s user 0m0.744s sys 0m0.796s

make test-unit with Go 1.4.2 real 1m29.796s user 0m1.116s sys 0m0.824s

I haven't done performance tests for Docker binaries, but that is probably going to be slower as well because Docker has quite a bit of code. This might mean waiting for Go 1.6 and skipping Go 1.5.

Go tip didn't seem to have these issues a few months ago.

Are there any plans to address some of these issues in Go 1.5.x?

[davecheney]

I haven't done performance tests for Docker binaries, but that is probably going to be slower as well because Docker has quite a bit of code. This might mean waiting for Go 1.6 and skipping Go 1.5.

Please test and profile to confirm if this is the case. Your make unit-test slowdown looks unexpected. 10m vs 1m30 sounds like a lot more work is being done before the tests start.

Go tip didn't seem to have these issues a few months ago. Are there any plans to address some of these issues in Go 1.5.x?

yes, please log an issue with details of what you are seeing and how to reproduce the issue.

[tssajo]

@davecheney Thanks for responding to my slowdown issue. I'm going to do some profiling too. I'll profile both the 1.4.2 and 1.5 generated program code. I try to find out the differences between the two. Fortunately, I can reproduce this issue on every run. I hope I can install both 1.4.2 and 1.5 on the same computer (Windows 7 x64) at the same time... I'll try to send you an update soon.

[tssajo]

In addition to the slowdown, every single Windows x64 exe file built with 1.5 is about 500kb larger than the one built with 1.4.2 ... My build command looks like this: go build -ldflags "-s -w" So the resulting exe files are not just executing slower (in my case), but also 500kb larger as well... :(

[davecheney]

@tssajo thanks, and please remember to file a new issue.

[davecheney]

In addition to the slowdown, every single Windows x64 exe file built with 1.5 is about 500kb larger than > the one built with 1.4.2 ... My build command looks like this: go build -ldflags "-s -w" So the resulting exe files are not just executing slower (in my case), but also 500kb larger as well... :(

Binary size is not a primary concern for Go development. We know they are large and are trying not to let it get ridiculous, but there is no pressing force to make them as small as possible.

[tssajo]

@davecheney New issue is filed as requested: https://github.com/golang/go/issues/12228 with CPU and memory profile info.

[unclejack]

Please test and profile to confirm if this is the case. Your make unit-test slowdown looks unexpected. 10m vs 1m30 sounds like a lot more work is being done before the tests start.

@davecheney The unit tests were exactly the same for the two runs. The tests are compiled and then executed for the make test-unit tests.

I'll provide more details after I track down some some specific regressions. Simply profiling the whole Docker binary won't help because it's huge - millions of small objects are created and freed.

[rsc]

This is blocked on the new compiler back end, which didn't make it into Go 1.6.

[bradfitz]

I think this is bug can probably be closed. Much happened in Go 1.7: the compiler is faster, binaries are smaller, and generated code is better. See http://dave.cheney.net/2016/04/02/go-1-7-toolchain-improvements

Let's move specific issues to new bugs.