Detecting memory fragmentation

[mystic pivot]

Hi, hoping to get some advice here -

I have a long running process which seems to leak memory. I've gone through the usual checks (leaky goroutines, pprof heap analysis) but I can't seem to find anything else now.
However the total mem consumed by the process constantly increases while the stats reported by expvar stay constant(ish).

The process is a webscraper that scrapes at a fairly constant rate. I read responses with io.ReadAll as I regex a lot of data. Would this result in potential memory fragmentation? This is the only thing I can think of at this point.

Screenshot attached of a dash showing the expvar metrics

EDIT: go 1.20, centos 8

[wintry lodge]

the go gc is pretty good at handling fragmentation
Are you sure it's not GOGC spiking ?

actually this looks like this might be madvise stuff.
(the GC marked the pages as reclaimable but the kernel doesn't feel it need to)

@mystic pivot for a simple test, can you add an endpoint or signal handler which runs runtime.Gc() and try to call it when it's pretty high such as the graph you are showing ?

if it stays like this you are likely correct

[mystic pivot]

Okay, will do. I tried something similar before, except I'd used debug.FreeOSMemory(). It would release a small amount of mem (~1gb on a 15gb process) which would then quickly be reallocated.

[wintry lodge]

intresting

[mighty forge]

unless this got changed in the past ~3 years, heap_sys should only grow

    // HeapSys is bytes of heap memory obtained from the OS.
    //
    // HeapSys measures the amount of virtual address space
    // reserved for the heap. This includes virtual address space
    // that has been reserved but not yet used, which consumes no
    // physical memory, but tends to be small, as well as virtual
    // address space for which the physical memory has been
    // returned to the OS after it became unused (see HeapReleased
    // for a measure of the latter).
    //
    // HeapSys estimates the largest size the heap has had.
    HeapSys uint64
``` <https://pkg.go.dev/runtime#MemStats>

[mystic pivot]

@mighty forge heap_sys is constant, but that increasing line is the system memory

unless I'm misinterpreting what you're saying

[mighty forge]

oh I got my colors wrong

ignore me then

[mystic pivot]

hahah

[wintry lodge]

your two blues are too close ^^

[wintry lodge]

I also got it wrong

[mighty forge]

yeah now I can see the distinction x)

[mystic pivot]

well I've added the endpoint and will wait until mem usage increases a bit

thanks for the suggestion

[mighty forge]

are you, perchance, using a large map? maps don't shrink, so if you're stuffing a huge amount of data into a map, clearing it and repeating, the backing memory will only grow (or stay the same)

[wintry lodge]

I'm pretty surethey do shrink if you completely empty a bucket which really only happens reliably if you clear the map fully.
But I think a heap profile would catch this.

[mighty forge]

hmm if they do that's new to me, at least until recently to completely "evict" you had to create a new map

I don't recall exactly what got retained

[mystic pivot]

Do you mean re-using a map? afaik in this application all my maps have finite lifespans

but I'll have to check, it's been a while since I wrote this one 😅

[mighty forge]

I mean if you don't know off the top of your head stick with external analysis, it's (was?) just a common place for memory growth

[wintry lodge]

@mighty forge ok so I've dug up my test script.
You are right the map does not shrink ever as long as it reachable.

What was happening is that my previous key was using strings as key, so when I was deleting elements (instead of m[k] = nil) I was seeing memory shrink, but this wasn't the map this was the keys being freed.

m[k] = nil has still to keep a reference to the keys in case someone do k := range m

Testing with map[int]struct{} shows a completely flat memory usage

Also this test script remind me how map's insert and lookup perf are O(log(n))

which is

[mystic pivot]

Okay, did my testing, both debug.FreeOSMemory and rutime.GC do not free system memory

[wintry lodge]

Looks like you could be right.
I would take an allocation profile (not heap profile), you would expect to see one piece of code allocation lots of objects.
It's probably thoses are many different sizes of objects but not required.

[mystic pivot]

Hmm, I'll do that but I fear the output might be quite muddy, I know the http requests are going to be causing massive numbers of allocations

as opposed to my working hypothesis, which is that ReadAll is constantly allocating variable sized buffers resulting in the fragmentation

will get back to you on this! thanks

[wintry lodge]

ReadAll could be cullprit but I don't expect so

Allocations above a certain size aren't slabbed so the GC should be able to clean them and reuse the pages even if sizes are different

[mystic pivot]

Build ID: d3ca4fb82daabed7e14e8ab9e6fb9da9ae0bf043
Type: alloc_space
Time: May 17, 2023 at 8:26am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 860.34GB, 81.94% of 1049.92GB total
Dropped 1078 nodes (cum <= 5.25GB)
Showing top 10 nodes out of 107
      flat  flat%   sum%        cum   cum%
  696.86GB 66.37% 66.37%   771.26GB 73.46%  io.ReadAll
   49.78GB  4.74% 71.11%    49.78GB  4.74%  compress/flate.(*dictDecoder).init (inline)
   25.33GB  2.41% 73.53%    38.36GB  3.65%  github.com/goccy/go-json.unmarshal
   20.86GB  1.99% 75.51%    20.86GB  1.99%  bytes.growSlice
   17.45GB  1.66% 77.18%    17.45GB  1.66%  bufio.NewReaderSize (inline)
   11.65GB  1.11% 78.29%    11.65GB  1.11%  bufio.NewWriterSize
   11.65GB  1.11% 79.40%    61.43GB  5.85%  compress/flate.NewReader
   10.10GB  0.96% 80.36%    10.10GB  0.96%  crypto/sha512.New384

is this what I'm looking for? or should I be looking at alloc_objects?

[wintry lodge]

Yes
Help yourself tho use go tool pprof -http localhost:8081 /path/to/your/binary allocs.pprof

[mystic pivot]

Ah

Yeah so it looks like ReadAll is comparatively hot to anything else,

So I guess I should try preallocating buffers rather that letting ReadAll grow buffers in 512b increments?

Unless you meant I should be looking at alloc_objects

[wintry lodge]

ReadAll use append to grow buffers it doesn't grow by 512

[wintry lodge]

I originally meant to but ReadAll is so above anything else it seems unlikely to be something else

still take a look

[mystic pivot]

👍 will do!

[mystic pivot]

Hmm, so I'd replaced ReadAll ops with io.Copy and used reusable memory buffers for writing into, unfortunately no change on climbing memory usage

Just that the base use is now higher at ~6gb as opposed to 2gb before

Interestingly, according to https://pkg.go.dev/runtime@master#MemStats.HeapInuse, taking HeapInuse minus HeapAlloc should give you an upper bound on fragmented memory, which only amounts to about 1gb at its peak. Unless I'm misinterpreting this and it is additive (ie increasing at a rate of 1gb or something)

[wintry lodge]

if you use a tool like htop, do you see RES climbing ?

[mystic pivot]

htop would be drastically different to top?

[wintry lodge]

yeah it's readable 🤣

(no)

[mystic pivot]

haha

well, yes. top shows constantly climbing RSS from 2gb all the way to 32gb when the oom killer kicks in

[wintry lodge]

Sounds like a leak, are you sure you don't see anything in your heap profile ?

Heap profiles can be tricky, with the default GC config you expect 1~3x more usage in RES vs what the golang heap reports (between heap overhead, what is garbage, ...)

[mystic pivot]

I understand this, and I was playing with the GOGC env variable before, with little success

[wintry lodge]

what is GOGC at right now ?

[mystic pivot]

but even when max heap was at 2gb, I'd see the RSS climb to 32

GOGC is now at 100

[wintry lodge]

that the default value right ?

[mystic pivot]

but manually forcing a GC via the endpoint I hooked up does nothing

barely moves the values

yes, 100 is default

[wintry lodge]

yeah, because it's actually 2X

since that on top of what you already had

There is GOMEMLIMIT which I use myself but if runtime.GC() do nothing this will also do nothing intresting

Sounds like you have a memory leak

[mystic pivot]

😩

I'll take a diff of a new profile in about an hour, but I imagine I'm not going to see anything particularly interesting in pprof seeing as the reported in-process stats are stable

Not sure how I'm going to track down this leak haha

[mighty forge]

Are you json decoding a []byte? I don't know what github.com/goccy/go-json does precisely, but I've seen a few "fast json" libs just pin the whole buffer so they can reduce allocations.

[mystic pivot]

Yes- perhaps I'll try replace it with the standard lib version

Thanks for the idea

[mystic pivot]

hmm, no improvement with the std lib json

[wintry lodge]

what are you io.Copying into ?

[mystic pivot]

a *bytes.Buffer

[wintry lodge]

that io.ReadAll but slightly worst

[mystic pivot]

they're all preallocated for the life of the application

[wintry lodge]

@mystic pivot try json.NewEncoder (it do buffering too but per json message)

[wintry lodge]

oh ok

[mystic pivot]

most of it isn't json, most of it is regexing through html

[wintry lodge]

@mystic pivot are you pooling them ?

[mystic pivot]

yes, the buffers are pooled

[wintry lodge]

(this is important because stuff in pools can be reclaimed by the GC)

@mystic pivot can you show a screenshot of heap_inuse profile ?

[mighty forge]

are you resetting them properly

[mystic pivot]

yep one sec

[mystic pivot]

I call buffer.Reset() before writing to it, that should be enough, no?

[wintry lodge]

if they don't I would expect stuff to get GCed not leak

[mighty forge]

my thought is around the lines of increasing the cap indefinitely

[mystic pivot]

this?

[mystic pivot]

The buffers are initialized with 0 cap and are increased if required. I guess if malicious input came in they could be increased indefinitely, but I think I'm resetting them correctly

Unless there's a correct way to reset them other than calling Reset()

[wintry lodge]

Ohhhhhh

@mystic pivot you got tricked

Don't do that 😉

@mystic pivot so the thing that sync.Pool doesn't really tell you is that it doesn't follow the same rules as you do

[mighty forge]

hmm I see a couple of issues in your bufferpool lib

[wintry lodge]

It creates multiple pools by CPU cores to avoid synchronisation costs and it has access to weak references (so the GC can reclaim stuff from the pool)

Just use sync.Pool

[mystic pivot]

wait let me stop you there haha

[mighty forge]

https://github.com/dteh/bufferPool/blob/main/bufferPool.go#L24
https://github.com/dteh/bufferPool/blob/main/bufferPool.go#L29

[mystic pivot]

Should I just use someone elses implementation? I just wrote this because the other ones seemed comparatively complex

[wintry lodge]

Just use sync.Pool

wrap it with type assertions if you want so you hide away thoses ugly any

[mighty forge]

sorry I got distracted by something else, in line 24 you meant >0
in line 29 is the big one, you are sharing buffers between multiple things since you put it in the pool then return it, which means the next Get will use that buffer even tho it's already being used

[mystic pivot]

Oops you're right on both of those. But would that really be the source of the leak? I imagine I'd just be writing bad data all over the place (within the buffer though)

but let me fix that and get back to you

[mighty forge]

Possibly but it would be a rather contrived sequence of events. For this to play out it would need to lead to unbounded growth of the underlying buffer

[mystic pivot]

As well as that I think I'd need to neglect calling Reset() while it's growing?

[mighty forge]

reset keeps the underlying buffer intact

if you grow to 20gb once, and then never write more than 20mb, you'll still have a 20gb buffer

[mystic pivot]

true, but I was more so thinking that with my 20-50kb inputs, calling Reset() would cause the inputs to start writing from the start of the buffer again

[mighty forge]

yes, but your code doesn't guarantee that necessarily since it's racy - but as I said, for this to be the cause it would have to be a bit contrived

your buffer list technically also has unbounded growth, but since it's just pointers you'd need it to be rather huge for it to show up in the graphs

[mystic pivot]

yeah, luckily it's limited by my application (unless I've written buggy code again)

[mighty forge]

all in all I'd scrap this and use sync.Pool as youth pointed out

be sure to implement at least a basic rejection policy to avoid poisoning it

[wintry lodge]

I wouldn't do this just because of the lack of weak references.

[mighty forge]

(that is to say, at a minimum, make it so you can't put buffers larger than N back in the pool)

[mighty forge]

hmm?

[wintry lodge]

A Pool is a set of temporary objects that may be individually saved and retrieved.

Any item stored in the Pool may be removed automatically at any time without notification. If the Pool holds the only reference when this happens, the item might be deallocated.

sync.Pool are handled specialy by the runtime, it can GC elements within a pool

Actually I'm not sure the GC does this

but still it's a neat feature

[mighty forge]

yeah that's the point isn't it? I'm not sure we're on the same wavelength

[wintry lodge]

Yes that the point, it's not a feature your custom pool have

sync.Pool is also mostly lock free, which is pita to implement

[mighty forge]

precisely, so their pool has effectively 100% retention, which while not a problem in and of itself, considering the topic is unbounded memory growth, it's at least relevant

[mystic pivot]

okay forgive my lack of knowledge on sync.Pool but is this essentially all I need to do?

create pool

        New: func() interface{} { return bytes.NewBuffer([]byte{}) },
    }

get a buffer
buffer := h.bp.Get().(*bytes.Buffer)

place buffer back into the pool (using a closure as the buffer ends up being used in a couple of places)

            if buffer.Cap() > 1*1024*1024 {
                return
            }
            buffer.Reset()
            h.bp.Put(buffer)
        }```

with buffers > 1mb being rejected

[wintry lodge]

don't dereference the pointer in New

[mystic pivot]

oops that's a typo haha

thanks

[wintry lodge]

buffer.Reset does not remove any buffer from memory. buffer.Reset do buf = buf[:0:cap(buf)], this keeps the capacity while putting the index at 0

To reject something you "just" don't put it back in

so next time someone will have to call New instead

[mighty forge]

place buffer back into the pool (using a closure as the buffer ends up being used in a couple of places)
careful, you need to ensure this function is called at most once

[mystic pivot]

That's fine, I'm happy to not need to reallocate, just that if it seems to start growing (ie past 1mb) then I 'eject' it

is that ok?

[wintry lodge]

yes

[mystic pivot]

yes, that is certainly something I'm making sure of

[wintry lodge]

oh I miss red your code

it's correct

[mystic pivot]

😄 thanks

[wintry lodge]

just so you know using a closure for this means you might have to allocate the pointer to the pointer to the buffer

because it gets captured

if you use an argument to defered function

defer func(buffer *bytes.Bytes){
            if buffer.Cap() > 1*1024*1024 {
                return
            }
            buffer.Reset()
            h.bp.Put(buffer)
}(buffer)

will never allocate (*assuming *bytes.Buffer is already heap allocated, which it is here)

[mystic pivot]

ah got it, thanks

[mystic pivot]

I'm thinking now it's just a cgo leak somewhere. I'm using a modified http lib so it feels like it could just be one of the cgo decoders leaking -_-

[wintry lodge]

would make sense

pprof doesn't track cgo code

[mystic pivot]

sooo update

stripped out the google brotli library and replaced it with a full-go implementation. saw a minor improvement but still leaking (albeit slower) memory.

then my server provider contacted me and told me one of the memory modules was logging a ton of errors (ecc) so they were going to replace the module

and now my memory leak problems are gone 🤣

so looks like it was mostly a hardware issue the whole time

[wintry lodge]

🤣

[mystic pivot]

hate my life