DIY pprof profiles using Go

August 3, 2021 | Matthias Loibl

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:

Polar Signals Showing Profile

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:

Polar Signals Showing Profile

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. 😎

Polar Signals Showing Profile

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.

Polar Signals Showing Profile

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!


Sign up for the latest Polar Signals news


More posts like this one

Continuous Profiler Cumulative Metrics

Our first major feature since our product launch: cumulative profiling metrics!

Mar 23, 2021 | Frederic Branczyk

Read more →

Perfessor - Continuous Profiling Without Instrumentation

Continuously profiling your applications without having to make modifications!

Mar 31, 2021 | Thor Hansen

Read more →

Demystifying Pprof Labels with Go

April 13, 2021 | Frederic Branczyk

Read more →