runtime: general runtime slowdown from 1.3 to 1.4 to 1.5 #9123

gopherbot · 2014-11-18T11:37:14Z

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 · 2014-11-18T12:03:02Z

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 · 2014-11-18T17:14:24Z

Comment 2:

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

unclejack · 2014-12-09T15:54:12Z

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 · 2014-12-15T00:55:58Z

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

adg · 2014-12-15T01:05:31Z

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

tssajo · 2015-08-19T21:37:08Z

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 · 2015-08-19T23:26:53Z

@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 · 2015-08-20T08:29:00Z

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 · 2015-08-20T09:01:41Z

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 · 2015-08-20T09:15:32Z

@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 · 2015-08-20T09:17:55Z

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 · 2015-08-20T09:24:44Z

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

davecheney · 2015-08-20T09:25:47Z

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 · 2015-08-20T10:52:04Z

@davecheney New issue is filed as requested: #12228 with CPU and memory profile info.

unclejack · 2015-08-20T11:25:39Z

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 · 2015-11-23T20:58:18Z

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

bradfitz · 2016-05-06T00:27:57Z

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.

gopherbot added new labels Nov 18, 2014

bradfitz removed the new label Dec 18, 2014

rsc added this to the Go1.5Maybe milestone Apr 10, 2015

rsc removed release-go1.4maybe labels Apr 14, 2015

rsc changed the title ~~runtime: Slow performance with 1.4rc1~~ runtime: general runtime slowdown from 1.3 to 1.4 to 1.5 Jul 21, 2015

rsc modified the milestones: Go1.6, Go1.5Maybe Jul 21, 2015

rsc modified the milestones: Go1.7Early, Go1.6 Nov 23, 2015

dsymonds added the Performance label Mar 31, 2016

bradfitz closed this as completed May 6, 2016

golang locked and limited conversation to collaborators May 6, 2017

gopherbot added the FrozenDueToAge label May 6, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: general runtime slowdown from 1.3 to 1.4 to 1.5 #9123

runtime: general runtime slowdown from 1.3 to 1.4 to 1.5 #9123

gopherbot commented Nov 18, 2014

egonelbre commented Nov 18, 2014

ianlancetaylor commented Nov 18, 2014

unclejack commented Dec 9, 2014

nkev commented Dec 15, 2014

adg commented Dec 15, 2014

tssajo commented Aug 19, 2015

davecheney commented Aug 19, 2015

unclejack commented Aug 20, 2015

davecheney commented Aug 20, 2015

tssajo commented Aug 20, 2015

tssajo commented Aug 20, 2015

davecheney commented Aug 20, 2015

davecheney commented Aug 20, 2015

tssajo commented Aug 20, 2015

unclejack commented Aug 20, 2015

rsc commented Nov 23, 2015

bradfitz commented May 6, 2016

runtime: general runtime slowdown from 1.3 to 1.4 to 1.5 #9123

runtime: general runtime slowdown from 1.3 to 1.4 to 1.5 #9123

Comments

gopherbot commented Nov 18, 2014

egonelbre commented Nov 18, 2014

ianlancetaylor commented Nov 18, 2014

unclejack commented Dec 9, 2014

nkev commented Dec 15, 2014

adg commented Dec 15, 2014

tssajo commented Aug 19, 2015

davecheney commented Aug 19, 2015

unclejack commented Aug 20, 2015

davecheney commented Aug 20, 2015

tssajo commented Aug 20, 2015

tssajo commented Aug 20, 2015

davecheney commented Aug 20, 2015

davecheney commented Aug 20, 2015

tssajo commented Aug 20, 2015

unclejack commented Aug 20, 2015

rsc commented Nov 23, 2015

bradfitz commented May 6, 2016