Skip to content

runtime: -race allocates 2.8x VM in Go 1.4 vs Go 1.3.3 #9332

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
vito opened this issue Dec 16, 2014 · 6 comments
Closed

runtime: -race allocates 2.8x VM in Go 1.4 vs Go 1.3.3 #9332

vito opened this issue Dec 16, 2014 · 6 comments

Comments

@vito
Copy link

vito commented Dec 16, 2014

We upgraded to 1.4 recently and noticed dramatically higher memory usage when using the -race flag.

The following table is the memory usage expressed in virtual and resident (as seen in htop), with and without -race:

go race no-race
1.4 2236M / 36352 418M / 8576
1.3.3 782M / 24884 427M / 8884

Is this a side-effect of converting them automatically from C to Go? (as seen in 59e3e53).

We noticed this because tests started running out of memory and failing. Looks like the overall footprint is just much higher with -race than in 1.3.3 (which was also higher, but not as bad).

/cc @onsi @krishicks

@minux
Copy link
Member

minux commented Dec 16, 2014

The high memory usage is not a side effect of converting the race runtime
to Go, because the commit you cited is not included in 1.4.

high VM usage is generally not a problem, and RSS doesn't increase much.

@vito
Copy link
Author

vito commented Dec 16, 2014

Fair enough; it's not that commit.

More details: Linux amd64, ~6GB RAM, 1GB swap.

At some point high VM does seem to become a problem. We were seeing failures depending on how /proc/sys/vm/overcommit_memory and friends are configured. With the defaults, tests started failing with out-of-memory. Setting it to always permit allocation (echo 1 > /proc/sys/vm/overcommit_memory) "worked".

As a dramatic example, a worker pool of 8000 goroutines has no hope of working in Go 1.4 with -race on our machine. With 1.3.3, this works for much longer before eventually failing (after running out of swap). So it seems like the overhead of goroutines with -race is generally much larger in 1.4 than it was in 1.3.3.

Bottom line is this behavior seems to have changed between 1.3 and 1.4. It's not blocking us anymore but wanted to at least log the issue so others can find it. We can spend more time on whittling it down to a reproducible example, but it seems like something that applies across-the-board (-race + N goroutines).

@vito
Copy link
Author

vito commented Dec 16, 2014

Small reproduction:

package main

import (
    "fmt"
    "os"
    "os/exec"
    "sync"
    "time"
)

func main() {
    wg := new(sync.WaitGroup)
    wg.Add(8000)

    for i := 0; i < 8000; i++ {
        go func() { wg.Done(); time.Sleep(10 * time.Hour) }()
    }

    wg.Wait()

    cmd := exec.Command("ps", "auxf")
    cmd.Stdout = os.Stdout
    cmd.Stderr = os.Stderr
    fmt.Println(cmd.Run())
}

On 1.4:

root@bnpdc5ehkue:~# time /usr/local/go/bin/go run -race test.go
fork/exec /bin/ps: cannot allocate memory

real    0m2.669s
user    0m1.164s
sys 0m0.542s

On 1.3.3:

root@bnpdc5ehkua:~# time /usr/local/go/bin/go run test.go -race
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0   1120     0 ?        S<s  01:00   0:00 wshd: bnpdc5ehkua
root       234  0.0  0.0  18168  1136 pts/1    S<s  01:01   0:00 bash
root       542  0.0  0.1 256040  6768 pts/1    S<l  01:14   0:00  \_ /usr/local/go/bin/go run -race test.go
root       550  0.1 20.5 5500216 1256116 pts/1 S<l  01:14   0:00  |   \_ /tmp/go-build944912787/command-line-arguments/_obj/exe/test
root       590  0.0  0.0 255912  5136 pts/1    S<l+ 01:25   0:00  \_ /usr/local/go/bin/go run test.go -race
root       598  0.0  0.6  72228 37960 pts/1    S<l+ 01:25   0:00      \_ /tmp/go-build681557977/command-line-arguments/_obj/exe/test -race
root       602  0.0  0.0  15564  1104 pts/1    R<+  01:25   0:00          \_ ps auxf
<nil>

real    0m0.216s
user    0m0.180s
sys 0m0.061s

(Also note the time taken to run. Way different.)

@minux
Copy link
Member

minux commented Dec 16, 2014

According to
http://golang.org/doc/articles/race_detector.html#Runtime_Overheads,
the memory overhead could be 5x-10x.

The change could be due to updates to the race detector core during the 1.4
time
frame.

@rsc
Copy link
Contributor

rsc commented Apr 10, 2015

@dvyukov, any ideas what might have changed wrt VM usage?

@rsc rsc changed the title dramatically higher memory usage with -race in Go 1.4 runtime: -race allocates 2.8x VM in Go 1.4 vs Go 1.3.3 Apr 10, 2015
@dvyukov
Copy link
Member

dvyukov commented Apr 10, 2015

Tested locally.
With go1.4 the program fails the same way:
fork/exec /bin/ps: cannot allocate memory
With tip it prints:
dvyukov 5133 94.0 1.0 2951416 706384 pts/32 Sl+ 10:32

I don't have 1.3, so taking the reported report:
root 550 0.1 20.5 5500216 1256116 pts/1 S<l 01:14

So, on tip memory consumption dropped 2x as compared to 1.3.
We are not going to update race runtime in 1.4, so I am closing this.

@dvyukov dvyukov closed this as completed Apr 10, 2015
@golang golang locked and limited conversation to collaborators Jun 25, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants