Re: Out of Memory errors are frustrating as heck!

On Tue, Apr 16, 2019 at 11:46:51PM -0500, Justin Pryzby wrote:

>> I wonder if it'd be useful to compile with
>> ./configure CFLAGS=-DHJDEBUG=1
> Could you try this, too ?

OK, doing it now, here is what I'm getting in the log file now. I am
surprised I get so few rows here when there

2019-04-20 17:12:16.077 UTC [7093] LOG: database system was shut down at 2019-04-20 17:12:15 UTC
2019-04-20 17:12:16.085 UTC [7091] LOG: database system is ready to accept connections
Hashjoin 0x118e0c8: initial nbatch = 1, nbuckets = 1024
Hashjoin 0x118e0f8: initial nbatch = 1, nbuckets = 1024
Hashjoin 0x1194e78: initial nbatch = 1, nbuckets = 65536
Hashjoin 0x119b518: initial nbatch = 16, nbuckets = 65536
Hashjoin 0x1194e78: initial nbatch = 1, nbuckets = 65536
Hashjoin 0x119bb38: initial nbatch = 16, nbuckets = 65536
TopMemoryContext: 4347672 total in 9 blocks; 41784 free (19 chunks); 4305888 used
HandleParallelMessages: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
pgstat TabStatusArray lookup hash table: 8192 total in 1 blocks; 1456 free (0 chunks); 6736 used
TopTransactionContext: 8192 total in 1 blocks; 5416 free (2 chunks); 2776 used
Operator lookup cache: 24576 total in 2 blocks; 10760 free (3 chunks); 13816 used
TableSpace cache: 8192 total in 1 blocks; 2096 free (0 chunks); 6096 used
Type information cache: 24352 total in 2 blocks; 2624 free (0 chunks); 21728 used
RowDescriptionContext: 8192 total in 1 blocks; 6896 free (0 chunks); 1296 used
MessageContext: 32768 total in 3 blocks; 13488 free (1 chunks); 19280 used
Operator class cache: 8192 total in 1 blocks; 560 free (0 chunks); 7632 used
smgr relation table: 32768 total in 3 blocks; 16832 free (8 chunks); 15936 used
TransactionAbortContext: 32768 total in 1 blocks; 32512 free (0 chunks); 256 used
Portal hash: 8192 total in 1 blocks; 560 free (0 chunks); 7632 used
TopPortalContext: 8192 total in 1 blocks; 7664 free (0 chunks); 528 used
PortalHoldContext: 24632 total in 2 blocks; 7392 free (0 chunks); 17240 used
PortalContext: 1474560 total in 183 blocks; 6152 free (8 chunks); 1468408 used:
ExecutorState: 2234501600 total in 266274 blocks; 3696112 free (17274 chunks); 2230805488 used
HashTableContext: 32768 total in 3 blocks; 17272 free (8 chunks); 15496 used
HashBatchContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
HashTableContext: 8192 total in 1 blocks; 7320 free (0 chunks); 872 used
HashBatchContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
HashTableContext: 8192 total in 1 blocks; 7320 free (0 chunks); 872 used
HashBatchContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
HashTableContext: 8192 total in 1 blocks; 7752 free (0 chunks); 440 used
HashBatchContext: 90288 total in 4 blocks; 16072 free (6 chunks); 74216 used
HashTableContext: 8192 total in 1 blocks; 7624 free (0 chunks); 568 used
HashBatchContext: 90288 total in 4 blocks; 16072 free (6 chunks); 74216 used
TupleSort main: 286912 total in 8 blocks; 246792 free (39 chunks); 40120 used
TupleSort main: 286912 total in 8 blocks; 246792 free (39 chunks); 40120 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
HashTableContext: 8454256 total in 6 blocks; 64848 free (32 chunks); 8389408 used
HashBatchContext: 177003344 total in 5387 blocks; 7936 free (0 chunks); 176995408 used
TupleSort main: 452880 total in 8 blocks; 126248 free (27 chunks); 326632 used
Caller tuples: 1048576 total in 8 blocks; 21608 free (14 chunks); 1026968 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
Relcache by OID: 16384 total in 2 blocks; 3512 free (2 chunks); 12872 used
CacheMemoryContext: 1101328 total in 14 blocks; 236384 free (1 chunks); 864944 used
index info: 2048 total in 2 blocks; 680 free (1 chunks); 1368 used: pg_toast_2619_index
index info: 2048 total in 2 blocks; 968 free (1 chunks); 1080 used: entity_id_fkidx
index info: 2048 total in 2 blocks; 696 free (1 chunks); 1352 used: entity_id_idx
index info: 2048 total in 2 blocks; 968 free (1 chunks); 1080 used: act_id_fkidx
...
index info: 2048 total in 2 blocks; 680 free (1 chunks); 1368 used: pg_attribute_relid_attnum_index
index info: 2048 total in 2 blocks; 952 free (1 chunks); 1096 used: pg_class_oid_index
WAL record construction: 49768 total in 2 blocks; 6368 free (0 chunks); 43400 used
PrivateRefCount: 8192 total in 1 blocks; 2624 free (0 chunks); 5568 used
MdSmgr: 8192 total in 1 blocks; 6152 free (1 chunks); 2040 used
LOCALLOCK hash: 16384 total in 2 blocks; 4600 free (2 chunks); 11784 used
Timezones: 104120 total in 2 blocks; 2624 free (0 chunks); 101496 used
ErrorContext: 8192 total in 1 blocks; 7936 free (4 chunks); 256 used
Grand total: 2430295856 bytes in 272166 blocks; 5223104 free (17571 chunks); 2425072752 used
2019-04-20 17:28:56.887 UTC [7100] ERROR: out of memory
2019-04-20 17:28:56.887 UTC [7100] DETAIL: Failed on request of size 32800 in memory context "HashBatchContext".
2019-04-20 17:28:56.887 UTC [7100] STATEMENT: explain analyze SELECT * FROM reports.v_BusinessOperation;

There are amazingly few entries in the log.

(gdb) break ExecHashIncreaseNumBatches
Breakpoint 1 at 0x6b7bd6: file nodeHash.c, line 884.
(gdb) cont
Continuing.

Breakpoint 1, ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:884
884             int                     oldnbatch = hashtable->nbatch;
(gdb) cont
Continuing.

Breakpoint 1, ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:884
884             int                     oldnbatch = hashtable->nbatch;
(gdb) cont
Continuing.

Breakpoint 1, ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:884
884             int                     oldnbatch = hashtable->nbatch;
(gdb) cont 100
Will ignore next 99 crossings of breakpoint 1.  Continuing.

But I am surprised now to find that the behavior has changed or what?

First, weirdly enough, now I am not getting any of the HJDEBUG messages
any more. And yet my resident memory has already increased to 1.1 GB.

7100 postgres 20 0 2797036 1.1g 188064 R 17.9 14.9 14:46.00 postgres: postgres integrator [local] EXPLAIN
7664 postgres 20 0 1271788 16228 14408 D 17.6 0.2 0:01.96 postgres: parallel worker for PID 7100
7665 postgres 20 0 1271788 16224 14404 R 17.6 0.2 0:01.95 postgres: parallel worker for PID 7100

so why is it all different now? Are we chasing a red herring?

Finally I had another stop now at the HJDEBUG line

#0 ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:904
#1 0x00000000006b93b1 in ExecHashTableInsert (hashtable=0x12d0818, slot=0x12bcf98, hashvalue=234960700) at nodeHash.c:1655
#2 0x00000000006bd600 in ExecHashJoinNewBatch (hjstate=0x12a4340) at nodeHashjoin.c:1051
#3 0x00000000006bc999 in ExecHashJoinImpl (pstate=0x12a4340, parallel=false) at nodeHashjoin.c:539
#4 0x00000000006bca23 in ExecHashJoin (pstate=0x12a4340) at nodeHashjoin.c:565
#5 0x00000000006a191f in ExecProcNodeInstr (node=0x12a4340) at execProcnode.c:461
#6 0x00000000006ceaad in ExecProcNode (node=0x12a4340) at ../../../src/include/executor/executor.h:247
#7 0x00000000006cebe7 in ExecSort (pstate=0x12a4230) at nodeSort.c:107
#8 0x00000000006a191f in ExecProcNodeInstr (node=0x12a4230) at execProcnode.c:461
#9 0x00000000006a18f0 in ExecProcNodeFirst (node=0x12a4230) at execProcnode.c:445
#10 0x00000000006cf25c in ExecProcNode (node=0x12a4230) at ../../../src/include/executor/executor.h:247
#11 0x00000000006cf388 in ExecUnique (pstate=0x12a4040) at nodeUnique.c:73
#12 0x00000000006a191f in ExecProcNodeInstr (node=0x12a4040) at execProcnode.c:461
#13 0x00000000006a18f0 in ExecProcNodeFirst (node=0x12a4040) at execProcnode.c:445
#14 0x000000000069728b in ExecProcNode (node=0x12a4040) at ../../../src/include/executor/executor.h:247
#15 0x0000000000699790 in ExecutePlan (estate=0x12a3da0, planstate=0x12a4040, use_parallel_mode=true, operation=CMD_SELECT,
sendTuples=true, numberTuples=0, direction=ForwardScanDirection, dest=0xe811c0 <donothingDR>, execute_once=true)
at execMain.c:1723
#16 0x0000000000697757 in standard_ExecutorRun (queryDesc=0x1404168, direction=ForwardScanDirection, count=0, execute_once=true)
at execMain.c:364
#17 0x00000000006975f4 in ExecutorRun (queryDesc=0x1404168, direction=ForwardScanDirection, count=0, execute_once=true)
at execMain.c:307
#18 0x000000000060d227 in ExplainOnePlan (plannedstmt=0x1402588, into=0x0, es=0x10b03a8,
queryString=0x10866c0 "explain analyze SELECT * FROM reports.v_BusinessOperation;", params=0x0, queryEnv=0x0,
planduration=0x7fff56a0df00) at explain.c:535

So now I am back with checking who calls AllocSetAlloc?

(gdb) break AllocSetAlloc if (int)strcmp(context->name, "ExecutorState") == 0
Breakpoint 4 at 0x9eab11: file aset.c, line 719.
(gdb) cont
Continuing.

Breakpoint 4, AllocSetAlloc (context=0x12a3c90, size=8272) at aset.c:719
719 AllocSet set = (AllocSet) context;
(gdb) bt 5
#0 AllocSetAlloc (context=0x12a3c90, size=8272) at aset.c:719
#1 0x00000000009f2e47 in palloc (size=8272) at mcxt.c:938
#2 0x000000000082ae84 in makeBufFileCommon (nfiles=1) at buffile.c:116
#3 0x000000000082af14 in makeBufFile (firstfile=34029) at buffile.c:138
#4 0x000000000082b09f in BufFileCreateTemp (interXact=false) at buffile.c:201
(More stack frames follow...)
(gdb) bt 7
#0 AllocSetAlloc (context=0x12a3c90, size=8272) at aset.c:719
#1 0x00000000009f2e47 in palloc (size=8272) at mcxt.c:938
#2 0x000000000082ae84 in makeBufFileCommon (nfiles=1) at buffile.c:116
#3 0x000000000082af14 in makeBufFile (firstfile=34029) at buffile.c:138
#4 0x000000000082b09f in BufFileCreateTemp (interXact=false) at buffile.c:201
#5 0x00000000006bda31 in ExecHashJoinSaveTuple (tuple=0x86069b8, hashvalue=234960700, fileptr=0x8616a30) at nodeHashjoin.c:1220
#6 0x00000000006b80c0 in ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:1004
(More stack frames follow...)
(gdb) cont
Continuing.

Breakpoint 4, AllocSetAlloc (context=0x12a3c90, size=8) at aset.c:719
719 AllocSet set = (AllocSet) context;
(gdb) bt 7
#0 AllocSetAlloc (context=0x12a3c90, size=8) at aset.c:719
#1 0x00000000009f2f5d in palloc0 (size=8) at mcxt.c:969
#2 0x000000000082aea2 in makeBufFileCommon (nfiles=1) at buffile.c:119
#3 0x000000000082af14 in makeBufFile (firstfile=34029) at buffile.c:138
#4 0x000000000082b09f in BufFileCreateTemp (interXact=false) at buffile.c:201
#5 0x00000000006bda31 in ExecHashJoinSaveTuple (tuple=0x86069b8, hashvalue=234960700, fileptr=0x8616a30) at nodeHashjoin.c:1220
#6 0x00000000006b80c0 in ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:1004
(More stack frames follow...)
(gdb) cont
Continuing.

Breakpoint 4, AllocSetAlloc (context=0x12a3c90, size=4) at aset.c:719
719 AllocSet set = (AllocSet) context;
(gdb) bt 7
#0 AllocSetAlloc (context=0x12a3c90, size=4) at aset.c:719
#1 0x00000000009f2e47 in palloc (size=4) at mcxt.c:938
#2 0x000000000082af22 in makeBufFile (firstfile=34029) at buffile.c:140
#3 0x000000000082b09f in BufFileCreateTemp (interXact=false) at buffile.c:201
#4 0x00000000006bda31 in ExecHashJoinSaveTuple (tuple=0x86069b8, hashvalue=234960700, fileptr=0x8616a30) at nodeHashjoin.c:1220
#5 0x00000000006b80c0 in ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:1004
#6 0x00000000006b93b1 in ExecHashTableInsert (hashtable=0x12d0818, slot=0x12bcf98, hashvalue=234960700) at nodeHash.c:1655
(More stack frames follow...)
(gdb) cont
Continuing.

Breakpoint 4, AllocSetAlloc (context=0x12a3c90, size=375) at aset.c:719
719 AllocSet set = (AllocSet) context;
(gdb) bt 7
#0 AllocSetAlloc (context=0x12a3c90, size=375) at aset.c:719
#1 0x00000000009f2e47 in palloc (size=375) at mcxt.c:938
#2 0x00000000006bdbec in ExecHashJoinGetSavedTuple (hjstate=0x12a4340, file=0x13ca418, hashvalue=0x7fff56a0da54, tupleSlot=0x12bcf98)
at nodeHashjoin.c:1277
#3 0x00000000006bd61f in ExecHashJoinNewBatch (hjstate=0x12a4340) at nodeHashjoin.c:1042
#4 0x00000000006bc999 in ExecHashJoinImpl (pstate=0x12a4340, parallel=false) at nodeHashjoin.c:539
#5 0x00000000006bca23 in ExecHashJoin (pstate=0x12a4340) at nodeHashjoin.c:565
#6 0x00000000006a191f in ExecProcNodeInstr (node=0x12a4340) at execProcnode.c:461
(More stack frames follow...)

Now I am adding a breakpoint in AllocSetFree and I see that this gets
called right after AllocSetAlloc with the same context, and presumably
the pointer previously allocated.

(gdb) finish
Run till exit from #0 AllocSetAlloc (context=0x12a3c90, size=375) at aset.c:719
0x00000000009f2e47 in palloc (size=375) at mcxt.c:938
938 ret = context->methods->alloc(context, size);
Value returned is $1 = (void *) 0x11bd858
(gdb) cont
Continuing.

Breakpoint 5, AllocSetFree (context=0x12a3c90, pointer=0x11bf748) at aset.c:992
992 AllocSet set = (AllocSet) context;
(gdb) cont
Continuing.

Breakpoint 4, AllocSetAlloc (context=0x12a3c90, size=375) at aset.c:719
719 AllocSet set = (AllocSet) context;
(gdb) finish
Run till exit from #0 AllocSetAlloc (context=0x12a3c90, size=375) at aset.c:719
0x00000000009f2e47 in palloc (size=375) at mcxt.c:938
938 ret = context->methods->alloc(context, size);
Value returned is $2 = (void *) 0x11bf748
(gdb) cont
Continuing.

Breakpoint 5, AllocSetFree (context=0x12a3c90, pointer=0x11bd858) at aset.c:992
992 AllocSet set = (AllocSet) context;

See, now that pointer allocated before is being freed. I can already see
how I would write a memory leak detection tool. I would keep a cache of
a fixed size, say one page, of recently allocated pointers, and when
free is called, it would remove the pointer from the cache. Then I would
only log the allocated pointer once it has to be evicted from the cache
because another one needs to be added, so I don't fill my log file with
a bunch of memory allocations that get freed relatively quickly.

This is very confused. I just stepped over

Breakpoint 2, ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:904
904 printf("Hashjoin %p: increasing nbatch to %d because space = %zu\n",
(gdb) next
908 oldcxt = MemoryContextSwitchTo(hashtable->hashCxt);
(gdb) call MemoryContextStats(TopPortalContext)

and checked my log file and there was nothing before the call
MemoryContextStats(TopPortalContext) so I don't understand where this
printf stuff is ending up. Clearly *some* of it is in the log, but none
of that "increasing nbatch" stuff is. I think there is something wrong
with that HJDEBUG stuff. Oops, my calling that MemoryContextStats really
seems to help force this buffer to be flushed, because now I got more:

Hashjoin 0x118e4c8: initial nbatch = 1, nbuckets = 1024
Hashjoin 0x118e4f8: initial nbatch = 1, nbuckets = 1024
Hashjoin 0x1195278: initial nbatch = 1, nbuckets = 65536
Hashjoin 0x119b918: initial nbatch = 16, nbuckets = 65536
Hashjoin 0x1195278: initial nbatch = 1, nbuckets = 65536
Hashjoin 0x119b918: initial nbatch = 16, nbuckets = 65536
...
Hashjoin 0x13a8e68: initial nbatch = 16, nbuckets = 8192
Hashjoin 0x13a8e68: increasing nbatch to 32 because space = 4128933
Hashjoin 0x13a8e68: freed 148 of 10584 tuples, space now 4071106
Hashjoin 0x13a8e68: increasing nbatch to 64 because space = 4128826
Hashjoin 0x13a8e68: freed 544 of 10584 tuples, space now 3916296
Hashjoin 0x13a8e68: increasing nbatch to 128 because space = 4128846
Hashjoin 0x13a8e68: freed 10419 of 10585 tuples, space now 65570
Hashjoin 0x13a8e68: increasing nbatch to 256 because space = 4128829
Hashjoin 0x13a8e68: freed 10308 of 10734 tuples, space now 161815
Hashjoin 0x13a8e68: increasing nbatch to 512 because space = 4128908
Hashjoin 0x13a8e68: freed 398 of 10379 tuples, space now 3977787
Hashjoin 0x13a8e68: increasing nbatch to 1024 because space = 4129008
Hashjoin 0x13a8e68: freed 296 of 10360 tuples, space now 4013423
Hashjoin 0x13a8e68: increasing nbatch to 2048 because space = 4129133
Hashjoin 0x13a8e68: freed 154 of 10354 tuples, space now 4068786
Hashjoin 0x13a8e68: increasing nbatch to 4096 because space = 4129035
Hashjoin 0x13a8e68: freed 10167 of 10351 tuples, space now 72849
Hashjoin 0x242c9b0: initial nbatch = 1, nbuckets = 1024
Hashjoin 0x2443ee0: initial nbatch = 1, nbuckets = 1024
Hashjoin 0x2443aa0: initial nbatch = 1, nbuckets = 1024
Hashjoin 0x2443440: initial nbatch = 1, nbuckets = 65536
Hashjoin 0x2443330: initial nbatch = 16, nbuckets = 65536
Hashjoin 0x13a8e68: increasing nbatch to 8192 because space = 4128997
Hashjoin 0x12d0818: freed 10555 of 10560 tuples, space now 1983
Hashjoin 0x12d0818: increasing nbatch to 16384 because space = 4128957
Hashjoin 0x12d0818: freed 10697 of 10764 tuples, space now 25956TopPortalContext: 8192 total in 1 blocks; 7664 free (0 chunks); 528 used
...

And you see here clearly that there is a problem with this printf stdout
buffer.

Now finally I am at this stage of the breakpoint firing rapidly

(gdb) cont 100
Will ignore next 99 crossings of breakpoint 1. Continuing.

Breakpoint 1, ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:884
884 int oldnbatch = hashtable->nbatch;
(gdb) bt 7
#0 ExecHashIncreaseNumBatches (hashtable=0x12d0818) at nodeHash.c:884
#1 0x00000000006b93b1 in ExecHashTableInsert (hashtable=0x12d0818, slot=0x12bcf98, hashvalue=2161368) at nodeHash.c:1655
#2 0x00000000006bd600 in ExecHashJoinNewBatch (hjstate=0x12a4340) at nodeHashjoin.c:1051
#3 0x00000000006bc999 in ExecHashJoinImpl (pstate=0x12a4340, parallel=false) at nodeHashjoin.c:539
#4 0x00000000006bca23 in ExecHashJoin (pstate=0x12a4340) at nodeHashjoin.c:565
#5 0x00000000006a191f in ExecProcNodeInstr (node=0x12a4340) at execProcnode.c:461
#6 0x00000000006ceaad in ExecProcNode (node=0x12a4340) at ../../../src/include/executor/executor.h:247
(More stack frames follow...)

so it's not a red herring after all. But nothing new in the logfile from
that HJDEBUG. Trying to flush stdout with this call
MemoryContextStats(TopPortalContext)

...
ExecutorState: 782712360 total in 92954 blocks; 3626888 free (3126 chunks); 779085472 used

and nothing heard from HJDEBUG. So you really can't rely on that HJDEBUG
stuff. It's not working.

I will summarize that the memory problem with the rapid firing on
ExecHashIncreaseNumBatches is still occurring, confirmed as I reported
earlier, it wasn't some red herring but that the HJDEBUG stuff doesn't
work. Also, that there might be benefit in creating a little resident
memory leak detector that keeps track of a single page of AllocSetAlloc
pointers cancelled out by matching AllocSetFree and reporting the
overflow with a quick little stack trace.

On 4/20/2019 6:53, Justin Pryzby wrote:
>> The only problem is that I can't test that this actually would trigger the
>> memory problem, because I can't force the plan to use the right join, it
>> always reverts to the left join hashing the tmp_q:
> I think the table on the "OUTER" side is the one which needs to be iterated
> over (not hashed), in order to return each of its rows even if there are no
> join partners in the other table. In your original query, the small table was
> being hashed and the large table iterated; maybe that's whats important.

May be so. Trying to wrap my head around the RIGHT vs. LEFT outer join
and why there even is a difference though.

-> Hash Right Join (cost=4255031.53..5530808.71 rows=34619 width=1197)
Hash Cond: (((q.documentinternalid)::text = (documentinformationsubject.documentinternalid)::text) AND ((r.targetinternalid)::text = (documentinformationsubject.actinternalid)::text))
-> Hash Right Join (cost=1341541.37..2612134.36 rows=13 width=341)
Hash Cond: (((documentinformationsubject_2.documentinternalid)::text = (q.documentinternalid)::text) AND ((documentinformationsubject_2.actinternalid)::text = (q.actinternalid)::text))
... from the TINY table tmp_q, the estimate of 13 rows ain't bad
-> Hash (cost=2908913.87..2908913.87 rows=34619 width=930)
-> Gather Merge (cost=2892141.40..2908913.87 rows=34619 width=930)
.... from the HUGE tmp_r table, with 100 million rows (estimate of 34619 is grossly wrong, but how could it know? ...

Now in a right join, we include all rows from the right table, and only
those from the left table that match the join key. I wonder why not
transform all of those to left joins then?

Why are we not hashing only the "optional" side?

The plan here seems to tell me without a doubt that it is hashing the
big table, 100 million rows get hashed into the hash join and then we
iterate over the tiny table and then ... now my mind boggles and I just
don't know why there are right joins at all.

But I see the plan is running the Hash index of 100 million rows.

>> which is of course much better, but when tmp_q and tmp_r are the results of
>> complex stuff that the planner can't estimate, then it gets it wrong, and
>> then the issue gets triggered because we are hashing on the big tmp_r, not
>> tmp_q.
> I was able to get something maybe promising ? "Batches: 65536 (originally 1)"
>
> I didn't get "Out of memory" error yet, but did crash the server with this one:
> postgres=# explain analyze WITH v AS( SELECT * FROM generate_series(1,99999999)i WHERE i%10<10 AND i%11<11 AND i%12<12 AND i%13<13 AND i%14<14 AND i%15<15 AND i%16<16 AND i%17<17 AND i%18<18 AND i%19<19 AND i%20<20 AND i%21<21 ) SELECT * FROM generate_series(1,99)k JOIN v ON k=i ;
>
> Note, on pg12dev this needs to be "with v AS MATERIALIZED".
>
> postgres=# SET work_mem='128kB';SET client_min_messages =log;SET log_statement_stats=on;explain(analyze,timing off) WITH v AS( SELECT * FROM generate_series(1,999999)i WHERE i%10<10 AND i%11<11 AND i%12<12 AND i%13<13 AND i%14<14 AND i%15<15 AND i%16<16 AND i%17<17 AND i%18<18 AND i%19<19 AND i%20<20 AND i%21<21 ) SELECT * FROM generate_series(1,99)k JOIN v ON k=i ;
> Hash Join (cost=70.04..83.84 rows=5 width=8) (actual rows=99 loops=1)
> Hash Cond: (k.k = v.i)
> CTE v
> -> Function Scan on generate_series i (cost=0.00..70.00 rows=1 width=4) (actual rows=999999 loops=1)
> Filter: (((i % 10) < 10) AND ((i % 11) < 11) AND ((i % 12) < 12) AND ((i % 13) < 13) AND ((i % 14) < 14) AND ((i % 15) < 15) AND ((i % 16) < 16) AND ((i % 17) < 17) AND ((i % 18) < 18) AND ((i % 19) < 19) AND ((i % 20) < 20) AND ((i % 21) < 21))
> -> Function Scan on generate_series k (cost=0.00..10.00 rows=1000 width=4) (actual rows=99 loops=1)
> -> Hash (cost=0.02..0.02 rows=1 width=4) (actual rows=999999 loops=1)
> Buckets: 4096 (originally 1024) Batches: 512 (originally 1) Memory Usage: 101kB
> -> CTE Scan on v (cost=0.00..0.02 rows=1 width=4) (actual rows=999999 loops=1)

Yes I thought that with CTEs and functions one might be able to generate
a test case, but still not seing how you can trick the planner into this
peculiar jointype JOIN_RIGHT and whether that is requisite for
triggering the problem.

Finally, I have tried to make a pstate pretty printer in explain.c:

void
DumpPlanState(PlanState *pstate) {
ExplainState *es = NewExplainState();
ExplainNode(pstate, NIL, NULL, NULL, es);
puts(es->str->data);
pfree(es->str->data);
}

but that didn't work, because unfortunately that ExplainNode function is
destructive. It would be so nice to refactor this explain code such that
there would be a completely conservative function that simply dumps the
present pstate with all the information about its estimate and actual
situation, how many iterations it has already accomplished, how many it
estimates to still have to do, whether its original estimate panned out
or not, etc. This would be so tremendously useful for runtime debugging
of queries. I think the utility of this can hardly be overstated. I mean
even for end-user applications of some data warehouse, where you could
probe a long running query every 5 seconds as to where the execution is.
Man, I could not think of any more low hanging fruit useful feature. I
am sure that if PostgreSQL was originally written in Java, this feature
would naturally exist already.

regards and Happy Easter,
-Gunther