Debugging performance issues in Go programs

Let's assume you have a Go program and want to improve its performance. There are several tools available that can help with this task. These tools can help you to identify various types of hotspots (CPU, IO, memory), hotspots are the places that you need to concentrate on in order to significantly improve performance. However, another outcome is possible -- the tools can help you identify obvious performance defects in the program. For example, you prepare an SQL statement before each query while you could prepare it once at program startup. Another example is if an O(N^2) algorithm somehow slipped into where an obvious O(N) exists and is expected. In order to identify such cases you need to sanity check what you see in profiles. For example for the first case significant time spent in SQL statement preparation would be the red flag.

It's also important to understand various bounding factors for performance. For example, if the program communicates via 100 Mbps network link and it is already utilizes >90Mbps, there is not much you can do with the program to improve its performance. There are similar bounding factors for disk IO, memory consumption and computational tasks.

With that in mind we can look at the available tools.

Note: The tools can interfere with each other. For example, precise memory profiling skews CPU profiles, goroutine blocking profiling affects scheduler trace, etc. Use tools in isolation to get more precise info.

Note: the formats described here are based on Go1.3 release.

 

CPU Profiler

 

Go runtime contains built-in CPU profiler, which shows what functions consume what percent of CPU time. There are 3 ways you can get access to it:

 

1. The simplest one is -cpuprofile flag of 'go test' command. For example, the following command:

$ go test -run=none -bench=ClientServerParallel4 -cpuprofile=cprof net/http

will profile the given benchmark and write CPU profile into 'cprof' file.

Then:

$ go tool pprof --text http.test cprof

will print a list of the hottest functions.

There are several output types available, the most useful ones are: --text, --web and --list. Run 'go tool pprof' to get the complete list.

The obvious drawback of this option is that it works only for tests.

 

2. net/http/pprof package. This is the ideal solution for network servers. You merely need to import net/http/pprof, and collect profiles with:

$ go tool pprof --text mybin http://myserver:6060:/debug/pprof/profile

 

3. Manual profile collection. You need to import runtime/pprof and add the following code to main function:

The profile will be written to the specified file, visualize it the same way as in the first option.

 

Here is an example of a profile visualized with --web option:

 

 

You can investigate a single function with --list=funcname option. For example, the following profile shows that the time was spent in the append function:

You can find detailed info on pprof tool and description of the numbers in the graph here.

 

There are also 3 special entries that the profiler uses when it can't unwind stack: GC, System and ExternalCode. GC means time spent during garbage collection, see Memory Profiler and Garbage Collector Trace sections below for optimization suggestions. System means time spent in goroutine scheduler, stack management code and other auxiliary runtime code. ExternalCode means time spent in native dynamic libraries.

 

Here are some hints with respect to how to interpret what you see in the profile.

If you see lots of time spent in runtime.mallocgc function, the program potentially makes excessive amount of small memory allocations. The profile will tell you where the allocations are coming from. See the memory profiler section for suggestions on how to optimize this case.

If lots of time is spent in channel operations, sync.Mutex code and other synchronization primitives or System component, the program probably suffers from contention. Consider to restructure program to eliminate frequently accessed shared resources. Common techniques for this include sharding/partitioning, local buffering/batching and copy-on-write technique.

If lots of time is spent in syscall.Read/Write, the program potentially makes excessive amount of small reads and writes. Bufio wrappers around os.File or net.Conn can help in this case.

If lots of time is spent in GC component, the program either allocates too many transient objects or heap size is very small so garbage collections happen too frequently. See Garbage Collector Tracer and Memory Profiler sections for optimization suggestions.

 

Note: CPU profiler currently does not work on darwin.

Note: On windows you need to install Cygwin, Perl and Graphviz to generate svg/web profiles.

Note: On linux you can also try perf system profiler. It can't unwind Go stacks, but it can profile and unwind cgo/SWIG code and kernel. So it can be useful to get insights into native/kernel performance bottlenecks.

 

Memory Profiler

 

Memory profiler shows what functions allocate heap memory. You can collect it in similar ways as CPU profile: with 'go test --memprofile', with net/http/pprof via http://myserver:6060:/debug/pprof/heap or by calling runtime/pprof.WriteHeapProfile.

 

You can visualize only allocations live at the time of profile collection (--inuse_space flag to pprof, default), or all allocations happened since program start (--alloc_space flag to pprof). The former is useful for profiles collected with net/http/pprof on live applications, the latter is useful for profiles collected at program end (otherwise you will see almost empty profile).

 

Note: the memory profiler is sampling, that is, it collects information only about some subset of memory allocations. Probability of sampling an object is proportional to its size. You can change the sampling rate with go test --memprofilerate flag, or by setting runtime.MemProfileRate variable at program startup. The rate of 1 will lead to collection of information about all allocations, but it can slow down execution. The default sampling rate is 1 sample per 512KB of allocated memory.

 

You can also visualize number of bytes allocated or number of objects allocated (--inuse/alloc_space and --inuse/alloc_objects flags, respectively). The profiler tends to sample larger objects during profiling  more. But it's important to understand that large objects affect memory consumption and GC time, while large number of tiny allocations affects execution speed (and GC time to some degree as well). So it may be useful to look at both.

Objects can be persistent or transient. If you have several large persistent objects allocated at program start, they will be most likely sampled by the profiler (because they are large). Such objects do affect memory consumption and GC time, but they do not affect normal execution speed (no memory management operations happen on them). On the other hand if you have large number of objects with very short life durations, they can be barely represented in the profile (if you use the default --inuse_space mode). But they do significantly affect execution speed, because they are constantly allocated and freed. So, once again, it may be useful to look at both types of objects.

So, generally, if you want to reduce memory consumption, you need to look at --inuse_space profile collected during normal program operation. If you want to improve execution speed, look at --alloc_objects profile collected after significant running time or at program end.

There are several flags that control reporting granularity. --functions makes pprof report on function level (default). --lines makes pprof report on source line level, which is useful if hot functions allocate on different lines. And there are also --addresses and --files for exact instruction address and file level, respectively.

 

There is a useful option for the memory profile -- you can look at it right in the browser (provided that you imported net/http/pprof). If you open  http://myserver:6060/debug/pprof/heap?debug=1 you must see the heap profile along the lines of:

The numbers in the beginning of each entry ("1: 262144 [4: 376832]") represent number of currently live objects, amount of memory occupied by live objects, total number of allocations and amount of memory occupied by all allocations, respectively.

 

Optimizations are usually application-specific, but here are some common suggestions.

1. Combine objects into larger objects. For example, replace *bytes.Buffer struct member with bytes.Buffer (you can preallocate buffer for writing by calling bytes.Buffer.Grow later). This will reduce number of memory allocations (faster) and also reduce pressure on garbage collector (faster garbage collections).

 

2. Local variables that escape from their declaration scope get promoted into heap allocations. Compiler generally can't prove that several variables have the same life time, so it allocates each such variable separately. So you can use the above advise for local variables as well. For example, replace:

with:

This replaces two memory allocations with a single allocation. However, this optimization usually negatively affects code readability, so use it reasonably.

3. A special case of allocation combining is slice array preallocation. If you know a typical size of the slice, you can preallocate a backing array for it as follows:

4. If possible use smaller data types. For example, use int8 instead of int.

 

5. Objects that do not contain any pointers (note that strings, slices, maps and chans contain implicit pointers), are not scanned by garbage collector. For example, a 1GB byte slice virtually does not affect garbage collection time. So if you remove pointers from actively used objects, it can positively impact garbage collection time. Some possibilities are: replace pointers with indices, split object into two parts one of which does not contain pointers.

 

6. Use freelists to reuse transient objects and reduce number of allocations. Standard library containssync.Pool type that allows to reuse the same object several times in between garbage collections. However, be aware that, as any manual memory management scheme, incorrect use of sync.Pool can lead to use-after-free bugs.

 

You can also use the Garbage Collector Trace (see below) to get some insights into memory issues.

Blocking Profiler

 

The blocking profiler shows where goroutine block waiting on synchronization primitives (including timer channels). You can collect it in similar ways as CPU profile: with 'go test --blockprofile', with net/http/pprofvia http://myserver:6060:/debug/pprof/block or by calling runtime/pprof.Lookup("block").WriteTo.

But there is significant caveat -- the blocking profiler is not enabled by default. 'go test --blockprofile' will enable it for you automatically. However, if you use net/http/pprof or runtime/pprof, you need to enable it manually (otherwise the profile will be empty). To enable the blocking profiler callruntime.SetBlockProfileRate. SetBlockProfileRate controls the fraction of goroutine blocking events that are reported in the blocking profile. The profiler aims to sample an average of one blocking event per the specified amount of nanoseconds spent blocked. To include every blocking event in the profile, set the rate to 1.

 

If a function contains several blocking operations and it's not obvious which one leads to blocking, use --lines flag to pprof.

 

Note that not all blocking is bad. When a goroutine blocks, the underlying worker thread simply switches to another goroutine. So blocking in the cooperative Go environment is very different from blocking on a mutex in a non-cooperative systems (e.g. typical C++ or Java threading libraries, where blocking leads to thread idling and expensive thread context switches). To give you some feeling, let's consider some examples.

 

Blocking on a time.Ticker is usually OK. If a goroutine blocks on a Ticker for 10 seconds, you will see 10 seconds of blocking in the profile, which is perfectly fine. Blocking on sync.WaitGroup is frequently OK. For example, is a task takes 10 seconds, the goroutine waiting on a WaitGroup for completion will account for 10 seconds of blocking in the profile. Blocking on sync.Cond may or may not be OK, depending on the situation. Consumer blocking on a channel suggests slow producers or lack of work. Producer blocking on a channel suggests that consumers are slower, but this is frequently OK. Blocking on a channel-based semaphore shows how much goroutines are gated on the semaphore. Blocking on a sync.Mutex or sync.RWMutex is usually bad. You can use --ignore flag to pprof to exclude known uninteresting blocking from a profile during visualization.

 

Blocking of goroutines can lead to two negative consequences:

1. Program does not scale with processors due to lack of work. Scheduler Trace can help to identify this case.

2. Excessive goroutine blocking/unblocking consumes CPU time. CPU Profiler can help to identify this case (look at the System component).

 

Here are some common suggestions that can help to reduce goroutine blocking:

 

1. Use sufficiently buffered channels in producer-consumer scenarios. Unbuffered channels substantially limit available parallelism in the program.

 

2. Use sync.RWMutex instead of sync.Mutex for read-mostly workloads. Readers never block other readers in sync.RWMutex, even on implementation level.

 

3. In some cases it's possible to remove mutexes entirely by using copy-on-write technique. If the protected data structure is modified infrequently and it's feasible to make copies of it, then it can be updated as follows:

This pattern prevents the writer from blocking readers during update.

 

4. Partitioning is another general technique for reducing contention/blocking on shared mutable data structures. Below is an example of how to partition a hashmap:

 

5. Local caching and batching of updates can help to reduce contention on un-partitionable data structures. Below you can see how to batch sends to a channel:

This technique is not limited to channels. It can be used to batch updates to a map, batch allocations, etc.

 

6. Use sync.Pool for freelists instead of chan-based or mutex-protected freelists. sync.Pool uses smart techniques internally to reduce blocking.

Goroutine Profiler

 

The goroutine profiler simply gives you current stacks of all live goroutines in the process. It can be handy to debug load balancing issues (see Scheduler Trace section below), or to debug deadlocks.

The profile makes sense only for a running app, so go test does not expose it. You can collect the profile with net/http/pprof via http://myserver:6060:/debug/pprof/goroutine, and visualize it to svg/pdf or by callingruntime/pprof.Lookup("goroutine").WriteTo. But the most useful way is to type  http://myserver:6060:/debug/pprof/goroutine?debug=2 in your browser, which will give you symbolized stacks similar to what you see when a program crashes.

Note that goroutines in "syscall" state consume an OS thread, other goroutines do not (except for goroutines that called runtime.LockOSThread, which is, unfortunately, not visible in the profile). Note that goroutines in "IO wait" state also do not consume threads, they are parked on non-blocking network poller (which uses epoll/kqueue/GetQueuedCompletionStatus to unpark goroutines later).

 

Garbage Collector Trace

 

Aside from the profiling tools, there is another kind of tools available -- tracers. They allow to trace garbage collections, memory allocator and goroutine scheduler state. To enable the garbage collector (GC) trace, run the program with GODEBUG=gctrace=1 environment variable:

$ GODEBUG=gctrace=1 ./myserver

Then the program will print output similar to the following during execution:

Let's consider the meaning of these numbers. One line per GC is printed. The first number ("gc9") is the number of GC (this is the 9-th GC since program start). The number in parens ("(2)") is the number of worker threads participated in the GC. The next 4 numbers ("12+1+744+8 us") mean stop-the-world, sweeping, marking and waiting for worker threads to finish, in microseconds, respectively. The next 2 numbers ("2 -> 10 MB") mean size of live heap after the previous GC and full heap size (including garbage) before the current GC. The next 3 numbers ("108615 (593983-485368) objects") are total number of objects in heap (including garbage) and total number of memory allocation and free operations. The next 3 numbers ("4825/3620/0 sweeps") characterize sweep phase (of the previous GC): there were total 4825 memory spans, 3620 were swept on demand or in background, 0 were swept during stop-the-world phase (the rest were unused spans). The next 4 numbers ("0(0) handoff, 6(91) steal") characterize load balancing during parallel mark phase: there were 0 object handoff operations (0 objects were handoff), and 6 steal operations (91 objects were stolen). The last 3 numbers ("16/1/0 yields") characterize effectiveness of parallel mark phase: there were total of 17 yield operations during waiting for another thread.

 

The GC is mark-and-sweep type. Total GC can be expressed as:

 

Tgc = Tseq + Tmark + Tsweep

 

where Tseq is time to stop user goroutines and some preparation activities (usually small); Tmark is heap marking time, marking happens when all user goroutines are stopped, and thus can significantly affect latency of processing; Tsweep is heap sweeping time, sweeping generally happens concurrently with normal program execution, and so is not so critical for latency.

 

Marking time can be approximately expressed as:

 

Tmark = C1*Nlive + C2*MEMlive_ptr + C3*Nlive_ptr

 

where Nlive is the number of live objects in the heap during GC, MEMlive_ptr is the amount of memory occupied by live objects with pointers, Nlive_ptr is the number of pointers in live objects.

 

Sweeping time can be approximately expressed as:

 

Tsweep = C4*MEMtotal + C5*MEMgarbage

 

where MEMtotal is the total amount of heap memory, MEMgarbage is the amount of garbage in the heap.

 

Next GC happens after the program has allocated an extra amount of memory proportional to the amount already in use. The proportion is controlled by GOGC environment variable (100 by default). If GOGC=100 and the program is using 4M of heap memory, runtime will trigger GC again when the program gets to 8M. This keeps the GC cost in linear proportion to the allocation cost. Adjusting GOGC changes the linear constant and also the amount of extra memory used.

 

Only sweeping depends on total size of the heap, and sweeping happens concurrently with normal program execution. So it can make sense to set GOGC to a higher value (200, 300, 500, etc) if you can afford extra memory consumption. For example, GOGC=300 can reduce garbage collection overhead by up to 2 times while keeping latencies the same (at the cost of 2 times larger heap).

 

GC is parallel and generally scales well with hardware parallelism. So it can make sense to set GOMAXPROCS to higher value even for sequential programs just to speed up garbage collections. However, note that number of garbage collector threads is currently bounded by 8.

 

Memory Allocator Trace

 

Memory allocator traces simply dumps all memory allocation and free operations onto console. It's enabled with GODEBUG=allocfreetrace=1 environment variable. The output looks along the lines of:

The trace contains address of the memory block, size, type, goroutine id and the stack trace.

It's probably more useful for debugging, but can give very fine-grained info for allocation optimizations as well.

 

Scheduler Trace

 

Scheduler trace can provide insights into dynamic behavior of the goroutine scheduler and allow to debug load balancing and scalability issues. To enable the scheduler trace trace, run the program with GODEBUG=schedtrace=1000 environment variable (the value means period of output, in ms, in this case it's once per second):

$ GODEBUG=schedtrace=1000 ./myserver

Then the program will print output similar to the following during execution:

The first number ("1004ms") is time since program start. Gomaxprocs is the current value of GOMAXPROCS. Idleprocs is the number of idling processors (the rest are executing Go code). Threads is the total number of worker threads created by the scheduler (threads can be in 3 states: execute Go code (gomaxprocs-idleprocs), execute syscalls/cgocalls or idle). Idlethreads is the number of idling worker threads. Runqueue is the length of global queue with runnable goroutines. The numbers in square brackets ("[0 1 0 3]") are lengths of per-processor queues with runnable goroutines. Sum of lengths of global and local queues represents the total number of goroutines available for execution.

Note: You can combine any of the tracers as GODEBUG=gctrace=1,allocfreetrace=1,schedtrace=1000.

Note: There is also detailed scheduler trace, which you can enable with GODEBUG=schedtrace=1000,scheddetail=1. It prints detailed info about every goroutine, worker thread and processor. We won't describe its format here as it's mainly useful for scheduler developers; but you can find details in src/pkg/runtime/proc.c.

 

The scheduler trace is useful when a program does not scale linearly with GOMAXPROCS and/or does not consume 100% of CPU time. The ideal situation is when all processors are busy executing Go code, number of threads is reasonable, there is plenty of work in all queues and the work is reasonably evenly distributed:

 

gomaxprocs=8 idleprocs=0 threads=40 idlethreads=5 runqueue=10 [20 20 20 20 20 20 20 20]

A bad situation is when something of the above does not hold. For example the following sample demonstrates shortage of work to keep all processors busy:

 

gomaxprocs=8 idleprocs=6 threads=40 idlethreads=30 runqueue=0 [0 2 0 0 0 1 0 0]

 

Note: use OS-provided means to measure actual CPU utilization as the ultimate characteristic. On Unix family of operating system it is top command; on Windows it is Task Manager.

 

You can use the goroutine profiler to understand where goroutines block in the case of work shortage. Note that load imbalance is not ultimately bad as long as all processors are busy, it will just cause some moderate load balancing overheads.

 

Memory Statistics

 

Go runtime exposes coarse-grained memory statistics via runtime.ReadMemStats function. The statistics are also exposed via net/http/pprof at the bottom of  http://myserver:6060/debug/pprof/heap?debug=1. The statistics are described here.

Some of the interesting fields are:

1. HeapAlloc - current heap size.

2. HeapSys - total heap size.

3. HeapObjects - total number of objects in the heap.

4. HeapReleased - amount of memory released to the OS; runtime releases to the OS memory unused for 5 minutes, you can force this process with runtime/debug.FreeOSMemory.

5. Sys - total amount of memory allocated from OS.

6. Sys-HeapReleased - effective memory consumption of the program.

7. StackSys - memory consumed for goroutine stacks (note that some stacks are allocated from heap and are not accounted here, unfortunately there is no way to get total size of stacks (https://code.google.com/p/go/issues/detail?id=7468)).

8. MSpanSys/MCacheSys/BuckHashSys/GCSys/OtherSys - amount of memory allocated by runtime for various auxiliary purposes; they are generally not interesting, unless they are too high.

9. PauseNs - durations of last garbage collections.

 

Heap Dumper

 

The last available tool is heap dumper, it can write state of the whole heap into a file for future exploration. It can be useful for identifying memory leaks and getting insights into program memory consumption.

 

First, you need to write the dump using runtime/debug.WriteHeapDump function:

Then you can either render it to a dot file with graphical representation of the heap or convert it to hprof format. To render it to a dot file:

$ go get github.com/randall77/hprof/dumptodot

$ dumptodot heapdump mybinary > heap.dot

and open heap.dot with Graphviz.

 

To convert it to hprof format:

$ go get github.com/randall77/hprof/dumptohprof

$ dumptohprof heapdump heap.hprof

$ jhat heap.hprof

and navigate your browser to http://localhost:7000.

 

Concluding Remarks

 

Optimization is an open problem, there are simple recipes that you can use to improve performance. Sometimes optimization requires complete re-architecture of the program. But we hope that the tools will be a valuable addition to your toolbox, that you can use to at least analyze and understand what happens.

Profiling Go Programs is a good tutorial on usage of CPU and memory profilers to optimize a simple program.

---