pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedFrom: Jehan-Guillaume de Rorthais <jgdr@dalibo.com>
To: Tomas Vondra <tomas.vondra@enterprisedb.com>
Cc: pgsql-hackers@lists.postgresql.org
Subject: Re: Memory leak from ExecutorState context?
Date: Wed, 1 Mar 2023 18:48:40 +0100
Message-ID: <20230301184840.0a897a80@karst> (raw)
In-Reply-To: <45d453c8-b2d3-b477-36eb-32fdf4455f3c@enterprisedb.com>
References: <20230228190643.1e368315@karst>
<45d453c8-b2d3-b477-36eb-32fdf4455f3c@enterprisedb.com>
Hi Tomas,
On Tue, 28 Feb 2023 20:51:02 +0100
Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:
> On 2/28/23 19:06, Jehan-Guillaume de Rorthais wrote:
> > * HashBatchContext goes up to 1441MB after 240s then stay flat until the end
> > (400s as the last record)
>
> That's interesting. We're using HashBatchContext for very few things, so
> what could it consume so much memory? But e.g. the number of buckets
> should be limited by work_mem, so how could it get to 1.4GB?
>
> Can you break at ExecHashIncreaseNumBatches/ExecHashIncreaseNumBuckets
> and print how many batches/butches are there?
I did this test this morning.
Batches and buckets increased really quickly to 1048576/1048576.
ExecHashIncreaseNumBatches was really chatty, having hundreds of thousands of
calls, always short-cut'ed to 1048576, I guess because of the conditional block
«/* safety check to avoid overflow */» appearing early in this function.
I disabled the breakpoint on ExecHashIncreaseNumBatches a few time to make the
query run faster. Enabling it at 19.1GB of memory consumption, it stayed
silent till the memory exhaustion (around 21 or 22GB, I don't remember exactly).
The breakpoint on ExecHashIncreaseNumBuckets triggered some times at beginning,
and a last time close to the end of the query execution.
> > Any idea? How could I help to have a better idea if a leak is actually
> > occurring and where exactly?
>
> Investigating memory leaks is tough, especially for generic memory
> contexts like ExecutorState :-( Even more so when you can't reproduce it
> on a machine with custom builds.
>
> What I'd try is this:
>
> 1) attach breakpoints to all returns in AllocSetAlloc(), printing the
> pointer and size for ExecutorState context, so something like
>
> break aset.c:783 if strcmp("ExecutorState",context->header.name) == 0
> commands
> print MemoryChunkGetPointer(chunk) size
> cont
> end
>
> 2) do the same for AllocSetFree()
>
> 3) Match the palloc/pfree calls (using the pointer address), to
> determine which ones are not freed and do some stats on the size.
> Usually there's only a couple distinct sizes that account for most of
> the leaked memory.
So here is what I end up with this afternoon, using file, lines and macro from
REL_11_18:
set logging on
set pagination off
break aset.c:781 if strcmp("ExecutorState",context.name) == 0
commands 1
print (((char *)(chunk)) + sizeof(struct AllocChunkData))
print chunk->size
cont
end
break aset.c:820 if strcmp("ExecutorState",context.name) == 0
commands 2
print (((char *)(chunk)) + sizeof(struct AllocChunkData))
print chunk->size
cont
end
break aset.c:979 if strcmp("ExecutorState",context.name) == 0
commands 3
print (((char *)(chunk)) + sizeof(struct AllocChunkData))
print chunk->size
cont
end
break AllocSetFree if strcmp("ExecutorState",context.name) == 0
commands 4
print pointer
cont
end
So far, gdb had more than 3h of CPU time and is eating 2.4GB of memory. The
backend had only 3'32" of CPU time:
VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2727284 2.4g 17840 R 99.0 7.7 181:25.07 gdb
9054688 220648 103056 t 1.3 0.7 3:32.05 postmaster
Interestingly, the RES memory of the backend did not explode yet, but VIRT is
already high.
I suppose the query will run for some more hours, hopefully, gdb will not
exhaust the memory in the meantime...
You'll find some intermediate stats I already collected in attachment:
* break 1, 2 and 3 are from AllocSetAlloc, break 4 is from AllocSetFree.
* most of the non-free'd chunk are allocated since the very beginning, before
the 5000's allocation call for almost 1M call so far.
* 3754 of them have a chunk->size of 0
* it seems there's some buggy stats or data:
# this one actually really comes from the gdb log
0x38a77b8: break=3 num=191 sz=4711441762604810240 (weird sz)
# this one might be a bug in my script
0x2: break=2 num=945346 sz=2 (weird address)
* ignoring the weird size requested during the 191st call, the total amount
of non free'd memory is currently 5488MB
I couldn't print "size" as it is optimzed away, that's why I tracked
chunk->size... Is there anything wrong with my current run and gdb log?
The gdb log is 5MB compressed. I'll keep it off-list, but I can provide it if
needed.
Stay tuned...
Thank you!
Attachments:
[application/gzip] allocs-tmp-stats.txt.gz (52.5K, ../20230301184840.0a897a80@karst/2-allocs-tmp-stats.txt.gz)
download
view thread (60+ messages) latest in thread
Message-ID: <20230301184840.0a897a80@karst>
Permalink: ../20230301184840.0a897a80@karst/
Also on: postgresql.org/message-id/20230301184840.0a897a80@karst
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: jgdr@dalibo.com, tomas.vondra@enterprisedb.com, pgsql-hackers@lists.postgresql.org
Subject: Re: Memory leak from ExecutorState context?
In-Reply-To: <20230301184840.0a897a80@karst>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox