unique: Handle memory leaks; cleanup goroutine can't keep up

[bradfitz]

Go version

go version go1.24.0 darwin/arm64
go version go1.24.0 linux/amd64
go version go1.23.6 darwin/arm64
go version go1.23.6 linux/amd64

What did you do?

We have a server that processes a stream of user connect & disconnect events from our edge servers. Users are identified by a [32]byte public key, wrapped up like:

type NodePublic struct {
   k [32]byte
}

This server maintains ~4 maps keyed by NodePublic. Out of curiosity and as an experiment, we decided to kick the tires with unique.Handle to make those maps instead be keyed by unique.Handle[NodePublic] to make them 8 bytes instead of 32. It saves about 96 bytes per connection. Not a ton, but ... an experiment.

The experiment didn't go as expected.

What did you see happen?

What we saw happen was unbounded memory growth and kernel OOMs. These are the two instances of this server we run. (it's an internal debug tool only, so we only run two for HA reasons)

It previously took about ~1GB of memory at steady state. With unique.Handle, it just keeps growing until the kernel OOM kills it.

The flat parts in the graph are where we changed the map key types from unique.Handle[NodePublic] back to just NodePublic, changing nothing else.

To debug, I hacked up the unique package (patch: https://gist.github.com/bradfitz/06f57b1515d58fb4d8b9b4eb5a84262e) to try out two things:

• see if the weak pointers were getting tinyalloc'ed and preventing GC. To counter this, I tried making the unique package use 24 byte value types in its uniqueMap. No change.
• to log stats when the cleaners ran to see how much it tried to delete
• Oh, and I also tried both Go 1.23.6 and Go 1.24.0

The result is that never frees anything. The weak pointer is never nil. It takes ever longer to iterate over the map (up to 2.7 seconds now), never finding anything to delete:

Feb 16 00:30:44 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2 ; deleted= 0 ; kept= 2 ; took  16µs
Feb 16 00:30:46 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2829766 ; deleted= 0 ; kept= 2829766 ; took  2.585244s
Feb 16 00:32:51 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2 ; deleted= 0 ; kept= 2 ; took  14µs
Feb 16 00:32:53 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2850211 ; deleted= 0 ; kept= 2850211 ; took  2.692595s
Feb 16 00:34:58 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2 ; deleted= 0 ; kept= 2 ; took  19µs
Feb 16 00:35:01 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2870410 ; deleted= 0 ; kept= 2870410 ; took  2.728681s
Feb 16 00:37:06 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2 ; deleted= 0 ; kept= 2 ; took  19µs
Feb 16 00:37:08 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2890817 ; deleted= 0 ; kept= 2890817 ; took  2.635071s
Feb 16 00:39:13 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2 ; deleted= 0 ; kept= 2 ; took  18µs
Feb 16 00:39:16 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2911098 ; deleted= 0 ; kept= 2911098 ; took  2.600478s
Feb 16 00:41:20 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2 ; deleted= 0 ; kept= 2 ; took  19µs
Feb 16 00:41:22 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2931399 ; deleted= 0 ; kept= 2931399 ; took  2.606853s
Feb 16 00:43:27 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2 ; deleted= 0 ; kept= 2 ; took  20µs
Feb 16 00:43:29 derptrackd2 derptrackd[771925]: XXX did unique cleanup loop: items= 2951574 ; deleted= 0 ; kept= 2951574 ; took  2.701304s

Looking at historical logs, it never deletes anything on Linux.

I tried to write a repro (on my Mac) and I failed, despite a bunch of efforts.

I ended up doing too much debugging on a remote AWS VM, with a hacked up Go toolchain.

Eventually I ran the same code on my Mac (same server + same hacked up Go toolchain), pulling from the same data sources, and surprisingly: it worked! unique finds weak things to delete in its cleaner and it doesn't grow.

In summary:

• unique leaks on linux/amd64 (prod cloud VM)
• same code on same data doesn't leak on darwin/arm64 (my dev laptop)

I'll now try revisiting my standalone repro but running it on Linux instead of macOS.

I had hoped to deliver @mknyszek a bug on a silver platter before filing, but I'm going a little crazy at this pointed and figured it was time to start sharing.

What did you expect to see?

No memory leaks on Linux also.

[gabyhelp]

Related Issues

• unique: Fatal errors (found bad pointer in Go heap, found pointer to free object) and memory corruption #69643 (closed)
• unique: large string still referenced, after interning only a small substring #69370 (closed)
• unique: fatal error: found pointer to free object #69210 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[bradfitz]

Actually, I'm going to close this for now until there's something actionable. I'll reopen if/when I have a repro.

[mknyszek]

up to 2.7 seconds now

Tangentially related, but we should probably remove the loop and switch to runtime.AddCleanup. I don't think that'll fix this issue though.

[bradfitz]

I played with hacking away at the server, trying to minimize the real code down to minimal repro instead of building up a minimal repro from scratch, with the goal to eventually plug in a in-memory generated random data source rather than reading from the network.

That seemed to have worked.... at a certain point, Linux started reclaiming a small amount of memory on a test Linux box I was running. And over night it did one huge unique.Handle reclaim during one of its GCs, but zero for all the others throughout the night.

Now I need to binary search my deletions and see what the key deletion was.

In any case, it still reclaims super slowly on Linux even after my minimization.

Will report back when I have more.

[bradfitz]

Okay, I think I've narrowed it down and figured out the macOS-vs-Linux difference: this is about the number goroutines producing new unique.Handles overwhelming the sole cleanup goroutine. My Mac laptop (M4 Max) is just significantly beefier than my dinky Linux VMs (both prod & dev).

Now I understand why my ground-up repro didn't work before: it was using a single goroutine.

I have a standalone repro now from the full server that doesn't depend on the network (using 100 goroutines adding+removing keys) but now that I think I know what's happening, I think I'll switch back to my bottom-up repro, slapping on some goroutines.

So @mknyszek, maybe runtime.AddCleanup is indeed the answer here.

[bradfitz]

Here ya go: https://go.dev/play/p/rrNRBh6g-WF

Ignore that that's a playground link and also that it's written as a test function. Just run it locally (on either macOS or Linux) and watch it leak.

Running WithoutUnique, it doesn't grow:

% GODEBUG=gctrace=1 go test -v -run=WithoutUnique
...
gc 35 @27.366s 0%: 0.13+54+0.10 ms clock, 2.2+1.7/134/0+1.7 ms cpu, 3589->3667->1814 MB, 3715 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1500000; 3660669760 HeapAlloc, 2440.45 per item
gc 36 @28.590s 0%: 0.20+31+0.10 ms clock, 3.2+3.3/121/0+1.7 ms cpu, 3501->3544->1780 MB, 3629 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499999; 3702783968 HeapAlloc, 2468.52 per item
gc 37 @29.773s 0%: 0.12+36+0.038 ms clock, 1.9+2.8/135/0+0.61 ms cpu, 3433->3483->1790 MB, 3562 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499999; 3750955328 HeapAlloc, 2500.64 per item
    uniqueleak_test.go:124: # items = 1499984; 3678439048 HeapAlloc, 2452.32 per item
gc 38 @30.970s 0%: 0.18+50+0.11 ms clock, 2.8+3.2/128/0+1.8 ms cpu, 3451->3520->1810 MB, 3581 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499999; 3622019400 HeapAlloc, 2414.68 per item
gc 39 @32.194s 0%: 0.21+52+0.17 ms clock, 3.4+2.1/144/0+2.8 ms cpu, 3491->3563->1816 MB, 3622 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1500000; 3665755200 HeapAlloc, 2443.84 per item
gc 40 @33.458s 0%: 0.10+64+0.060 ms clock, 1.6+3.2/128/0+0.97 ms cpu, 3551->3642->1837 MB, 3633 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1500000; 3755686688 HeapAlloc, 2503.79 per item
gc 41 @34.742s 0%: 0.20+52+0.039 ms clock, 3.2+3.0/135/0+0.62 ms cpu, 3582->3655->1821 MB, 3675 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1500000; 3832429984 HeapAlloc, 2554.95 per item

But using unique, it leaks (with my hacked up unique package doing extra logging, as linked above)

% GODEBUG=gctrace=1 go test -v -run=WithUnique
gc 20 @17.533s 5%: 0.16+1023+0.010 ms clock, 2.6+501/4094/8.2+0.16 ms cpu, 6973->8495->4847 MB, 8189 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499986; 8882974072 HeapAlloc, 5922.04 per item
    uniqueleak_test.go:124: # items = 1499999; 8880822872 HeapAlloc, 5920.55 per item
    uniqueleak_test.go:124: # items = 1499996; 8541901672 HeapAlloc, 5694.62 per item
    uniqueleak_test.go:124: # items = 1499983; 8328100968 HeapAlloc, 5552.13 per item
    uniqueleak_test.go:124: # items = 1499986; 9557681720 HeapAlloc, 6371.85 per item
gc 21 @22.366s 5%: 0.16+1267+0.010 ms clock, 2.5+802/5066/14+0.17 ms cpu, 8255->10094->5671 MB, 9694 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499980; 10552296616 HeapAlloc, 7034.96 per item
    uniqueleak_test.go:124: # items = 1499996; 10549919064 HeapAlloc, 7033.30 per item
    uniqueleak_test.go:124: # items = 1499987; 10354593096 HeapAlloc, 6903.12 per item
    uniqueleak_test.go:124: # items = 1499997; 9738898648 HeapAlloc, 6492.61 per item
    uniqueleak_test.go:124: # items = 1499993; 10020571944 HeapAlloc, 6680.41 per item
    uniqueleak_test.go:124: # items = 1499984; 11420736632 HeapAlloc, 7613.91 per item
XXX did unique cleanup loop:  7469606 items 3946215 deleted 3523391 kept; took  26.446266s
XXX starting unique cleanup loop
gc 22 @28.087s 6%: 0.14+1478+0.010 ms clock, 2.3+1673/5913/9.8+0.17 ms cpu, 9659->11751->6463 MB, 11343 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499988; 12283776280 HeapAlloc, 8189.25 per item
    uniqueleak_test.go:124: # items = 1499997; 12282524312 HeapAlloc, 8188.37 per item
    uniqueleak_test.go:124: # items = 1499818; 12138670280 HeapAlloc, 8093.43 per item
    uniqueleak_test.go:124: # items = 1499987; 11612830136 HeapAlloc, 7741.95 per item
    uniqueleak_test.go:124: # items = 1499982; 10844047640 HeapAlloc, 7229.45 per item
    uniqueleak_test.go:124: # items = 1499975; 11746102088 HeapAlloc, 7830.87 per item
    uniqueleak_test.go:124: # items = 1499997; 13196850496 HeapAlloc, 8797.92 per item
gc 23 @34.794s 6%: 0.11+1706+0.013 ms clock, 1.8+2438/6823/4.2+0.20 ms cpu, 11008->13350->7317 MB, 12927 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499989; 13948964920 HeapAlloc, 9299.38 per item
    uniqueleak_test.go:124: # items = 1499989; 13947515720 HeapAlloc, 9298.41 per item
    uniqueleak_test.go:124: # items = 1499946; 13924360552 HeapAlloc, 9283.24 per item
    uniqueleak_test.go:124: # items = 1499997; 13429541096 HeapAlloc, 8953.05 per item
    uniqueleak_test.go:124: # items = 1499987; 12570533544 HeapAlloc, 8380.43 per item
    uniqueleak_test.go:124: # items = 1499985; 12730948488 HeapAlloc, 8487.38 per item
    uniqueleak_test.go:124: # items = 1499980; 13995042328 HeapAlloc, 9330.15 per item
    uniqueleak_test.go:124: # items = 1499991; 15426806832 HeapAlloc, 10284.60 per item
gc 24 @42.260s 7%: 0.14+1943+0.013 ms clock, 2.2+3785/7772/4.1+0.21 ms cpu, 12462->15056->8208 MB, 14635 MB goal, 0 MB stacks, 0 MB globals, 16 P
    uniqueleak_test.go:124: # items = 1499988; 15727126728 HeapAlloc, 10484.84 per item
    uniqueleak_test.go:124: # items = 1499995; 15726441208 HeapAlloc, 10484.33 per item
    uniqueleak_test.go:124: # items = 1499995; 15724350536 HeapAlloc, 10482.94 per item

Note that there are multiples GCs happening while the unique cleanup func is still running.

[bradfitz]

Yeah, AddCleanup seems to do the trick. But it's not enough by itself. It also needs a bit of back pressure. Here's a trashy fix:

https://gist.github.com/bradfitz/a136006f112fee47ce1d87232e779d24

(I've signed the CLA; consider that trashy patch safe to look at 😅)

[bradfitz]

A potential fix for Go 1.23 (without using Go 1.24's AddCleanup) is https://gist.github.com/bradfitz/901f14f9c6dfd5c9344673a2c9478932 , making new handles wait for any ongoing cleanup to finish, but it's a bit too aggressive: it makes all goroutines wait.

But it works. 🤷‍♂

[mknyszek]

Hm... We should make the unique cleanup more efficient by using runtime.AddCleanup (we can use finalizers in Go 1.23, maybe), but (just musing here) the fact that that's not enough and it still needs some kind of back-pressure mechanism makes me wonder if maybe any kind of canonicalization map just isn't worth it for this workload?

In other words, if there are so many new entries being created that deletion can't keep up, that suggests there isn't really all that much deduplication happening; that there are more inserts than lookups.

... But also maybe I'm wrong about that. Maybe there's enough of a benefit even if you only get, for example, 1 lookup on average after an insert, before a deletion. I'd love to understand this better if you can collect any metrics from production in an ad-hoc way, @bradfitz. And perhaps we need diagnostics (runtime/metrics, probably) to help people understand whether unique is actually working for them.

Off the top of my head, I'm not sure what the right back-pressure policy would be here. An alternative would be is that we could scale up deletions instead. Deletions on independent parts of the tree (especially for a big tree) should scale well in my testing. The runtime.AddCleanup cleanup function could put work on a queue instead of doing the deletion, and a pool of goroutines could consume this queue instead of just a single goroutine. We can scale this pool according to the rate of insertions (or even just always have enough goroutines on-hand to handle the load). There's a sort of natural back-pressure built-in as you start spending CPU time on these background cleaners, and the scheduler handles distribution of resources.

[mknyszek]

Thank you for the thorough investigation @bradfitz!!