DIY pprof profiles using Go

Working at Polar Signals on the Continuous Profiling storage that is based on pprof, I had to learn more about the internals of pprof. Rather than working my way through this all alone let's take a deep dive together and see how things fit together to make the profiles we often use.

We will begin with Go structs and see how we end up with a flame graph representation of the example data we'll use.

The Profile Go struct

The fundamental building block is the profile.Profile Go struct:

type Profile struct {
	SampleType        []*ValueType
	DefaultSampleType string
	Sample            []*Sample
	Mapping           []*Mapping
	Location          []*Location
	Function          []*Function
	Comments          []string

	DropFrames string
	KeepFrames string

	TimeNanos     int64
	DurationNanos int64
	PeriodType    *ValueType
	Period        int64
	// contains filtered or unexported fields
}

Note: This struct is not the same that's used by proto which also takes care of serializing strings into the string table. That's a topic for another post.

Don't worry what all of these are just yet, as we are going to concentrate on the most important fields one step at a time to build a simple profile.

For now, let's create a test (by saving the source code as `profile_test.go`) that writes an empty profile to disk:

package profile_test

import (
	"os"
	"testing"

	"github.com/google/pprof/profile"
)

func TestProfile(t *testing.T) {
	// Create an empty new Profile we can start adding stuff to.
	p := profile.Profile{}

	// Create a new file to write the profile to.
	f, err := os.Create("profile.pb.gz")
	if err != nil {
		t.Fatal(err)
	}
	// Write the profile to the file.
	if err := p.Write(f); err != nil {
		t.Fatal(err)
	}
}

We can run the test by executing the `go test ./profile_test.go` command in our terminal.
Now next to that file you should see a file called `profile.pb.gz`. This file is just like the files you usually get from the pprof endpoints of your application, someone sends you for debugging or that people share on share.polarsignals.com for interactive debugging with others.

Currently, the profile has no samples and thus won't be able to be visualized:

Adding our first Sample with Function and Location

Now, to actually add some data to the pprof profile let's think of a simple function that we imagine to be profiling.

We want to see how many allocations that function has had since the process started. Therefore we chose the `allocs_space` profile type.

package main

import (
	"os"
	"testing"

	"github.com/google/pprof/profile"
)

func TestProfile(t *testing.T) {
	// Create an empty new Profile we can start adding stuff to.
	p := profile.Profile{}

+	// SampleType specifies what type the samples are of.
+	// Usually shown in the top of the profile visualization.
+	p.SampleType = []*profile.ValueType{{
+		Type: "alloc_space", // We want to have a profile that describes the allocations
+		Unit: "bytes",       // in bytes.
+	}}

	// Create a new file to write the profile to.
	f, err := os.Create("profile.pb.gz")
	if err != nil {
		t.Fatal(err)
	}
	// Write the profile to the file.
	if err := p.Write(f); err != nil {
		t.Fatal(err)
	}
}

Let's add a Sample (a measurement) of a function that we say had allocated 128 bytes:

package main

import (
	"os"
	"testing"

	"github.com/google/pprof/profile"
)

func TestProfile(t *testing.T) {
	// Create an empty new Profile we can start adding stuff to.
	p := profile.Profile{}

	// SampleType specifies what type the samples are of.
	// Usually shown in the top of the profile visualization.
	p.SampleType = []*profile.ValueType{{
		Type: "alloc_space", // We want to have a profile that describes the allocations
		Unit: "bytes",       // in bytes.
	}}

+	p.Sample = []*profile.Sample{{
+		Location: nil,
+		Value:    []int64{128},
+		// Says that the location allocated 128 bytes (because the first sample type is alloc_space).
+	}}

	// Create a new file to write the profile to.
	f, err := os.Create("profile.pb.gz")
	if err != nil {
		t.Fatal(err)
	}
	// Write the profile to the file.
	if err := p.Write(f); err != nil {
		t.Fatal(err)
	}
}

The visualization won't show anything yet, as we don't have any Location given, but on of the most important data points has been filled.

The `Value` of a Sample is a slice `[]int64` because, if we were to have more sample types than just _alloc_space_, for example, _in_use_, we would add the second Value as `[]int64{128, 100}`. That means that the order of `SampleType` dictates the order of Values too.

Next, let's add a Location that describes where in the memory the sample was recorded:

package main

import (
	"os"
	"testing"

	"github.com/google/pprof/profile"
)

func TestProfile2(t *testing.T) {
	// Create an empty new Profile we can start adding stuff to.
	p := profile.Profile{}

	// SampleType specifies what type the samples are of.
	// Usually shown in the top of the profile visualization.
	p.SampleType = []*profile.ValueType{{
		Type: "alloc_space", // We want to have a profile that describes the allocations
		Unit: "bytes",       // in bytes.
	}}

+	// Locations are addresses inside the processes memory.
+	p.Location = []*profile.Location{{
+		ID:      1,
+		Address: 123456789,
+	}}

	p.Sample = []*profile.Sample{{
-		Location: nil,
+		Location: []*profile.Location{p.Location[0]},
		Value:    []int64{128},
		// Says that the location allocated 128 bytes (because the first sample type is alloc_space).
	}}

	// Create a new file to write the profile to.
	f, err := os.Create("profile.pb.gz")
	if err != nil {
		t.Fatal(err)
	}
	// Write the profile to the file.
	if err := p.Write(f); err != nil {
		t.Fatal(err)
	}
}

As you can see we have now added one Location with the memory address `123456789`. Our sample from before now references that Location.

Visualizing the profile, by running `go test profile_test.go` and then `go tool pprof -http=:8080 profile.pb.gz`, now shows the following graph:

Exciting! We can see that something has used 128B (bytes)! 🎉

Because the `Mapping` is unknown for the `Location` it shows <unknown>. Adding a `Mapping` would already show the `Mapping` file name. For keeping this post shorter we'll skip this step.

Let's fix the naming next!

package main

import (
	"os"
	"testing"

	"github.com/google/pprof/profile"
)

func TestProfile(t *testing.T) {
	// Create an empty new Profile we can start adding stuff to.
	p := profile.Profile{}

	// SampleType specifies what type the samples are of.
	// Usually shown in the top of the profile visualization.
	p.SampleType = []*profile.ValueType{{
		Type: "alloc_space", // We want to have a profile that describes the allocations
		Unit: "bytes",       // in bytes.
	}}

+	// Functions give more meaning to the memory location like filename and function name.
+	p.Function = []*profile.Function{{
+		ID:         1,
+		Name:       "simpleFunction",
+		SystemName: "simpleFunction",
+		Filename:   "main.go",
+		StartLine:  0,
+	}}

	// Locations are addresses inside the processes memory.
	p.Location = []*profile.Location{{
		ID:      1,
		Address: 123456789,
+		Line: []profile.Line{{
+			Function: p.Function[0],
+			Line:     42,
+		}},
	}}

	p.Sample = []*profile.Sample{{
		Location: []*profile.Location{p.Location[0]},
		Value:    []int64{128},
		// Says that the location allocated 128 bytes (because the first sample type is alloc_space).
	}}

	// Create a new file to write the profile to.
	f, err := os.Create("profile.pb.gz")
	if err != nil {
		t.Fatal(err)
	}
	// Write the profile to the file.
	if err := p.Write(f); err != nil {
		t.Fatal(err)
	}
}

Running `go test profile_test.go` once again and then opening the profile with `go tool pprof -http=:8080 profile.pb.gz ` shows us that indeed we've now added the needed metadata to the sample. 😎

A slightly more complex sample

So far the profile is far from what you'd actually see in reality therefore let's create a somewhat more complicated sample.

package main

import (
	"os"
	"testing"

	"github.com/google/pprof/profile"
)

func TestProfile(t *testing.T) {
	// Create an empty new Profile we can start adding stuff to.
	p := profile.Profile{}

	// SampleType specifies what type the samples are of.
	// Usually shown in the top of the profile visualization.
	p.SampleType = []*profile.ValueType{{
		Type: "alloc_space", // We want to have a profile that describes the allocations
		Unit: "bytes",       // in bytes.
	}}

	// Functions give more meaning to the memory location like filename and function name.
	p.Function = []*profile.Function{{
		ID:         1,
		Name:       "simpleFunction",
		SystemName: "simpleFunction",
		Filename:   "main.go",
		StartLine:  0,
+	}, {
+		ID:         2,
+		Name:       "badFunction",
+		SystemName: "badFunction",
+		Filename:   "storage.go",
+		StartLine:  22,
+	}, {
+		ID:         3,
+		Name:       "badSubFunction",
+		SystemName: "badSubFunction",
+		Filename:   "storage.go",
+		StartLine:  42,
	}}

	// Locations are addresses inside the processes memory.
	p.Location = []*profile.Location{{
		ID:      1,
		Address: 123456789,
		Line: []profile.Line{{
			Function: p.Function[0],
			Line:     42,
		}},
+	}, {
+		ID:      2,
+		Address: 234567890,
+		Line: []profile.Line{{
+			Function: p.Function[1],
+			Line:     22,
+		}},
+	}, {
+		ID:      3,
+		Address: 234567891,
+		Line: []profile.Line{{
+			Function: p.Function[2],
+			Line:     42,
+		}},
	}}

	p.Sample = []*profile.Sample{{
		Location: []*profile.Location{p.Location[0]},
		Value:    []int64{128},
		// Says that the location allocated 128 bytes (because the first sample type is alloc_space).
+	}, {
+		Location: []*profile.Location{p.Location[2], p.Location[1]},
+		Value:    []int64{128 * 4},
+		// For demo purposes let's make this second function allocate 4 times as much.
	}}

	// Create a new file to write the profile to.
	f, err := os.Create("profile.pb.gz")
	if err != nil {
		t.Fatal(err)
	}
	// Write the profile to the file.
	if err := p.Write(f); err != nil {
		t.Fatal(err)
	}
}

As you can see we've added two new Functions, two new Locations, and then one new Sample.
The most important difference now is that the Location field of the Sample contains multiple Locations.

The order of these Locations is what makes up the underlying stack trace. In this example, it means that the `Location[1]` (our badFunction) was a function that called another function at `Location[2]` (our badSubFunction). Note, that somewhat counter-intuitively the first `Location` is the leaf and the last `Location` is the root of the stack trace. Each profile may contain many of these stack traces that make up the profiles as you normally see them.

Let's see how it looks visualized by running `go test profile_test.go` and `go tool pprof -http=:8080 profile.pb.gz`.

Perfect, just as we've hoped for we can now see visualized how the badFunction calls the badSubFunction that allocates four times as much as the simpleFunction from the previous example.

Conclusion

At first, the Go struct might not intuitively make sense. Maybe the `Functions` field makes sense, but working out way step by step from an empty profile to something the reassembles what we usually look at made understanding easier.

We started out by creating a single Sample that on its own was not that helpful yet. Therefore we created a Location next and referenced it from our sample - our first visualized graph still showing `<unknown>` though. We added a Function that we can reference from the Locations Line so that we get some actual function name. Our first full graph was done!

To make things a bit more realistic we've added multiple Samples, Locations, and Functions next to see how stack traces are represented. Exciting! 🎉

Going forward, you shouldn't be all too afraid when opening your editor and working with the in-memory representation of a profile.

If you would like to discuss this post, feel free to join our Discord community server!