Go Developer Tools: Getting to Know Profiler Labels

Hey. My name is Marco. I am a system programmer at Badoo. I present to you the translation of a wonderful post by rakyll about a new feature in Go 1.9. It seems to me that labels will be very useful for profiling your Go programs. We at Badoo, for example, use a similar thing to tag pieces of code in our programs in C. And if the timer works and the stack trace is displayed in the log, then in addition to it, we display such a tag. In it, for example, it can be said that we processed photos of a user with a specific UID. This is incredibly useful, and I'm very glad that a similar opportunity appeared in Go.

Profiler labels appeared in Go 1.9 : the ability to add a key-value pair to the samples that the CPU profiler makes. The profiler collects and displays information about the hottest functions, where the processor spends the most time. The output of a conventional CPU profiler consists of the name of the function, the name of the source file and the line number in this file, and so on. From this data, you can also understand what parts of the code called these hot functions. You can even filter the output to get a deeper idea of ​​particular branches of execution.

Information about the full call stack is very useful, but this is not always enough to find a performance problem. A large number of Go programmers use Go to write servers, and it’s even more difficult to figure out where the performance problem is in the server. It is difficult to separate one execution branch from another or it is difficult to understand when only one execution branch causes problems (some user or a specific handler). Starting with Go 1.9, we have the opportunity to add additional information about the context of what is happening at the moment, and use this information in the profiler in order to get more isolated data.

Labels can be useful in many cases. Here are just the most obvious ones:

• You do not want the abstractions from your program to flow into the profiling process, but the data about your objects would be useful there. For example, for a web server it would be much more useful to see the URL in the profiler instead of bare function names.
• The stack trace is not enough to understand who was the initiator of the work. For example, a queue handler processes events that were created by someone earlier. A handler could mark his work with the name of this someone.
• To find a performance issue, it is critical to have a processing context.

Adding Labels

runtime/pprofSeveral new features for adding labels will appear in the package . Most users will use a function Dothat takes a context, adds labels to it, and passes the new context to the function f:

func Do(ctx context.Context, labels LabelSet, f func(context.Context))

Do records a set of labels only within the current goroutine. If you create new goroutines in f, you can pass the context as an argument.

labels := pprof.Labels("worker", "purge")
pprof.Do(ctx, labels, func(ctx context.Context) {
    // Делаем какую-либо работу...
    go update(ctx) // пробрасывает лейблы дальше
})

Work above will be marked with a label worker:purge.

We look at the output of the profiler

This section will demonstrate the use of the profiler with labels. After you have marked all the pieces of code that interest you with labels, it’s time to profile the code and look at the output of the profiler.

I will use the package net/http/pprofin this example. See the Profiling Go programs article for more details.

package main
import _ "net/http/pprof"
func main() {
    // Много кода...
    log.Fatal(http.ListenAndServe("localhost:5555", nil))
}

We collect data on the use of the CPU ...

$ go tool pprof http://localhost:5555/debug/pprof/profile

After the utility goes into interactive mode, you can see all the recorded labels with the command tags. Note that the pprof utility names their tags, even though they are called labels in the Go standard library.

(pprof) tags
http-path: Total 80
        70 (87.50%): /messages
        10 (12.50%): /user
worker: Total 158
       158 (  100%): purge

As you can see, there are two keys ( http-path, worker) and several values ​​for each. The http-path key points to HTTP handlers, and worker: purge points to the code from the example above.

Filtering by labels, we can focus, for example, only on the code from the handler /user.

(pprof) tagfocus="http-path:/user"
(pprof) top10 -cum
Showing nodes accounting for 0.10s, 3.05% of 3.28s total
      flat  flat%   sum%        cum   cum%
         0     0%     0%      0.10s  3.05%  main.generateID.func1 /Users/jbd/src/hello/main.go
     0.01s   0.3%   0.3%      0.08s  2.44%  runtime.concatstring2 /Users/jbd/go/src/runtime/string.go
     0.06s  1.83%  2.13%      0.07s  2.13%  runtime.concatstrings /Users/jbd/go/src/runtime/string.go
     0.01s   0.3%  2.44%      0.02s  0.61%  runtime.mallocgc /Users/jbd/go/src/runtime/malloc.go
         0     0%  2.44%      0.02s  0.61%  runtime.slicebytetostring /Users/jbd/go/src/runtime/string.go
         0     0%  2.44%      0.02s  0.61%  strconv.FormatInt /Users/jbd/go/src/strconv/itoa.go
         0     0%  2.44%      0.02s  0.61%  strconv.Itoa /Users/jbd/go/src/strconv/itoa.go
         0     0%  2.44%      0.02s  0.61%  strconv.formatBits /Users/jbd/go/src/strconv/itoa.go
     0.01s   0.3%  2.74%      0.01s   0.3%  runtime.memmove /Users/jbd/go/src/runtime/memmove_amd64.s
     0.01s   0.3%  3.05%      0.01s   0.3%  runtime.nextFreeFast /Users/jbd/go/src/runtime/malloc.go

This output contains only samples marked with a label http-path:/user. And in this conclusion, we can easily understand where the most loaded places / user handlers are.

You can also try commands tagshow, taghideand tagignorefor additional filtering. For example, tagignoreit gives you the opportunity to get data on all labels except for a given one. The filter below will return everything except the / user handler. In this case, worker:purgeand http-path:/messages.

(pprof) tagfocus=
(pprof) tagignore="http-path:/user"
(pprof) tags
http-path: Total 70
        70 (  100%): /messages
worker: Total 158
       158 (  100%): purge

If you try to visualize the filtered data, the output will show how much each label brings to the full “cost”.

Here you can see that it worker:purgebrought 0.07s, and the handler messages 0.03sin the function generateID.

Try it yourself!

Labels allow you to add additional information to the profiler that is not available from a simple call stack. If you need additional dimensions in your profiler, then you can try it now by downloading the beta version of Go 1.9 beta . Also try a package pprofutilto automatically wrap your HTTP paths with labels.

Go 1.9 beta 2 is currently available . There are no known bugs in it, but the development team asks to try it on their programs, and if problems arise, report it to the bug tracker. I want to say that it’s very, very easy to assemble Go and be on the cutting edge of development. The assembly itself takes no more than a minute. Go for it!