Date: Thu, 2 Mar 2023 13:08:38 +0100
From: 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?
Message-ID: <20230302130838.717e888d@karst>
In-Reply-To: <41c5766d-ed71-b70c-bbbc-d3396c462d62@enterprisedb.com>
References: <20230228190643.1e368315@karst>
	<45d453c8-b2d3-b477-36eb-32fdf4455f3c@enterprisedb.com>
	<20230301184840.0a897a80@karst>
	<3013398b-316c-638f-2a73-3783e8e2ef02@enterprisedb.com>
	<20230302001827.66e95dc3@karst>
	<41c5766d-ed71-b70c-bbbc-d3396c462d62@enterprisedb.com>
Organization: Dalibo
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: quoted-printable
Archived-At: 
 <https://www.postgresql.org/message-id/20230302130838.717e888d%40karst>
Precedence: bulk

On Thu, 2 Mar 2023 01:30:27 +0100
Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:
> On 3/2/23 00:18, Jehan-Guillaume de Rorthais wrote:
> >>> ExecHashIncreaseNumBatches was really chatty, having hundreds of thou=
sands
> >>> of calls, always short-cut'ed to 1048576, I guess because of the
> >>> conditional block =C2=AB/* safety check to avoid overflow */=C2=BB ap=
pearing early
> >>> in this function.  =20
> >[...] But what about this other short-cut then?
> >=20
> >     /* do nothing if we've decided to shut off growth */
> >     if (!hashtable->growEnabled)
> >         return;
> >=20
> >     [...]
> >=20
> >     /*
> >      * If we dumped out either all or none of the tuples in the table,
> >      * disable
> >      * further expansion of nbatch.  This situation implies that we have
> >      * enough tuples of identical hashvalues to overflow spaceAllowed.
> >      * Increasing nbatch will not fix it since there's no way to subdiv=
ide
> >      * the
> >      * group any more finely. We have to just gut it out and hope the s=
erver
> >      * has enough RAM.
> >      */
> >     if (nfreed =3D=3D 0 || nfreed =3D=3D ninmemory)
> >     {
> >         hashtable->growEnabled =3D false;
> >   #ifdef HJDEBUG
> >         printf("Hashjoin %p: disabling further increase of nbatch\n",
> >                hashtable);
> >   #endif
> >     }
> >=20
> > If I guess correctly, the function is not able to split the current bat=
ch,
> > so it sits and hopes. This is a much better suspect and I can surely tr=
ack
> > this from gdb.
>=20
> Yes, this would make much more sense - it'd be consistent with the
> hypothesis that this is due to number of batches exploding (it's a
> protection exactly against that).
>=20
> You specifically mentioned the other check earlier, but now I realize
> you've been just speculating it might be that.

Yes, sorry about that, I jumped on this speculation without actually diggin=
g it
much...

[...]
> But I have another idea - put a breakpoint on makeBufFile() which is the
> bit that allocates the temp files including the 8kB buffer, and print in
> what context we allocate that. I have a hunch we may be allocating it in
> the ExecutorState. That'd explain all the symptoms.

That what I was wondering as well yesterday night.

So, on your advice, I set a breakpoint on makeBufFile:

  (gdb) info br
  Num     Type           Disp Enb Address            What
  1       breakpoint     keep y   0x00000000007229df in makeBufFile
          bt 10
          p CurrentMemoryContext.name


Then, I disabled it and ran the query up to this mem usage:

   VIRT    RES    SHR S  %CPU %MEM
  20.1g   7.0g  88504 t   0.0 22.5

Then, I enabled the breakpoint and look at around 600 bt and context name
before getting bored. They **all** looked like that:

  Breakpoint 1, BufFileCreateTemp (...)                at buffile.c:201
  201     in buffile.c
  #0  BufFileCreateTemp (...)                             buffile.c:201
  #1  ExecHashJoinSaveTuple (tuple=3D0x1952c180, ...)       nodeHashjoin.c:=
1238
  #2  ExecHashJoinImpl (parallel=3Dfalse, pstate=3D0x31a6418) nodeHashjoin.=
c:398
  #3  ExecHashJoin (pstate=3D0x31a6418)                     nodeHashjoin.c:=
584
  #4  ExecProcNodeInstr (node=3D<optimized out>)            execProcnode.c:=
462
  #5  ExecProcNode (node=3D0x31a6418)
  #6  ExecSort (pstate=3D0x31a6308)
  #7  ExecProcNodeInstr (node=3D<optimized out>)
  #8  ExecProcNode (node=3D0x31a6308)
  #9  fetch_input_tuple (aggstate=3Daggstate@entry=3D0x31a5ea0)
 =20
  $421643 =3D 0x99d7f7 "ExecutorState"

These 600-ish 8kB buffer were all allocated in "ExecutorState". I could
probably log much more of them if more checks/stats need to be collected, b=
ut
it really slow down the query a lot, granting it only 1-5% of CPU time inst=
ead
of the usual 100%.

So It's not exactly a leakage, as memory would be released at the end of the
query, but I suppose they should be allocated in a shorter living context,
to avoid this memory bloat, am I right?

> BTW with how many batches does the hash join start?

* batches went from 32 to 1048576 before being growEnabled=3Dfalse as suspe=
cted
* original and current nbuckets were set to 1048576 immediately
* allowed space is set to the work_mem, but current space usage is 1.3GB, as
  measured previously close before system refuse more memory allocation.

Here are the full details about the hash associated with the previous backt=
race:

  (gdb) up
  (gdb) up
  (gdb) p *((HashJoinState*)pstate)->hj_HashTable
  $421652 =3D {
    nbuckets =3D 1048576,
    log2_nbuckets =3D 20,
    nbuckets_original =3D 1048576,
    nbuckets_optimal =3D 1048576,
    log2_nbuckets_optimal =3D 20,
    buckets =3D {unshared =3D 0x68f12e8, shared =3D 0x68f12e8},
    keepNulls =3D true,
    skewEnabled =3D false,
    skewBucket =3D 0x0,
    skewBucketLen =3D 0,
    nSkewBuckets =3D 0,
    skewBucketNums =3D 0x0,
    nbatch =3D 1048576,
    curbatch =3D 0,
    nbatch_original =3D 32,
    nbatch_outstart =3D 1048576,
    growEnabled =3D false,
    totalTuples =3D 19541735,
    partialTuples =3D 19541735,
    skewTuples =3D 0,
    innerBatchFile =3D 0xdfcd168,
    outerBatchFile =3D 0xe7cd1a8,
    outer_hashfunctions =3D 0x68ed3a0,
    inner_hashfunctions =3D 0x68ed3f0,
    hashStrict =3D 0x68ed440,
    spaceUsed =3D 1302386440,
    spaceAllowed =3D 67108864,
    spacePeak =3D 1302386440,
    spaceUsedSkew =3D 0,
    spaceAllowedSkew =3D 1342177,
    hashCxt =3D 0x68ed290,
    batchCxt =3D 0x68ef2a0,
    chunks =3D 0x251f28e88,
    current_chunk =3D 0x0,
    area =3D 0x0,
    parallel_state =3D 0x0,
    batches =3D 0x0,
    current_chunk_shared =3D 1103827828993
  }

For what it worth, contexts are:

  (gdb) p ((HashJoinState*)pstate)->hj_HashTable->hashCxt.name
  $421657 =3D 0x99e3c0 "HashTableContext"

  (gdb) p ((HashJoinState*)pstate)->hj_HashTable->batchCxt.name
  $421658 =3D 0x99e3d1 "HashBatchContext"

Regards,