Out of Memory errors are frustrating as heck!

For weeks now, I am banging my head at an "out of memory" situation.
There is only one query I am running on an 8 GB system, whatever I try,
I get knocked out on this out of memory. It is extremely impenetrable to
understand and fix this error. I guess I could add a swap file, and then
I would have to take the penalty of swapping. But how can I actually
address an out of memory condition if the system doesn't tell me where
it is happening?

You might want to see the query, but it is a huge plan, and I can't
really break this down. It shouldn't matter though. But just so you can
get a glimpse here is the plan:

Insert on businessoperation (cost=5358849.28..5361878.44 rows=34619 width=1197)
-> Unique (cost=5358849.28..5361532.25 rows=34619 width=1197)
-> Sort (cost=5358849.28..5358935.83 rows=34619 width=1197)
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
-> Nested Loop Left Join (cost=2998335.54..5338133.63 rows=34619 width=1197)
Join Filter: (((documentinformationsubject.documentinternalid)::text = (q.documentinternalid)::text) AND ((documentinformationsubject.actinternalid)::text = (r.targetinternalid)::text))
-> Merge Left Join (cost=2998334.98..3011313.54 rows=34619 width=930)
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=1408783.87..1408870.41 rows=34619 width=882)
Sort Key: documentinformationsubject.documentinternalid, documentinformationsubject.documentid, documentinformationsubject.actinternalid
-> Seq Scan on documentinformationsubject (cost=0.00..1392681.22 rows=34619 width=882)
Filter: (((participationtypecode)::text = ANY ('{PPRF,PRF}'::text[])) AND ((classcode)::text = 'ACT'::text) AND ((moodcode)::text = 'DEF'::text) AND ((code_codesystem)::text = '2.16.840.1.113883.3.26.1.1'::text))
-> Materialize (cost=1589551.12..1594604.04 rows=1010585 width=159)
-> Sort (cost=1589551.12..1592077.58 rows=1010585 width=159)
Sort Key: documentinformationsubject_1.documentinternalid, documentinformationsubject_1.documentid, documentinformationsubject_1.actinternalid
-> Seq Scan on documentinformationsubject documentinformationsubject_1 (cost=0.00..1329868.64 rows=1010585 width=159)
Filter: ((participationtypecode)::text = 'PRD'::text)
-> Materialize (cost=0.56..2318944.31 rows=13 width=341)
-> Nested Loop Left Join (cost=0.56..2318944.24 rows=13 width=341)
-> Nested Loop Left Join (cost=0.00..2318893.27 rows=1 width=281)
Join Filter: ((agencyname.entityinternalid)::text = (documentinformationsubject_2.otherentityinternalid)::text)
-> Nested Loop Left Join (cost=0.00..2286828.33 rows=1 width=291)
Join Filter: ((agencyid.entityinternalid)::text = (documentinformationsubject_2.otherentityinternalid)::text)
-> Nested Loop Left Join (cost=0.00..2284826.24 rows=1 width=239)
Join Filter: (((q.documentinternalid)::text = (documentinformationsubject_2.documentinternalid)::text) AND ((q.actinternalid)::text = (documentinformationsubject_2.actinternalid)::text))
-> Nested Loop (cost=0.00..954957.59 rows=1 width=136)
Join Filter: ((q.actinternalid)::text = (r.sourceinternalid)::text)
-> Seq Scan on actrelationship r (cost=0.00..456015.26 rows=1 width=74)
Filter: ((typecode)::text = 'SUBJ'::text)
-> Seq Scan on documentinformation q (cost=0.00..497440.84 rows=120119 width=99)
Filter: (((classcode)::text = 'CNTRCT'::text) AND ((moodcode)::text = 'EVN'::text) AND ((code_codesystem)::text = '2.16.840.1.113883.3.26.1.1'::text))
-> Seq Scan on documentinformationsubject documentinformationsubject_2 (cost=0.00..1329868.64 rows=1 width=177)
Filter: ((participationtypecode)::text = 'AUT'::text)
-> Seq Scan on entity_id agencyid (cost=0.00..1574.82 rows=34182 width=89)
-> Seq Scan on bestname agencyname (cost=0.00..27066.08 rows=399908 width=64)
-> Index Scan using act_id_fkidx on act_id an (cost=0.56..50.85 rows=13 width=134)
Index Cond: ((q.actinternalid)::text = (actinternalid)::text)

I have monitored the activity with vmstat and iostat, and it looks like
the memory grabbing happens rapidly after a Sort Merge step. I see in
the iostat a heavy read and write activity, which I attribute to a
sort-merge step, then that is followed by a sudden spike in write
activity, and then the out of memory crash.

procs -----------------------memory---------------------- ---swap-- -----io---- -system-- --------cpu-------- -----timestamp-----
r b swpd free buff cache si so bi bo in cs us sy id wa st UTC
0 2 0 119344 0 7616672 0 0 11681 3107 9 0 6 1 72 21 0 2019-04-14 16:19:52
0 2 0 128884 0 7607288 0 0 2712 55386 500 509 3 2 15 80 0 2019-04-14 16:19:54
0 2 0 116984 0 7619916 0 0 880 59241 548 525 2 2 9 87 0 2019-04-14 16:19:56
0 2 0 131492 0 7604816 0 0 128 56512 518 401 1 1 12 86 0 2019-04-14 16:19:58
...
0 2 0 134508 0 7601480 0 0 0 58562 428 353 0 1 4 95 0 2019-04-14 16:21:46
0 2 0 125360 0 7611320 0 0 0 59392 481 369 0 1 11 89 0 2019-04-14 16:21:48
0 2 0 122896 0 7612872 0 0 0 58564 431 342 0 1 17 82 0 2019-04-14 16:21:50
1 1 0 121456 0 7614248 0 0 54 57347 487 399 0 1 13 85 0 2019-04-14 16:21:52
0 2 0 122820 0 7613324 0 0 12 59964 460 346 0 1 20 79 0 2019-04-14 16:21:54
0 2 0 120344 0 7616528 0 0 1844 55691 645 676 5 3 6 85 0 2019-04-14 16:21:56
0 2 0 124900 0 7611404 0 0 936 58261 795 1215 2 3 13 83 0 2019-04-14 16:21:58
0 2 0 124572 0 7612192 0 0 1096 55340 518 487 1 2 0 97 0 2019-04-14 16:22:00
0 2 0 123040 0 7612740 0 0 888 57574 573 620 1 2 5 92 0 2019-04-14 16:22:02
0 2 0 125112 0 7610592 0 0 124 59164 498 480 1 1 13 85 0 2019-04-14 16:22:04
1 1 0 129440 0 7607592 0 0 568 60196 563 612 2 2 8 88 0 2019-04-14 16:22:06
0 2 0 124020 0 7612364 0 0 0 58260 629 725 0 1 8 91 0 2019-04-14 16:22:08
2 1 0 124480 0 7611848 0 0 0 58852 447 331 0 1 1 98 0 2019-04-14 16:22:10
0 3 0 137636 0 7598484 0 0 11908 44995 619 714 1 1 11 87 0 2019-04-14 16:22:12
0 2 0 123128 0 7613392 0 0 29888 28901 532 972 1 1 29 68 0 2019-04-14 16:22:14
0 2 0 126260 0 7609984 0 0 39872 18836 706 1435 1 2 28 70 0 2019-04-14 16:22:16
0 2 0 130748 0 7605536 0 0 36096 22488 658 1272 2 1 8 89 0 2019-04-14 16:22:18
...
 0 2 0 127216 0 7609192 0 0 29192 29696 472 949 1 1 23 75 0 2019-04-14 16:22:40
0 2 0 147428 0 7588556 0 0 29120 29696 523 974 1 1 19 79 0 2019-04-14 16:22:42
0 1 0 120644 0 7615388 0 0 32320 25276 566 998 1 2 49 47 0 2019-04-14 16:22:44
0 1 0 128456 0 7607904 0 0 58624 0 621 1103 3 2 49 46 0 2019-04-14 16:22:46
0 1 0 127836 0 7608260 0 0 58624 0 631 1119 3 2 50 46 0 2019-04-14 16:22:48
0 1 0 126712 0 7609616 0 0 58624 0 616 1110 2 2 50 47 0 2019-04-14 16:22:50
...
0 1 0 157408 0 7578060 0 0 58628 0 736 1206 3 3 50 44 0 2019-04-14 16:27:22
0 1 0 142420 0 7593400 0 0 58688 0 623 1099 1 4 50 45 0 2019-04-14 16:27:24
0 1 0 247016 0 7488184 0 0 58568 0 649 1113 1 4 50 45 0 2019-04-14 16:27:26
0 1 0 123232 0 7612088 0 0 58412 215 675 1141 2 3 50 46 0 2019-04-14 16:27:28
0 2 0 144920 0 7586576 0 0 48376 11046 788 1455 1 5 34 60 0 2019-04-14 16:27:30
1 1 0 125636 0 7595704 0 0 36736 21381 702 1386 1 4 21 74 0 2019-04-14 16:27:32
0 3 0 156700 0 7559328 0 0 35556 23364 709 1367 1 3 22 74 0 2019-04-14 16:27:34
0 2 0 315580 0 7382748 0 0 33608 24731 787 1407 1 5 18 76 0 2019-04-14 16:27:36
...
0 2 0 684412 0 6152040 0 0 29832 28356 528 994 1 2 32 66 0 2019-04-14 16:38:04
0 2 0 563512 0 6272264 0 0 29696 29506 546 987 1 2 32 65 0 2019-04-14 16:38:06
0 2 0 595488 0 6241068 0 0 27292 30858 549 971 1 2 26 71 0 2019-04-14 16:38:08
0 2 0 550120 0 6285352 0 0 28844 29696 567 995 1 2 29 68 0 2019-04-14 16:38:10
1 1 0 432380 0 6402964 0 0 28992 29696 557 979 1 2 37 61 0 2019-04-14 16:38:12
0 2 0 445796 0 6384412 0 0 26768 32134 628 1029 1 4 27 69 0 2019-04-14 16:38:14
0 2 0 374972 0 6453592 0 0 28172 30839 529 962 1 2 43 54 0 2019-04-14 16:38:16
0 2 0 317824 0 6507992 0 0 29172 29386 560 1001 1 3 27 68 0 2019-04-14 16:38:18
0 3 0 215092 0 6609132 0 0 33116 25210 621 1148 1 3 19 77 0 2019-04-14 16:38:20
0 2 0 194836 0 6621524 0 0 27786 30959 704 1152 0 5 18 77 0 2019-04-14 16:38:22
0 3 0 315648 0 6500196 0 0 31434 27226 581 1073 0 3 31 65 0 2019-04-14 16:38:24
*0 2 0 256180 0 6554676 0 0 29828 29017 668 1174 0 4 20 76 0 2019-04-14
16:38:26* <<< CRASH
0 1 0 378220 0 6552496 0 0 4348 53686 2210 3816 1 5 46 49 0 2019-04-14 16:38:28
0 1 0 389888 0 6536296 0 0 2704 56529 2454 4178 0 5 42 52 0 2019-04-14 16:38:30
0 2 0 923572 0 5998992 0 0 1612 56863 2384 3928 0 6 16 78 0 2019-04-14 16:38:32
0 0 0 908336 0 6006696 0 0 3584 49280 8961 17334 0 19 39 42 0 2019-04-14 16:38:34
0 1 0 1306480 0 5607088 0 0 264 63632 18605 37933 3 58 35 4 0 2019-04-14 16:38:36
2 1 0 1355448 0 5558576 0 0 8 59222 14817 30296 2 46 24 27 0 2019-04-14 16:38:38
2 2 0 1358224 0 5555884 0 0 0 58544 14226 28331 2 44 3 50 0 2019-04-14 16:38:40
2 1 0 1446348 0 5468748 0 0 0 58846 14376 29185 2 44 11 42 0 2019-04-14 16:38:42
0 0 0 2639648 0 4357608 0 0 0 28486 12909 26770 2 44 49 5 0 2019-04-14 16:38:44
0 0 0 2639524 0 4357800 0 0 0 0 158 154 0 0 100 0 0 2019-04-14 16:38:46
0 0 0 2687316 0 4309976 0 0 0 0 181 188 0 2 98 0 0 2019-04-14 16:38:48
0 0 0 2706920 0 4300116 0 0 0 105 137 263 0 0 100 0 0 2019-04-14 16:38:50
0 0 0 2706672 0 4300232 0 0 0 0 142 204 0 0 100 0 0 2019-04-14 16:38:52
0 0 0 2815116 0 4191928 0 0 0 0 116 242 0 0 100 0 0 2019-04-14 16:38:54
0 0 0 2815364 0 4192008 0 0 0 0 116 239 0 0 100 0 0 2019-04-14 16:38:56
0 0 0 2815116 0 4192164 0 0 0 0 159 236 0 0 100 0 0 2019-04-14 16:38:58

ending after the out of memory crash, that occurred exactly at the
marked point 16:38:26.355 UTC.

We can't really see anything too worrisome. There is always lots of
memory used by cache, which could have been mobilized. The only possible
explanation I can think of is that in that moment of the crash the
memory utilization suddenly skyrocketed in less than a second, so that
the 2 second vmstat interval wouldn't show it??? Nah.

I have already much reduced work_mem, which has helped in some other
cases before. Now I am going to reduce the shared_buffers now, but that
seems counter-intuitive because we are sitting on all that cache memory
unused!

Might this be a bug? It feels like a bug. It feels like those out of
memory issues should be handled more gracefully (garbage collection
attempt?) and that somehow there should be more information so the
person can do anything about it.

Any ideas?

-Gunther