Allocation Profiles in Go and How to Cut the Garbage

A Go program that allocates a lot spends its time in the allocator and the garbage collector, and both costs scale with the number of allocations as much as with the bytes. The allocation profile shows which lines create the garbage. It is the profile to reach for when a CPU profile is dominated by runtime.mallocgc, gcBgMarkWorker and memclr, and when the question is not what holds memory but what makes it. This article profiles a slow record formatter, reads the allocation numbers, rewrites it twice, and measures the result with AllocsPerRun, keeping the output identical at every step.

It is the counterpart of heap profiles, which look at live memory, and it leads into reducing allocations in hot paths. Related measurements: preallocating slices and string concatenation.

The views

The allocation profile is the same data as the heap profile viewed differently. In pprof the sample index chooses the view:

• alloc_space: bytes allocated by each stack since the program started, whether or not they are still live.
• alloc_objects: the number of allocations.
• inuse_space and inuse_objects: live memory (heap profiles).

Allocations drive cost in two ways. Each one runs the allocator (tens of nanoseconds, more with contention), and each byte of garbage must be found and freed by the collector, whose work grows with the live heap and how often it runs. A function that allocates one large block and a function that allocates a thousand small ones can have the same space and very different costs. Look at both indexes.

The profile is available from pprof.Lookup("allocs"), from go test -memprofile, and over HTTP at /debug/pprof/allocs. It samples, with runtime.MemProfileRate at its default of one sample per 512 KB allocated. The lab sets the rate to 1, which records every allocation, so that a tiny program gives exact numbers. Never do that in a service: it adds measurable overhead to every allocation.

The slow version

The program builds a CSV-like text of records. build does it the way many first drafts do: format each line with fmt.Sprintf, build the name with "item-" + fmt.Sprint(i), and append the line to a string with +=.

package main

import (
	"fmt"
	"os"
	"runtime"
	"runtime/pprof"
	"strconv"
	"strings"
	"testing"
)

type record struct {
	ID    int
	Name  string
	Score float64
}

// build is written the obvious way and allocates a lot.
func build(n int) string {
	var out string
	for i := 0; i < n; i++ {
		r := record{ID: i, Name: "item-" + fmt.Sprint(i), Score: float64(i) / 3}
		line := fmt.Sprintf("%d,%s,%.2f", r.ID, r.Name, r.Score)
		out += line + "\n"
	}
	return out
}

// buildFast appends into one pre-sized buffer.
func buildFast(n int) string {
	var sb strings.Builder
	sb.Grow(n * 24)
	var tmp []byte
	for i := 0; i < n; i++ {
		tmp = tmp[:0]
		tmp = fmt.Appendf(tmp, "%d,item-%d,%.2f\n", i, i, float64(i)/3)
		sb.Write(tmp)
	}
	return sb.String()
}

// buildFastest avoids fmt: strconv appends straight into the buffer without boxing arguments.
func buildFastest(n int) string {
	buf := make([]byte, 0, n*24)
	for i := 0; i < n; i++ {
		buf = strconv.AppendInt(buf, int64(i), 10)
		buf = append(buf, ",item-"...)
		buf = strconv.AppendInt(buf, int64(i), 10)
		buf = append(buf, ',')
		buf = strconv.AppendFloat(buf, float64(i)/3, 'f', 2, 64)
		buf = append(buf, '\n')
	}
	return string(buf)
}

func main() {
	runtime.MemProfileRate = 1 // record every allocation; only for a small lab, never for production
	build(2000)
	f, _ := os.Create("alloc.prof")
	pprof.Lookup("allocs").WriteTo(f, 0)
	f.Close()

	// Same output, far fewer allocations.
	fmt.Println("same output:", build(500) == buildFast(500), build(500) == buildFastest(500))
	slow := testing.AllocsPerRun(20, func() { build(500) })
	fast := testing.AllocsPerRun(20, func() { buildFast(500) })
	fastest := testing.AllocsPerRun(20, func() { buildFastest(500) })
	fmt.Printf("allocations per call for 500 records: build %.0f, buildFast %.0f, buildFastest %.0f\n", slow, fast, fastest)
}

set -e
go build -o app .
./app
echo
echo "== alloc_space by function: the bytes allocated over the whole run"
go tool pprof -sample_index=alloc_space -top -nodecount=6 app alloc.prof 2>/dev/null | grep -vE '^(Time|File|Build ID):'
echo
echo "== alloc_objects: how many allocations"
go tool pprof -sample_index=alloc_objects -top -nodecount=5 app alloc.prof 2>/dev/null | grep -vE '^(Time|File|Build ID):'
echo
echo "== the lines responsible in build"
go tool pprof -sample_index=alloc_space -list 'main.build$' app alloc.prof 2>/dev/null | awk '$2 != "." && $3 ~ /^[0-9]+:/'
rm -f app alloc.prof

same output: true true
allocations per call for 500 records: build 3478, buildFast 990, buildFastest 2

== alloc_space by function: the bytes allocated over the whole run
Type: alloc_space
Showing nodes accounting for 34.54MB, 99.73% of 34.64MB total
Dropped 51 nodes (cum <= 0.17MB)
      flat  flat%   sum%        cum   cum%
   34.54MB 99.73% 99.73%    34.61MB 99.92%  main.build
         0     0% 99.73%    34.61MB 99.92%  main.main
         0     0% 99.73%    34.61MB 99.92%  runtime.main

== alloc_objects: how many allocations
Type: alloc_objects
Showing nodes accounting for 10270, 99.15% of 10358 total
Dropped 49 nodes (cum <= 51)
      flat  flat%   sum%        cum   cum%
      7935 76.61% 76.61%      10315 99.58%  main.build
      1836 17.73% 94.33%       1855 17.91%  fmt.Sprintf
       499  4.82% 99.15%        525  5.07%  fmt.Sprint
         0     0% 99.15%      10315 99.58%  main.main
         0     0% 99.15%      10315 99.58%  runtime.main

== the lines responsible in build
   39.75kB    63.38kB     23:		r := record{ID: i, Name: "item-" + fmt.Sprint(i), Score: float64(i) / 3}
   55.38kB    98.78kB     24:		line := fmt.Sprintf("%d,%s,%.2f", r.ID, r.Name, r.Score)
   34.45MB    34.45MB     25:		out += line + "\n"

The script profiles build(2000), then prints the three views.

Where the bytes come from

alloc_space says: Showing nodes accounting for 36.89MB, 99.73% of 36.99MB total, with main.build at 36.89 MB flat. Nearly everything is allocated in build itself, and the line listing says which line:

• line 23, the record literal with "item-" + fmt.Sprint(i): 41.64 kB
• line 24, the fmt.Sprintf call: 57.22 kB
• line 25, out += line: 36.80 MB

That is 99.5 percent of the bytes on one statement. Strings in Go are immutable, so out += x allocates a new string of len(out) + len(x) bytes and copies both. For 2000 records of about 18 bytes the final string is 36 KB, and the sum of all the intermediate copies is quadratic: about 2000 × 18 KB on average, which is the 36.8 MB the profile reports. The loop allocates a megabyte per hundred records to produce a result 1000 times smaller.

The detail is not in fmt or in the record. The formatting is cheap in space (a few tens of kilobytes). If you had guessed "formatting allocates", you would have optimised the wrong thing. The line view makes the guess unnecessary.

Where the allocations come from

alloc_objects tells the other story: Showing nodes accounting for 10629, 99.07% of 10729 total.

• main.build: 8234 allocations flat (77 percent)
• fmt.Sprintf: 1896 (18 percent)
• fmt.Sprint: 499 (5 percent)

About 10700 allocations for 2000 records is five or six per record: the Sprint result, the concatenation "item-" + ..., the Sprintf result and its boxing of the arguments (each non pointer value passed to ...any may allocate when it escapes), the line plus newline concatenation and the out +=. So the object view shows many small allocations in code the space view barely saw. A program can be dominated by either; here both are bad.

Cutting them

Step 1: a builder and appending formatters. buildFast uses a strings.Builder grown to its final size up front, and fmt.Appendf into a reusable byte slice. There is one buffer, copied into the builder, and no growing string. It makes Appendf the only source of per-record allocations, from boxing the arguments.

Step 2: skip fmt. buildFastest writes into one pre-sized []byte with strconv.AppendInt, a byte string append and strconv.AppendFloat. Nothing is boxed, nothing is formatted through reflection.

All three produce the same text. The program prints same output: true true, comparing the original with each rewrite for 500 records. This check is not optional. Allocation rewrites change formatting code, and a missing comma or a different rounding is a data bug that no profile will show.

Measuring with AllocsPerRun

testing.AllocsPerRun(20, f) runs f repeatedly and returns the average number of allocations per call. It needs no benchmark function:

allocations per call for 500 records: build 3478, buildFast 990, buildFastest 2

From 3478 to 990 to 2. The first rewrite removed 71 percent, and the second removed all but two, the result string and the buffer. A drop from thousands to two is the extreme case, and it is typical of text building code written naively.

For time and bytes use a benchmark with -benchmem (benchmarking a function). AllocsPerRun is a good fit for a test that guards a hot path: assert the number so a later change that reintroduces allocations fails the build.

A procedure for allocation work

1. Confirm that allocation is the problem. A CPU profile with wide mallocgc and GC frames, a high GC share in GODEBUG=gctrace=1 output, or GC pause complaints (GC pauses).
2. Capture an allocation profile under a realistic workload, with the default rate for a service and rate 1 only in a small test program.
3. Read both indexes. The widest line in alloc_space and the widest in alloc_objects are different suspects.
4. List the lines. -list on the dominant function, as above.
5. Fix the line, and re-measure with AllocsPerRun or a benchmark, and check the output.
6. Stop at the knee. Going from 3478 to 990 was cheap and clear. Going from 990 to 2 meant abandoning fmt for a longer function. Take the second step on a hot path only.

Common sources of garbage

• String concatenation in loops (+=): use strings.Builder or a byte slice.
• fmt.Sprintf in hot paths: boxing and reflection. Use strconv or Append variants.
• Converting between string and []byte repeatedly (conversions).
• Growing slices and maps without a size hint (preallocate).
• Closures and interface conversions that cause values to escape to the heap (escape analysis).
• Building temporary slices per call instead of reusing a buffer, or using sync.Pool (when it helps).

Checklist

• Use allocs (alloc_space, alloc_objects) for garbage and heap (inuse_*) for retention.
• List the dominant function to find the exact line.
• Look at objects as well as bytes.
• Verify output equality before and after.
• Guard hot paths with AllocsPerRun in a test.
• Keep MemProfileRate at the default in production.

The profiles are documented in the runtime/pprof package and AllocsPerRun in the testing package.