build: all.bash fails to saturate 6 cores

[bcmills]

go version devel +eed2bb7 Wed Nov 2 19:21:16 2016 +0000 linux/amd64

What did you do?

./clean.bash
time ./all.bash

What did you expect to see?

I do my development on a virtualized 6-core Xeon running Ubuntu. (runtime.NumCPU() returns 6.)

Per @rsc's comments on #10571, I expected "Both the build half and the test half of all.bash should consume nearly all the CPUs for most of the time."

What did you see instead?

all.bash seems to saturate at ~2 CPU cores for a significant fraction of the run. It consumes less than twice as much user time than real. Oddly, sys usage is even higher than user; I'm not sure what to make of that.

real    8m55.199s
user    14m13.511s
sys     8m51.402s

Here's a chart of CPU saturation over time as measured by mpstat. You can see that there are a couple bursts of parallelism with mostly poor saturation in between. The machine doesn't appear to be hitting swap during the build.

[bradfitz]

I don't have access to your CPU saturation chart. google.com accounts can't share outside of Google, IIRC. Use your golang account?

[bcmills]

That's annoying. I don't have a golang account; I'll see if I can just upload an image instead.

[bcmills]

[minux]

The low cpu utilization might be caused by non-optimal cmd/go scheduling. I'm more worried about the high sys time, because it usually indicates extensive unbuffered IO. However, I couldn't reproduce the high %sys usage on my Linux system, and /usr/bin/time reports that average CPU usage to be 353% on a 4 core HT system (8 logical cores).

[bradfitz]

on a virtualized 6-core Xeon

Which virtualization? (might explain high sys time?)

[josharian]

#15736 will help with understanding this. Sorry I didn't get it into 1.8. Making compilation more concurrent will also help saturate the cores (as would #15734, but the consensus is to focus on intra-package concurrency instead).

[bradfitz]

Also, the make.bash portion of Bryan's graph doesn't look super terrible.

The terrible part is running the tests, almost none of which use t.Parallel so are run serialized.

If people could go around and sprinkle some magic t.Parallel fairy dusty on tests where it's safe to do (where it doesn't introduce flakiness under load), that would be great.

[josharian]

Here are the 20 slowest packages to test, at least on my machine:

$ pbpaste | grep "^ok" | awk '{print $3"\t"$2}' | sort -n -r | head -n 20
67.474s cmd/go
54.461s runtime
42.232s cmd/compile/internal/gc
10.048s net/http
9.891s  go/build
9.311s  cmd/objdump
8.648s  cmd/cover
8.295s  cmd/vet
7.839s  net
6.487s  cmd/nm
5.483s  cmd/pack
4.813s  cmd/compile
4.534s  os/signal
3.899s  cmd/addr2line
2.784s  net/http/cgi
2.692s  time
2.615s  go/types
2.246s  log/syslog
2.209s  compress/flate
2.176s  runtime/pprof

Of these, cmd/go, runtime, net/http, net, os/signal, net/http/cgi, time, and runtime/pprof seem the most likely to become flakier under load. I'll take a look at cmd/compile/internal/gc and leave the rest for others.

[dsnet]

I can hammer on compress/flate. It's a package whose tests I want to clean up anyways.

[bradfitz]

Here are the 20 slowest packages to test, at least on my machine

I have the timing data for every trybot + build run on all machines in BigQuery, btw.

[gopherbot]

CL https://golang.org/cl/32585 mentions this issue.

[gopherbot]

CL https://golang.org/cl/32673 mentions this issue.

[bcmills]

@bradfitz

Which virtualization? (might explain high sys time?)

Xen (via Ganeti), I believe.

I suspect that I/O performance on my system is pretty poor, so that might explain the high sys time.

[gopherbot]

CL https://golang.org/cl/32684 mentions this issue.

[gopherbot]

CL https://golang.org/cl/32751 mentions this issue.

[gopherbot]

CL https://golang.org/cl/32754 mentions this issue.

[gopherbot]

CL https://golang.org/cl/32850 mentions this issue.

[josharian]

I'm curious whether concurrent compilation in 1.9 helps much here.

[bcmills]

I'm curious whether concurrent compilation in 1.9 helps much here.

The initial build transient seems to saturate a bit better, and a few of the tests spike to saturation, but the overall utilization is still pretty similar.

From a clean build at tip:

[rsc]

When I run "time all.bash" now I get

real 5m26.407s
user 24m59.594s
sys 11m20.201s

on my 6-core 12-hyperthread 2018 MacBook Pro.

That looks like (user+sys)/real = (1499+680)/326 = 6.7 cores used on average during all.bash.

Going to call that fixed.
Also note that in the original report it says 6-core but it may well be 3-core 6-hyperthread, in which case the observed (853+531)/535 = 2.6X is not too bad.

[bcmills]

FWIW, the chart (measured by mpstat 1) still shows spotty utilization as before, although the trough is less severe than it was.

This is on a non-virtualized Xeon E5-1650 v4 (6 cores, 12 hardware threads, and I'm not sure whether HT is enabled).

I expect the initial bootstrap phase not to parallelize very well (because it's using Go 1.4), and the initial build and the tail end of the tests do seem to parallelize well, but the ordinary package tests in the middle still don't even come close to saturating.

[bcmills]

time for the above run reported:

real    5m32.000s
user    15m8.107s
sys     2m58.300s

That's only ~3 cores saturated on average.

[bcmills]

on my 6-core 12-hyperthread 2018 MacBook Pro.

We've noticed that cmd/go performance on macOS tends to be a lot slower in general (#28739). I wonder whether that slowness allows make.bash to saturate more easily.

It's also possible that the thermal limits of a laptop make saturation easier: laptops tend to have lower sustained turbo frequencies, so perhaps parallel operations that complete quickly with a higher turbo end up doing more of that work in parallel at a lower clock speed.

[josharian]

@bcmills what is going on at each of the interesting transition points in that graph? (The tracing charts of #15736 would be really helpful here, but maybe the -debug-actiongraph timing information added by @rsc will help clarify as well) Are we spending a bunch of time waiting for stragglers? Or are we not starting enough compilations/tests in parallel? Should cmd/dist be doing higher level parallelization? Or...?

[rsc]

export GOBUILDTIMELOGFILE=/tmp/time.log before all.bash.