High Performance Go Workshop

Download the source to this document and code samples at https://github.com/davecheney/high-performance-go-workshop

The workshop material targets Go 1.13. This is currently available in beta.

Download Go 1.13 beta 1

The section on pprof requires the dot program which ships with the graphviz suite of tools.

The section on the execution tracer requires Google Chrome. It will not work with Safari, Edge, Firefox, or IE 4.01. Please tell your battery I’m sorry.

Download Google Chrome

The final section of the day will be an open session where you can experiment with the tools you’ve learnt.

As benchmarks use the testing package they are executed via the go test subcommand. However, by default when you invoke go test, benchmarks are excluded.

To explicitly run benchmarks in a package use the -bench flag. -bench takes a regular expression that matches the names of the benchmarks you want to run, so the most common way to invoke all benchmarks in a package is -bench=.. Here is an example:

Each benchmark function is called with different value for b.N, this is the number of iterations the benchmark should run for.

b.N starts at 1, if the benchmark function completes in under 1 second—​the default—​then b.N is increased and the benchmark function run again.

b.N increases in the approximate sequence, growing by roughly 20% each iteration. The benchmark framework tries to be smart and if it sees small values of b.N are completing relatively quickly, it will increase the iteration count faster.

Looking at the example above, BenchmarkFib20-8 found that around 29,000 iterations of the loop took just over a second. From there the benchmark framework computed that the average time per operation was 40617ns.

Prior to Go 1.13 the benchmarking iteration numbers we rounded to a 1, 2, 3, 5 sequence. The original goal of this rounding to was to make it easier to eyeball times. However, proper analysis requires tooling anyway, so human readable numbers became less valuble as the tooling improved.

The rounding could hide almost an order of magnitude of variation.

Fortuntely in Go 1.13 the rounding has been removed, which improves the accuracy of benchmarking operations in the low ns/op range, and reduce the run time of benchmarks overall as the benchmark framework arrives at the correct iteration count faster.

The fib function is a slightly contrived example—​unless your writing a TechPower web server benchmark—​it’s unlikely your business is going to be gated on how quickly you can compute the 20th number in the Fibonaci sequence. But, the benchmark does provide a faithful example of a valid benchmark.

Specifically you want your benchmark to run for several tens of thousand iterations so you get a good average per operation. If your benchmark runs for only 100’s or 10’s of iterations, the average of those runs may have a high standard deviation. If your benchmark runs for millions or billions of iterations, the average may be very accurate, but subject to the vaguaries of code layout and alignment.

To increase the number of iterations, the benchmark time can be increased with the -benchtime flag. For example:

Ran the same benchmark until it reached a value of b.N that took longer than 10 seconds to return. As we’re running for 10x longer, the total number of iterations is 10x larger. The result hasn’t changed much, which is what we expected.

If you have a benchmark which runs for millons or billions of iterations resulting in a time per operation in the micro or nano second range, you may find that your benchmark numbers are unstable because thermal scaling, memory locality, background processing, gc activity, etc.

For times measured in 10 or single digit nanoseconds per operation the relativistic effects of instruction reordering and code alignment will have an impact on your benchmark times.

To address this run benchmarks multiple times with the -count flag:

A benchmark of Fib(1) takes around 2 nano seconds with a variance of +/- 15%.

New in Go 1.12 is the -benchtime flag now takes a number of iterations, eg. -benchtime=20x which will run your code exactly benchtime times.

Determining the performance delta between two sets of benchmarks can be tedious and error prone. Benchstat can help us with this.

The previous Fib fuction had hard coded values for the 0th and 1st numbers in the fibonaci series. After that the code calls itself recursively. We’ll talk about the cost of recursion later today, but for the moment, assume it has a cost, especially as our algorithm uses exponential time.

As simple fix to this would be to hard code another number from the fibonacci series, reducing the depth of each recusive call by one.

To compare our new version, we compile a new test binary and benchmark both of them and use benchstat to compare the outputs.

There are three things to check when comparing benchmarks

p-values lower than 0.05 likely to be statistiaclly significant. p-values greater than 0.05 imply the benchmark may not be statistically significant.

An example of questionable p-values.

Further reading: P-value (wikipedia).

Before we go on, lets look at the assembly to confirm what we saw

Disabling inlining to make the benchmark work is unrealistic; we want to build our code with optimisations on.

To fix this benchmark we must ensure that the compiler cannot prove that the body of BenchmarkPopcnt does not cause global state to change.

This is the recommended way to ensure the compiler cannot optimise away body of the loop.

First we use the result of calling popcnt by storing it in r. Second, because r is declared locally inside the scope of BenchmarkPopcnt once the benchmark is over, the result of r is never visible to another part of the program, so as the final act we assign the value of r to the package public variable Result.

Because Result is public the compiler cannot prove that another package importing this one will not be able to see the value of Result changing over time, hence it cannot optimise away any of the operations leading to its assignment.

CPU profiling is the most common type of profile, and the most obvious.

When CPU profiling is enabled the runtime will interrupt itself every 10ms and record the stack trace of the currently running goroutines.

Once the profile is complete we can analyse it to determine the hottest code paths.

The more times a function appears in the profile, the more time that code path is taking as a percentage of the total runtime.

Memory profiling records the stack trace when a heap allocation is made.

Stack allocations are assumed to be free and are not_tracked in the memory profile.

Memory profiling, like CPU profiling is sample based, by default memory profiling samples 1 in every 1000 allocations. This rate can be changed.

Because of memory profiling is sample based and because it tracks allocations not use, using memory profiling to determine your application’s overall memory usage is difficult.

Personal Opinion: I do not find memory profiling useful for finding memory leaks. There are better ways to determine how much memory your application is using. We will discuss these later in the presentation.

Block profiling is quite unique to Go.

A block profile is similar to a CPU profile, but it records the amount of time a goroutine spent waiting for a shared resource.

This can be useful for determining concurrency bottlenecks in your application.

Block profiling can show you when a large number of goroutines could make progress, but were blocked. Blocking includes:

Block profiling is a very specialised tool, it should not be used until you believe you have eliminated all your CPU and memory usage bottlenecks.

Mutex profiling is simlar to Block profiling, but is focused exclusively on operations that lead to delays caused by mutex contention.

The mutex profile does not show you how long the program ran for, or even what took the most time. Instead it reports how much time was spent waiting for locks. Just like blocking profile, it says how much time was spent waiting for a resource.

Said another way, the mutex profile reports how much time could be saved if the lock contention was removed.

Let’s write a program to count words:

Let’s see how many words there are in Herman Melville’s classic Moby Dick (sourced from Project Gutenberg)

Let’s compare that to unix’s wc -w

So the numbers aren’t the same. wc is about 19% higher because what it considers a word is different to what my simple program does. That’s not important—​both programs take the whole file as input and in a single pass count the number of transitions from word to non word.

Let’s investigate why these programs have different run times using pprof.

First, edit main.go and enable profiling

Now when we run the program a cpu.pprof file is created.

Now we have the profile we can analyse it with go tool pprof

The top command is one you’ll use the most. We can see that 99% of the time this program spends in syscall.Syscall, and a small part in main.readbyte.

We can also visualise this call the with the web command. This will generate a directed graph from the profile data. Under the hood this uses the dot command from Graphviz.

However, in Go 1.10 (possibly 1.11) Go ships with a version of pprof that natively supports a http sever

Will open a web browser;

On the graph the box that consumes the most CPU time is the largest — we see sys call.Syscall at 99.3% of the total time spent in the program. The string of boxes leading to syscall.Syscall represent the immediate callers — there can be more than one if multiple code paths converge on the same function. The size of the arrow represents how much time was spent in children of a box, we see that from main.readbyte onwards they account for near 0 of the 1.41 second spent in this arm of the graph.

The reason our program is slow is not because Go’s syscall.Syscall is slow. It is because syscalls in general are expensive operations (and getting more expensive as more Spectre family vulnerabilities are discovered).

Each call to readbyte results in a syscall.Read with a buffer size of 1. So the number of syscalls executed by our program is equal to the size of the input. We can see that in the pprof graph that reading the input dominates everything else.

By inserting a bufio.Reader between the input file and readbyte will

The new words profile suggests that something is allocating inside the readbyte function. We can use pprof to investigate.

Then run the program as usual

As we suspected the allocation was coming from readbyte — this wasn’t that complicated, readbyte is three lines long:

We’ll talk about why this is happening in more detail in the next section, but for the moment what we see is every call to readbyte is allocating a new one byte long array and that array is being allocated on the heap.

Memory profiles come in two varieties, named after their go tool pprof flags

To demonstrate this, here is a contrived program which will allocate a bunch of memory in a controlled manner.

The program is annotation with the profile package, and we set the memory profile rate to 1--that is, record a stack trace for every allocation. This is slows down the program a lot, but you’ll see why in a minute.

Lets look at the graph of allocated objects, this is the default, and shows the call graphs that lead to the allocation of every object during the profile.

Not surprisingly more than 99% of the allocations were inside makeByteSlice. Now lets look at the same profile using -inuse_objects

What we see is not the objects that were allocated during the profile, but the objects that remain in use, at the time the profile was taken — this ignores the stack trace for objects which have been reclaimed by the garbage collector.

The last profile type we’ll look at is block profiling. We’ll use the ClientServer benchmark from the net/http package

Mutex contention increases with the number of goroutines.

Try running this on your machine.

Go 1.7 has been released and along with a new compiler for amd64, the compiler now enables frame pointers by default.

The frame pointer is a register that always points to the top of the current stack frame.

Framepointers enable tools like gdb(1), and perf(1) to understand the Go call stack.

We won’t cover these tools in this workshop, but you can read and watch a presentation I gave on seven different ways to profile Go programs.

b.StopTimer / b.StartTimer are surprisingly expensive. Use the profiling flags built into go test to profile the cost of b.StopTimer.

To print the compilers escape analysis decisions, use the -m flag.

Line 7 shows the compiler has correctly deduced that the result of make([]int, 100) does not escape to the heap. The reason it did no

The reason line 21 reports that answer escapes to the heap is fmt.Println is a variadic function. The parameters to a variadic function are boxed into a slice, in this case a []interface{}, so answer is placed into a interface value because it is referenced by the call to fmt.Println. Since Go 1.6 the garbage collector requires all values passed via an interface to be pointers, what the compiler sees is approximately:

We can confirm this using the -gcflags="-m -m" flag. Which returns

In short, don’t worry about line 21, its not important to this discussion.

This example is a little contrived. It is not intended to be real code, just an example.

NewPoint creates a new *Point value, p. We pass p to the Center function which moves the point to a position in the center of the screen. Finally we print the values of p.X and p.Y.

Even though p was allocated with the new function, it will not be stored on the heap, because no reference p escapes the Center function.

Question: What about line 19, if p doesn’t escape, what is escaping to the heap?

Again we use the -gcflags=-m flag to view the compilers optimisation decision.

The compiler printed two lines.

Compile max.go and see what the optimised version of F() became.

This is the body of F once Max has been inlined into it — there’s nothing happening in this function. I know there’s a lot of text on the screen for nothing, but take my word for it, the only thing happening is the RET. In effect F became:

Why did I declare a and b in F() to be constants?

Branch elimination is one of a category of optimisations known as dead code elimination. In effect, using static proofs to show that a piece of code is never reachable, colloquially known as dead, therefore it need not be compiled, optimised, or emitted in the final binary.

We saw how dead code elimination works together with inlining to reduce the amount of code generated by removing loops and branches that are proven unreachable.

You can take advantage of this to implement expensive debugging, and hide it behind

Combined with build tags this can be very useful.

Adjusting the inlining level is performed with the -gcflags=-l flag. Somewhat confusingly passing a single -l will disable inlining, and two or more will enable inlining at more aggressive settings.

Since Go 1.12 so called mid stack inlining has been enabled (it was previously available in preview in Go 1.11 with the -gcflags='-l -l -l -l' flag).

We can see an example of mid stack inlining in the previous example. In Go 1.11 and earlier F would not have been a leaf function — it called max. However because of inlining improvements F is now inlined into its caller. This is for two reasons; . When max is inlined into F, F contains no other function calls thus it becomes a potential leaf function, assuming its complexity budget has not been exceeded. . Because F is a simple function—​inlining and dead code elimination has eliminated much of its complexity budget—​it is eligable for mid stack inlining irrispective of calling max.

Just as with inining and escape analysis we can ask the compiler to show us the working of the prove pass. We do this with the -d flag passed to go tool compile via -gcflags

Line 5 is if x > 3. The compiler is saying that is has proven that the branch will always be true.

Let’s return to the pop count example from earlier. Population count is an important crypto operation so modern CPUs have a native instruction to perform it.

The math/bits package provides a set of functions, OnesCount…​ which are recognised by the compiler and replaced with their native equivalent.

Here’s an example of an atomic counter type. We’ve got methods on types, method calls several levels deep, multiple packages, etc. You’d be forgiven for thinking this might have a lot of overhead.

But, because of the interation between inlining and compiler intrinsics, this code collapses down to efficient native code on most platforms.

So, how long does this program take to generate a 1024 x 1024 pixel image?

The simplest way I know how to do this is to use something like time(1).

So, in this example the program took 1.6 seconds to generate the mandelbrot and write to to a png.

Is that good? Could we make it faster?

One way to answer that question would be to use Go’s built in pprof support to profile the program.

Let’s try that.

The previous slide showed a super cheap way to generate a profile, but it has a few problems.

The recommended way to use runtime/pprof is to write the trace to a file. But, then you have to make sure the trace is stopped, and file is closed before your program stops, including if someone `^C’s it.

So, a few years ago I wrote a package to take care of it.

If we run this version, we get a profile written to the current working directory

Now we have a profile, we can use go tool pprof to analyse it.

In this run we see that the program ran for 1.81s seconds (profiling adds a small overhead). We can also see that pprof only captured data for 1.53 seconds, as pprof is sample based, relying on the operating system’s SIGPROF timer.

We can use the top pprof function to sort functions recorded by the trace

We see that the main.fillPixel function was on the CPU the most when pprof captured the stack.

Finding main.paint on the stack isn’t a surprise, this is what the program does; it paints pixels. But what is causing paint to spend so much time? We can check that with the cummulative flag to top.

This is sort of suggesting that main.fillPixed is actually doing most of the work.

Using the tracer is as simple as asking for a profile.TraceProfile, nothing else changes.

When we run the program, we get a trace.out file in the current working directory.

Just like pprof, there is a tool in the go command to analyse the trace.

This tool is a little bit different to go tool pprof. The execution tracer is reusing a lot of the profile visualisation infrastructure built into Chrome, so go tool trace acts as a server to translate the raw execution trace into data which Chome can display natively.

We can see from the trace that the program is only using one cpu.

This isn’t a surprise, by default mandelbrot.go calls fillPixel for each pixel in each row in sequence.

Once the image is painted, see the execution switches to writing the .png file. This generates garbage on the heap, and so the trace changes at that point, we can see the classic saw tooth pattern of a garbage collected heap.

The trace profile offers timing resolution down to the microsecond level. This is something you just can’t get with external profiling.