Forem: Tyler Bui-Palsulich

Finding and fixing memory leaks in Go

Tyler Bui-Palsulich — Wed, 11 Aug 2021 15:05:22 +0000

This post reviews how I found a memory leak, how I fixed it, how I fixed similar issues in Google's sample Go code, and how we're improving our libraries to prevent this in the future.

The Google Cloud Client Libraries for Go generally use gRPC under the hood to connect with Google Cloud APIs. When you create an API client, the library initializes a connection to the API then leaves that connection open until you call Close on the Client.



client, err := api.NewClient()
// Check err.
defer client.Close()

Clients are safe to use concurrently, so you should keep the same Client around until you're done with it. But, what happens if you don't Close the client when you should?

You get a memory leak. The underlying connections never get cleaned up.

Google has a bunch of GitHub automation bots to help manage hundreds of GitHub repos. Some of our bots proxy their requests through a Go server running on Cloud Run. Our memory usage looked like a classic sawtooth memory leak:

I started debugging by adding the pprof.Index handler to the server:



mux.HandleFunc("/debug/pprof/", pprof.Index)

pprof provides runtime profiling data, like memory usage. See Profiling Go Programs on the Go Blog for more information.

Then, I built and started the server locally:



$ go build
$ PROJECT_ID=my-project PORT=8080 ./serverless-scheduler-proxy

Next, I sent a some requests requests to the server:



for i in {1..5}; do
curl --header "Content-Type: application/json" --request POST --data '{"name": "HelloHTTP", "type": "testing", "location": "us-central1"}' localhost:8080/v0/cron
echo " -- $i"
done

The exact payload and endpoint is specific to our server and is irrelevant for this post.

To get a baseline for what memory is being used, I collected some initial pprof data:



curl http://localhost:8080/debug/pprof/heap > heap.0.pprof

Inspecting the output, you can see some memory usage, but nothing immediately stands out as a large issue (which is good! We just started the server!):



$ go tool pprof heap.0.pprof
File: serverless-scheduler-proxy
Type: inuse_space
Time: May 4, 2021 at 9:33am (EDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 2129.67kB, 100% of 2129.67kB total
Showing top 10 nodes out of 30
      flat  flat%   sum%        cum   cum%
 1089.33kB 51.15% 51.15%  1089.33kB 51.15%  google.golang.org/grpc/internal/transport.newBufWriter (inline)
  528.17kB 24.80% 75.95%   528.17kB 24.80%  bufio.NewReaderSize (inline)
  512.17kB 24.05%   100%   512.17kB 24.05%  google.golang.org/grpc/metadata.Join
         0     0%   100%   512.17kB 24.05%  cloud.google.com/go/secretmanager/apiv1.(*Client).AccessSecretVersion
         0     0%   100%   512.17kB 24.05%  cloud.google.com/go/secretmanager/apiv1.(*Client).AccessSecretVersion.func1
         0     0%   100%   512.17kB 24.05%  github.com/googleapis/gax-go/v2.Invoke
         0     0%   100%   512.17kB 24.05%  github.com/googleapis/gax-go/v2.invoke
         0     0%   100%   512.17kB 24.05%  google.golang.org/genproto/googleapis/cloud/secretmanager/v1.(*secretManagerServiceClient).AccessSecretVersion
         0     0%   100%   512.17kB 24.05%  google.golang.org/grpc.(*ClientConn).Invoke
         0     0%   100%  1617.50kB 75.95%  google.golang.org/grpc.(*addrConn).createTransport

The next step was sending a bunch of requests to the server and seeing if we could (1) reproduce the seeming memory leak and (2) identify what the leak is.

Sending 500 requests:



for i in {1..500}; do
curl --header "Content-Type: application/json" --request POST --data '{"name": "HelloHTTP", "type": "testing", "location": "us-central1"}' localhost:8080/v0/cron
echo " -- $i"
done

Collecting and analyzing more pprof data:



$ curl http://localhost:8080/debug/pprof/heap > heap.6.pprof
$ go tool pprof heap.6.pprof
File: serverless-scheduler-proxy
Type: inuse_space
Time: May 4, 2021 at 9:50am (EDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 94.74MB, 94.49% of 100.26MB total
Dropped 26 nodes (cum <= 0.50MB)
Showing top 10 nodes out of 101
      flat  flat%   sum%        cum   cum%
   51.59MB 51.46% 51.46%    51.59MB 51.46%  google.golang.org/grpc/internal/transport.newBufWriter
   19.60MB 19.55% 71.01%    19.60MB 19.55%  bufio.NewReaderSize
    6.02MB  6.01% 77.02%     6.02MB  6.01%  bytes.makeSlice
    4.51MB  4.50% 81.52%    10.53MB 10.51%  crypto/tls.(*Conn).readHandshake
       4MB  3.99% 85.51%     4.50MB  4.49%  crypto/x509.parseCertificate
       3MB  2.99% 88.51%        3MB  2.99%  crypto/tls.Client
    2.50MB  2.49% 91.00%     2.50MB  2.49%  golang.org/x/net/http2/hpack.(*headerFieldTable).addEntry
    1.50MB  1.50% 92.50%     1.50MB  1.50%  google.golang.org/grpc/internal/grpcsync.NewEvent
       1MB     1% 93.50%        1MB     1%  runtime.malg
       1MB     1% 94.49%        1MB     1%  encoding/json.(*decodeState).literalStore

google.golang.org/grpc/internal/transport.newBufWriter really stands out as using a ton of memory! That's the first indication of what the leak is related to: gRPC. Looking at our application source code, the only place we were using gRPC was for Google Cloud Secret Manager:



client, err := secretmanager.NewClient(ctx) 
if err != nil { 
    return nil, fmt.Errorf("failed to create secretmanager client: %v", err) 
}

We never called client.Close() and created a Client on every request! So, I added a Close call and the problem went away:



defer client.Close()

I submitted the fix, it automatically deployed, and the sawtooth went away immediately!

Woohoo! 🎉🎉🎉

Around the same time, a user filed an issue on our Go sample repo for Cloud, which contains most of the Go samples for docs on cloud.google.com. The user noticed we forgot to Close the Client in one of our samples!

I had seen the same thing pop up a few other times, so I decided to investigate the entire repo.

I started with a rough estimate of how many affected files there were. Using grep, we can get a list of all files containing a NewClient style call, then pass that list to another invocation of grep to only list the files that don't contain Close, ignoring test files:



$ grep -L Close $(grep -El 'New[^(]*Client' **/*.go) | grep -v test

Oops! There were 207 files… For context, we have about 1300 .go files in the GoogleCloudPlatform/golang-samples repo.

Given the scale of the problem, I thought some automation would be worth it to get a rough start. I didn't want to write a full on Go program to edit the files, so I stuck with Bash:



$ grep -L Close $(grep -El 'New[^(]*Client' **/*.go) | grep -v test | xargs sed -i '/New[^(]*Client/,/}/s/}/}\ndefer client.Close()/'

Is it perfect? No. Did it make a huge dent in the amount of work? Yes!

The first part (up until test) is the exact same as above -- get a list of all of the possibly affected files (the ones that seem to create a Client but never call Close).

Then, I passed that list of files to sed for actual editing. xargs invokes the command you give it with each line of stdin being passed as an argument to the given command.

To understand the sed command, it helps to see what a sample usually looks like in the golang-samples repo (omitting imports and everything after client initialization):



// accessSecretVersion accesses the payload for the given secret version if one
// exists. The version can be a version number as a string (e.g. "5") or an
// alias (e.g. "latest").
func accessSecretVersion(w io.Writer, name string) error {
    // name := "projects/my-project/secrets/my-secret/versions/5"
    // name := "projects/my-project/secrets/my-secret/versions/latest"
    // Create the client.
    ctx := context.Background()
    client, err := secretmanager.NewClient(ctx)
    if err != nil {
        return fmt.Errorf("failed to create secretmanager client: %v", err)
    }
    // ...
}

At a high level, we initialize the client and check if there was an error. Whenever you check the error, there is a closing curly brace (}). I used that information to automate the editing.

The sed command is still a douzy, though:



sed -i '/New[^(]*Client/,/}/s/}/}\ndefer client.Close()/'

The -i says to edit the files in place. I'm OK with this because git can save me if I mess up.

Next, I used the s command to insert defer client.Close() right after the presumed closing curly brace (}) from checking the error.

But, I don't want to replace every }, I only want the first one after a call to NewClient. To do that, you can give an address range for sed to search.

An address range can include the start and end patterns to match before applying whatever command comes next. In this case, the start is /New[^(]*Client/, matching NewClient type calls, and the end (separated by a ,) is /}/, matching the next curly brace. That means our search and replace will only apply between the call to NewClient and the closing curly brace!

From knowing the error handling pattern above, the closing brace of the if err != nil condition is exactly where we want to insert our Close call.

Once I had automatically edited all of the samples, I ran goimports to fix the formatting. Then, I went through each edited file to make sure it did the right thing:

In server applications, should we actually close the client, or should we keep it around for future requests?
Is the name of the Client actually client or is it something else?
Is there more than one Client to Close?

Once that was done, I was left with 180 files edited.

The last order of business is trying to make it so this doesn't happen to users anymore. There are a few ways we have in mind:

Better samples. See above.
Better GoDoc. We updated our library generator to include a comment in the generated libraries saying to Close the Client when you're done with it. See https://github.com/googleapis/google-cloud-go/issues/3031.
Better libraries. Is there a way we can automatically Close clients? Finalizers? Have an idea of how we can do this better? Let us know on https://github.com/googleapis/google-cloud-go/issues/4498.

I hope you learned a bit about Go, memory leaks, pprof, gRPC, and Bash. I'd love to hear your stories about memory leaks you've found and what it took to fix them! If you have ideas about how we can improve our libraries or samples, let us know by filing an issue.

Why Go modules are faster than GOPATH

Tyler Bui-Palsulich — Mon, 10 Aug 2020 15:16:43 +0000

Downloading dependencies with Go modules can be significantly faster than using GOPATH-based dependency management. A fresh dependency download experiment for this post took 9 minutes and 33.845 seconds in GOPATH mode and 10.185 seconds in module mode. This post explains why. The key difference is that modules avoid deep repository clones and can use a module proxy.

For an introduction to Go modules, see https://blog.golang.org/using-go-modules.

GOPATH-based dependency management downloads every dependency into GOPATH/src, doing a deep clone of the version control repository in the process.

So, if you're in GOPATH mode and your project depends on A, which depends on B, which depends on C, the go command will git clone all three repositories (assuming they're all using git).

When using Go modules, you need two things when downloading a dependency:

The dependency's source code.
The dependency's go.mod file.

The go.mod file is used to figure out which version of every dependency you need. Once the go command collects all of the go.mod files from all of your dependencies, it can figure out which version of each dependency you need for your project.

For example, if you depend on modules A and B directly, and module A depends on v1.2.0 of module B, your module needs to depend on at a minimum B v1.2.0. This same idea is applied to every module you depend on, either directly or indirectly.

Side note: notice that if a new version of module A or B is released, that doesn't change the minimum version of B you must depend on. That requirement is stable over time.

Module proxy

Module proxies are a huge reason why Go modules are so much faster. A module proxy understands the two components you need from every module dependency: the source code and the go.mod file. That understanding leads to two separate optimizations:

Source code can be distributed as a zip file instead of a deep VCS clone. Downloading a single zip file is much faster than doing a full VCS clone, making module downloads more efficient than GOPATH.
You can download a go.mod file without getting the rest of the source code. This makes using a module proxy more efficient than not using a proxy.

Optimization #1 means when the go command downloads a dependency, there is less to download compared to GOPATH. Instead of having to (usually) do a full git clone, the go command downloads a single zip file with the source code of the module version you're asking for.

If you are using modules without a proxy, the go command does a shallow clone whenever possible. A shallow clone is much faster than a deep clone because you are only retrieving a single commit, rather than the full repository history.

The result is that, when using modules, there is simply less stuff to download compared to GOPATH.

Optimization #2, understanding go.mod files, is more subtle.

Just because a module is in your module graph doesn't mean it's in your import graph. The module graph includes the entire list of modules included in your go.mod file, all your dependencies' go.mod files, all of their dependencies' go.mod files, and so on. The import graph contains all of the packages imported by your project, the packages that those packages import, and so on. A module you depend on can contain packages you don't need to compile your project.

For example, let's say you depend on a database helper with support for Postgres, MySQL, and MongoDB. The helper has a separate package for each supported database and each one depends on a third-party module/package to communicate with that database. Your project only uses the helper's Postgres package, so you don't need the MySQL or MongoDB packages to build your project. Further, you don't need the source code for the MySQL or MongoDB modules to compile your project—they aren't in the import graph!

However, you do need the go.mod file for those modules. If a module is in your module graph, it must be taken into account when figuring out the minimum version of each dependency to use.

Here is where a module proxy comes to the rescue. A module proxy can give you just the go.mod file for any given module, without the source code. If you aren't using a proxy, you need to clone the entire repo (source code and all) just to get the go.mod file, knowing that code will never be compiled. Notably, as mentioned above, the go command in module mode does a shallow clone whenever possible.

When you're in GOPATH mode, the go command only downloads the dependencies that are in your import graph. So, this particular proxy optimization only improves performance compared to not using a module proxy. Lazy module loading (planned for Go 1.16) will speed up modules even more by reducing the number of go.mod files that the go command needs to fetch.

Results

The optimizations above mean that (1) the stuff you download is smaller and (2) there are fewer things to download.

Combined, a fresh module download can be around 5 times faster when using a proxy versus without. When compared to GOPATH, using modules with a proxy can be over 50 times faster.

It's theoretically possible for modules to be slower because you need to download each version of a dependency separately, rather than only having a single version of the dependency in your system. In practice, modules are much faster and the cache requires less space on disk, especially when you factor in standard GOPATH+vendoring patterns.

Try it out

To see these optimizations in action, try the following commands with a dependency of your choice. Starting with Go 1.13, the default module proxy is proxy.golang.org—if you're using Go 1.13 or later, using modules, and haven't adjusted GOPROXY, you're already getting these benefits.

I used Cloud Shell to run these tests. Your results may vary depending on the machine you're using, the Go version you're using, your network speed, the dependency you test with, and other factors.

Start by creating a temporary, empty GOPATH to test with to avoid deleting the normal GOPATH contents.

$ mkdir /tmp/tmp.GOPATH
$ export GOPATH=/tmp/tmp.GOPATH
$ go env GOPATH # Just to confirm.
/tmp/tmp.GOPATH

Now, try downloading a dependency in GOPATH mode. These commands use cloud.google.com/go/storage, but you can try with whatever dependency you'd like:
```
# Force GOPATH mode. Be sure the current directory
# doesn't have a go.mod.
$ export GO111MODULES=off
$ time go get cloud.google.com/go/storage
real    9m33.845s
user    4m1.197s
sys     0m18.079s
```
You can find the cloud.google.com/go/storage go.mod file on GitHub.

Next, try using Go modules. Create a new module to test with:

$ mkdir proxy-testing
$ cd proxy-testing
$ unset GO111MODULES # Back to the default.
$ go mod init example.com/proxy-testing

Now, try downloading a dependency without a proxy:

$ go clean -modcache # Careful!
$ go env -w GOPROXY=direct # direct means go directly to the source.
$ go env GOPROXY
direct
$ time go get cloud.google.com/go/storage
go: finding cloud.google.com/go/storage v1.10.0
...

real    2m6.396s
user    1m51.447s
sys     0m18.311s

Now try it with the proxy enabled (by resetting GOPROXY to the default):

$ go env -w GOPROXY=
$ go env GOPROXY
https://proxy.golang.org,direct
$ go clean -modcache # Careful!
$ go mod tidy # To start from the same state as before.
$ time go get cloud.google.com/go/storage
go: finding cloud.google.com/go/storage v1.10.0
...

real    0m10.185s
user    0m9.610s
sys     0m1.961s

Downloading cloud.google.com/go/storage took:

9m33.845s in GOPATH mode,
2m6.396s using modules without a proxy, and
10.185s using modules with a proxy (the default).

If you run these tests on your machine, the results will vary. However, modules are dramatically faster than GOPATH, especially when using the default proxy.