Re: Out of Memory errors are frustrating as heck!

On 4/21/2019 23:09, Tomas Vondra wrote:
> What I think might work better is the attached v2 of the patch, with a
> single top-level condition, comparing the combined memory usage
> (spaceUsed + BufFile) against spaceAllowed. But it also tweaks
> spaceAllowed once the size needed for BufFile gets over work_mem/3.

Thanks for this, and I am trying this now.

So far it is promising.

I see the memory footprint contained under 1 GB. I see it go up, but
also down again. CPU, IO, all being live.

foo=# set enable_nestloop to off; SET foo=# explain analyze select *
from reports.v_BusinessOperation; WARNING: ExecHashIncreaseNumBatches:
nbatch=32 spaceAllowed=4194304 WARNING: ExecHashIncreaseNumBatches:
nbatch=64 spaceAllowed=4194304 WARNING: ExecHashIncreaseNumBatches:
nbatch=128 spaceAllowed=4194304 WARNING: ExecHashIncreaseNumBatches:
nbatch=256 spaceAllowed=6291456 WARNING: ExecHashIncreaseNumBatches:
nbatch=512 spaceAllowed=12582912 WARNING: ExecHashIncreaseNumBatches:
nbatch=1024 spaceAllowed=25165824 WARNING: ExecHashIncreaseNumBatches:
nbatch=2048 spaceAllowed=50331648 WARNING: ExecHashIncreaseNumBatches:
nbatch=4096 spaceAllowed=100663296 WARNING: ExecHashIncreaseNumBatches:
nbatch=8192 spaceAllowed=201326592 WARNING: ExecHashIncreaseNumBatches:
nbatch=16384 spaceAllowed=402653184 WARNING: ExecHashIncreaseNumBatches:
nbatch=32768 spaceAllowed=805306368 WARNING: ExecHashIncreaseNumBatches:
nbatch=65536 spaceAllowed=1610612736

Aaaaaand, it's a winner!

Unique (cost=5551524.36..5554207.33 rows=34619 width=1197) (actual
time=6150303.060..6895451.210 rows=435274 loops=1) -> Sort
(cost=5551524.36..5551610.91 rows=34619 width=1197) (actual
time=6150303.058..6801372.192 rows=113478386 loops=1) Sort Key:
documentinformationsubject.documentinternalid,
documentinformationsubject.is_current,
documentinformationsubject.documentid,
documentinformationsubject.documenttypecode,
documentinformationsubject.subjectroleinternalid,
documentinformationsubject.subjectentityinternalid,
documentinformationsubject.subjectentityid,
documentinformationsubject.subjectentityidroot,
documentinformationsubject.subjectentityname,
documentinformationsubject.subjectentitytel,
documentinformationsubject.subjectentityemail,
documentinformationsubject.otherentityinternalid,
documentinformationsubject.confidentialitycode,
documentinformationsubject.actinternalid,
documentinformationsubject.code_code,
documentinformationsubject.code_displayname, q.code_code,
q.code_displayname, an.extension, an.root,
documentinformationsubject_2.subjectentitycode,
documentinformationsubject_2.subjectentitycodesystem,
documentinformationsubject_2.effectivetime_low,
documentinformationsubject_2.effectivetime_high,
documentinformationsubject_2.statuscode,
documentinformationsubject_2.code_code, agencyid.extension,
agencyname.trivialname, documentinformationsubject_1.subjectentitycode,
documentinformationsubject_1.subjectentityinternalid Sort Method:
external merge Disk: 40726720kB -> Hash Right Join
(cost=4255031.53..5530808.71 rows=34619 width=1197) (actual
time=325240.679..1044194.775 rows=113478386 loops=1) 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) (actual
time=81093.327..81093.446 rows=236 loops=1) Hash Cond:
(((documentinformationsubject_2.documentinternalid)::text =
(q.documentinternalid)::text) AND
((documentinformationsubject_2.actinternalid)::text =
(q.actinternalid)::text)) -> Gather (cost=31291.54..1301884.52 rows=1
width=219) (actual time=41920.563..41929.780 rows=0 loops=1) Workers
Planned: 2 Workers Launched: 2 -> Parallel Hash Left Join
(cost=30291.54..1300884.42 rows=1 width=219) (actual
time=41915.960..41915.960 rows=0 loops=3) Hash Cond:
((documentinformationsubject_2.otherentityinternalid)::text =
(agencyid.entityinternalid)::text) -> Parallel Hash Left Join
(cost=28606.13..1299199.00 rows=1 width=204) (actual
time=41862.767..41862.769 rows=0 loops=3) Hash Cond:
((documentinformationsubject_2.otherentityinternalid)::text =
(agencyname.entityinternalid)::text) -> Parallel Seq Scan on
documentinformationsubject documentinformationsubject_2
(cost=0.00..1268800.85 rows=1 width=177) (actual
time=40805.337..40805.337 rows=0 loops=3) Filter:
((participationtypecode)::text = 'AUT'::text) Rows Removed by Filter:
2815562 -> Parallel Hash (cost=24733.28..24733.28 rows=166628 width=64)
(actual time=981.000..981.001 rows=133303 loops=3) Buckets: 65536
Batches: 16 Memory Usage: 3136kB -> Parallel Seq Scan on bestname
agencyname (cost=0.00..24733.28 rows=166628 width=64) (actual
time=0.506..916.816 rows=133303 loops=3) -> Parallel Hash
(cost=1434.07..1434.07 rows=20107 width=89) (actual time=52.350..52.350
rows=11393 loops=3) Buckets: 65536 Batches: 1 Memory Usage: 4680kB ->
Parallel Seq Scan on entity_id agencyid (cost=0.00..1434.07 rows=20107
width=89) (actual time=0.376..46.875 rows=11393 loops=3) -> Hash
(cost=1310249.63..1310249.63 rows=13 width=233) (actual
time=39172.682..39172.682 rows=236 loops=1) Buckets: 1024 Batches: 1
Memory Usage: 70kB -> Hash Right Join (cost=829388.20..1310249.63
rows=13 width=233) (actual time=35084.850..39172.545 rows=236 loops=1)
Hash Cond: ((an.actinternalid)::text = (q.actinternalid)::text) -> Seq
Scan on act_id an (cost=0.00..425941.04 rows=14645404 width=134) (actual
time=0.908..7583.123 rows=14676871 loops=1) -> Hash
(cost=829388.19..829388.19 rows=1 width=136) (actual
time=29347.614..29347.614 rows=236 loops=1) Buckets: 1024 Batches: 1
Memory Usage: 63kB -> Gather (cost=381928.46..829388.19 rows=1
width=136) (actual time=23902.428..29347.481 rows=236 loops=1) Workers
Planned: 2 Workers Launched: 2 -> Parallel Hash Join
(cost=380928.46..828388.09 rows=1 width=136) (actual
time=23915.790..29336.452 rows=79 loops=3) Hash Cond:
((q.actinternalid)::text = (r.sourceinternalid)::text) -> Parallel Seq
Scan on documentinformation q (cost=0.00..447271.93 rows=50050 width=99)
(actual time=10055.238..15484.478 rows=87921 loops=3) Filter:
(((classcode)::text = 'CNTRCT'::text) AND ((moodcode)::text =
'EVN'::text) AND ((code_codesystem)::text =
'2.16.840.1.113883.3.26.1.1'::text)) Rows Removed by Filter: 1540625 ->
Parallel Hash (cost=380928.44..380928.44 rows=1 width=74) (actual
time=13825.726..13825.726 rows=79 loops=3) Buckets: 1024 Batches: 1
Memory Usage: 112kB -> Parallel Seq Scan on actrelationship r
(cost=0.00..380928.44 rows=1 width=74) (actual time=5289.948..13825.576
rows=79 loops=3) Filter: ((typecode)::text = 'SUBJ'::text) Rows Removed
by Filter: 3433326 -> Hash (cost=2908913.87..2908913.87 rows=34619
width=930) (actual time=244145.322..244145.322 rows=113478127 loops=1)
Buckets: 8192 (originally 8192) Batches: 65536 (originally 16) Memory
Usage: 1204250kB -> Gather Merge (cost=2892141.40..2908913.87 rows=34619
width=930) (actual time=75215.333..145622.427 rows=113478127 loops=1)
Workers Planned: 2 Workers Launched: 2 -> Merge Left Join
(cost=2891141.37..2903917.96 rows=14425 width=930) (actual
time=75132.988..99411.448 rows=37826042 loops=3) Merge Cond:
(((documentinformationsubject.documentinternalid)::text =
(documentinformationsubject_1.documentinternalid)::text) AND
((documentinformationsubject.documentid)::text =
(documentinformationsubject_1.documentid)::text) AND
((documentinformationsubject.actinternalid)::text =
(documentinformationsubject_1.actinternalid)::text)) -> Sort
(cost=1301590.26..1301626.32 rows=14425 width=882) (actual
time=39801.337..40975.780 rows=231207 loops=3) Sort Key:
documentinformationsubject.documentinternalid,
documentinformationsubject.documentid,
documentinformationsubject.actinternalidct_1.documentid,
documentinformationsubject_1.actinternalid Sort Method: external merge
Disk: 169768kB Worker 0: Sort Method: external merge Disk: 169768kB
Worker 1: Sort Method: external merge Disk: 169768kB -> Seq Scan on
documentinformationsubject documentinformationsubject_1
(cost=0.00..1329868.64 rows=1010585 width=159) (actual
time=23401.537..31758.042 rows=1031106 loops=3) Filter:
((participationtypecode)::text = 'PRD'::text) Rows Removed by Filter:
7415579 Planning Time: 40.559 ms Execution Time: 6896581.566 ms (70 rows)

For the first time this query has succeeded now. Memory was bounded. The
time of nearly hours is crazy, but things sometimes take that long. The
important thing was not to get an out of memory error.

Thank you. Anything else you want to try, I can do it.

regards,
-Gunther