Docker flame graphs

We released Docker 1.9 less than a month ago. Since then, we’ve got several reports of operations being slower than they used to be. The Docker daemon doesn’t consume lots of resources, but you might want to keep an eye on it. This post shows a few tools and techniques we use to measure and analyze metrics for the Docker daemon. Although, what you’re going to learn here can apply to any application written in Go.

One of the nice things of using Go is how well it integrates pprof into the standard library. It’s super easy to collect metrics if your application exposes an http endpoint. You can read about it in the net/http/pprof package. Docker loads the Go profiler into the api when you start the daemon in debug mode:

$ docker daemon --debug

We provide some extra debug information, besides the metrics explained in the pprof package. You can collect information about all the exported variables in the system. We use the expvar package to send that information in JSON format. You can also keep track of goroutines and heap allocations. We use some unexposed handlers for that. The code where we initialize the Docker profiler is pretty straight forward if you want to check it out.

Once we have an endpoint to get information from, we need to exercise the daemon to generate data.

Docker-stress is one of the tools we use for this. It’s a simple script capable of interacting with our CLI to run containers in a concurrent way. The default threshold to profile the daemon is set to 1000 containers. But we can change that and other settings with several flags:

$ docker-stress --concurrent 10 --containers 10000

Docker-stress times this operation to give us an initial estimate of how we’re doing:

ran 1011 containers in 349.26 seconds (2.89 container per sec. or 0.35 sec. per container)

We got good feedback recently about performance straight with the API. We ported the script provided in that report to Go and we’ve started to use it to collect more information.

It’s super easy to connect to the profiler while the daemon is running all those containers. We can use Go’s pprof tool and get the raw information from the profiler:

$ go tool pprof -raw http://127.0.0.1:2376/debug/pprof/profile

The problem is that the output is rather cryptic if you don’t know what you’re looking for. I’m going to avoid you the agony of scrolling down and I won’t paste all that information here. We need a tool to visualize where the Docker daemon is wasting all those extra CPU cycles, entering Flame graphs.

Flame graphs allow you to visualize the hot patch in your application in a quick and accurate way. The x-axis show the code in the application stack. A wider frame means that the function is longer in CPU. The order in the x-axis is not relevant. The y-axis represents the stack population. You can read it as any other stack trace, a function is at the top when it’s executed last. This is a simple flame graph for Docker PS command to get a first taste of them:

Docker PS flame graph

You can see the Docker daemon is spending most of its time in the getContainersJSON function. Although this is a simple glaph, we just unvealed an unexpected surprise. Look at the middle top of the graph, it looks like we’re connecting to some sort of SQLite3 database. That’s where Docker stores the naming graph for linked containers. And it turns out that’s linear operation. The more containers you have, the longer Docker PS is going to take in that operation. Don’t worry, we’re already working on removing that database dependency from the daemon.

Another nice thing about flame graphs is that you can browse through the stack. Feel free to open the original SVG to dive into the complete information.

Generating flame graphs is straight forward using Brendan Gregg’s scripts. Unfortunately, they don’t include an easy way to turn pprof data into a pretty graph.

Go-torch will help us do that. It collects pprof raw data and turns it into flame graphs for you. You can use it with binary data from running your tests, and you can also point it to a profile url to gather real time data:

$ go-torch --file docker-run.svg --url http://127.0.0.1:2376

Using go-torch, we were able to generate flame graphs for our stress tests. This first picture shows how the Docker daemon behaved in the previous 1.8.3 release:

Stress tests for Docker 1.8.3

This other graph shows how the newest 1.9.1 release behaves under the same conditions:

Stress test for Docker 1.9.1

This nicer visualization will help us to diagnose the causes of those performance regressions. For instance, we can see at first glance that the stack for 1.9.1 is much higher. It means that the Docker daemon is traversing much more code to do the same operations. There are several reasons for that, but we won’t cover them in this post.

Flame graphs are a super nice way to dive into unknown code. I’ve already been surprised with several unexpected behaviors that I discovered browsing them. Use them if you find yourself in a similar situation where things are slowing down and you don’t know why.