JBD | 5458173 | 2017-09-06 14:08:31 -0700 | [diff] [blame] | 1 | Originally published at https://rakyll.org/custom-profiles/. |
| 2 | |
JBD | dc34def | 2017-09-07 09:41:24 -0700 | [diff] [blame] | 3 | ---- |
JBD | 5458173 | 2017-09-06 14:08:31 -0700 | [diff] [blame] | 4 | |
Shulhan | e8dc08f | 2019-01-30 21:40:12 +0700 | [diff] [blame] | 5 | Go provides several pprof profiles out of the box to gather |
JBD | 5458173 | 2017-09-06 14:08:31 -0700 | [diff] [blame] | 6 | profiling data from Go programs. |
| 7 | |
| 8 | The builtin profiles provided by the [runtime/pprof](https://golang.org/pkg/runtime/pprof/) package: |
| 9 | |
| 10 | * **profile**: CPU profile determines where a program spends its time while actively consuming CPU cycles (as opposed while sleeping or waiting for I/O). |
| 11 | * **heap**: Heap profile reports the currently live allocations; used to monitor current memory usage or check for memory leaks. |
| 12 | * **threadcreate**: Thread creation profile reports the sections of the program that lead the creation of new OS threads. |
| 13 | * **goroutine**: Goroutine profile report the stack traces of all current goroutines. |
| 14 | * **block**: Block profile show where goroutines block waiting on synchronization primitives (including timer channels). Block profile is not enabled by default; use runtime.SetBlockProfileRate to enable it. |
| 15 | * **mutex**: Mutex profile reports the lock contentions. When you think your CPU is not fully utilized due to a mutex contention, use this profile. Mutex profile is not enabled by default, see runtime.SetMutexProfileFraction to enable. |
| 16 | |
| 17 | Additional to the builtin profiles, [runtime/pprof](https://golang.org/pkg/runtime/pprof/) package allows you to export your custom profiles, and instrument your code to record |
| 18 | execution stacks that contributes to this profile. |
| 19 | |
| 20 | Imagine we have a blob server, and we are writing a Go client for it. And our users want to be able to profile the opened blobs on the client. We can create a profile and record the events of blob opening and closing, so the user can tell how many open blobs they are at any time. |
| 21 | |
| 22 | Here is a blobstore package that allows you to open some blobs. We will create a new custom profile and start |
| 23 | recording execution stacks that contributes to opening of blobs: |
| 24 | |
| 25 | ``` go |
| 26 | package blobstore |
| 27 | |
| 28 | import "runtime/pprof" |
| 29 | |
| 30 | var openBlobProfile = pprof.NewProfile("blobstore.Open") |
| 31 | |
| 32 | // Open opens a blob, all opened blobs need |
| 33 | // to be closed when no longer in use. |
| 34 | func Open(name string) (*Blob, error) { |
| 35 | blob := &Blob{name: name} |
| 36 | // TODO: Initialize the blob... |
| 37 | |
| 38 | openBlobProfile.Add(blob, 2) // add the current execution stack to the profile |
| 39 | return blob, nil |
| 40 | } |
| 41 | ``` |
| 42 | |
| 43 | And once users want to close the blob, we need to remove the execution stack associated with the current blob from the profile: |
| 44 | |
| 45 | ```go |
| 46 | // Close closes the blob and frees the |
| 47 | // underlying resources. |
| 48 | func (b *Blob) Close() error { |
| 49 | // TODO: Free other resources. |
| 50 | openBlobProfile.Remove(b) |
| 51 | return nil |
| 52 | } |
| 53 | ``` |
| 54 | |
| 55 | And now, from the programs using this package, we should be able to retrieve `blobstore.Open` profile data and use our daily pprof tools to examine and visualize them. |
| 56 | |
| 57 | Let's write a small main program than opens some blobs: |
| 58 | |
| 59 | ``` |
| 60 | package main |
| 61 | |
| 62 | import ( |
| 63 | "fmt" |
| 64 | "math/rand" |
| 65 | "net/http" |
| 66 | _ "net/http/pprof" // as a side effect, registers the pprof endpoints. |
| 67 | "time" |
| 68 | |
| 69 | "myproject.org/blobstore" |
| 70 | ) |
| 71 | |
| 72 | func main() { |
| 73 | for i := 0; i < 1000; i++ { |
| 74 | name := fmt.Sprintf("task-blob-%d", i) |
| 75 | go func() { |
| 76 | b, err := blobstore.Open(name) |
| 77 | if err != nil { |
| 78 | // TODO: Handle error. |
| 79 | } |
| 80 | defer b.Close() |
| 81 | |
Shulhan | e8dc08f | 2019-01-30 21:40:12 +0700 | [diff] [blame] | 82 | // TODO: Perform some work, write to the blob. |
JBD | 5458173 | 2017-09-06 14:08:31 -0700 | [diff] [blame] | 83 | }() |
| 84 | } |
| 85 | http.ListenAndServe("localhost:8888", nil) |
| 86 | } |
| 87 | ``` |
| 88 | |
| 89 | Start the server, then use go tool to read and visualize the profile data: |
| 90 | |
| 91 | ``` |
| 92 | $ go tool pprof http://localhost:8888/debug/pprof/blobstore.Open |
| 93 | (pprof) top |
| 94 | Showing nodes accounting for 800, 100% of 800 total |
| 95 | flat flat% sum% cum cum% |
| 96 | 800 100% 100% 800 100% main.main.func1 /Users/jbd/src/hello/main.go |
| 97 | ``` |
| 98 | |
| 99 | You will see that there are 800 open blobs and all openings are coming from main.main.func1. In this small example, there is nothing more to see, but in a complex server you can examine the hottest spots that works with an open blob and find out bottlenecks or leaks. |