memory leak in 8.2.4

Resend attempt -- previous attempt rejected for size. I have NOT
attached the PostgreSQL log (110kB) to this attempt.

----------

We had an odd problem the other night which appears to be a rare but
serious bug in PostgreSQL 8.2.4. I don't see anything in the release
notes to indicate that this has been found and fixed. We don't need
any assistance here, but I thought I should get this "on the record"
in case others hit it -- my report might help find a pattern. (It
seems unlikely that I have enough information here to pin down the
cause.)

We fired off scripts for fourteen counties, to do DML against tables
which have countyNo as the high order part of their primary key. The
scripts called a series of plpgsql functions to do the actual work.
Each function accepts countyNo as a parameter and uses it in the data
modifications, so there should not be any overlap in the rows
affected. The scripts were fired as background processes in a tight
loop (using xargs from a county list), so they would all have started
within a very short time. The connect across TCP from another machine
on the same LAN. (We do this sort of thing frequently, by the way,
and have only hit this problem once.)

Within a few minutes of starting the scripts, the system became
unresponsive to TCP connection attempts. Our operations center runs
software which connects to the database, our software publisher, and
our middle tiers to check health and report problems; all monitored
connection attempts failed. This happened around 20:20 local time.
The system logs don't show anything at this point, and the PostgreSQL
log only shows this:

[2008-07-16 20:20:12.456 CDT] 6008 LOG: checkpoints are occurring too
frequently (19 seconds apart)
[2008-07-16 20:20:12.456 CDT] 6008 HINT: Consider increasing the
configuration parameter "checkpoint_segments".
[2008-07-16 20:20:28.386 CDT] 6008 LOG: checkpoints are occurring too
frequently (16 seconds apart)
[2008-07-16 20:20:28.386 CDT] 6008 HINT: Consider increasing the
configuration parameter "checkpoint_segments".
[2008-07-16 20:20:43.158 CDT] 6008 LOG: checkpoints are occurring too
frequently (15 seconds apart)
[2008-07-16 20:20:43.158 CDT] 6008 HINT: Consider increasing the
configuration parameter "checkpoint_segments".
[2008-07-16 20:20:54.052 CDT] 6008 LOG: checkpoints are occurring too
frequently (11 seconds apart)
[2008-07-16 20:20:54.052 CDT] 6008 HINT: Consider increasing the
configuration parameter "checkpoint_segments".

Seeing the distress reported by the opcenter software, a DBA attempted
to ssh to the box and got a timeout error on his end. The system log
shows this:

Jul 16 20:43:39 ATHENA sshd[15645]: fatal: Timeout before
authentication for 165.219.91.223

He left it in that state for investigation next day. The logs are
quiet until 01:51 the next day.

Jul 16 22:06:15 ATHENA -- MARK --
Jul 17 01:52:26 ATHENA -- MARK --
Jul 17 01:51:56 ATHENA kernel: Mem-info:
Jul 17 01:51:56 ATHENA kernel: DMA per-cpu:
Jul 17 01:51:56 ATHENA kernel: cpu 0 hot: low 2, high 6, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 0 cold: low 0, high 2, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 1 hot: low 2, high 6, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 1 cold: low 0, high 2, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 2 hot: low 2, high 6, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 2 cold: low 0, high 2, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 3 hot: low 2, high 6, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 3 cold: low 0, high 2, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 4 hot: low 2, high 6, batch 1
Jul 17 01:51:56 ATHENA kernel: cpu 4 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 5 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 5 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 6 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 6 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 7 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 7 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: Normal per-cpu:
Jul 17 01:52:26 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: HighMem per-cpu:
Jul 17 01:52:26 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel:
Jul 17 01:52:26 ATHENA kernel: Free pages: 395096kB (496kB
HighMem)
Jul 17 01:52:26 ATHENA kernel: Active:226494 inactive:2762411 dirty:0
writeback:0 unstable:0 free:98774 slab:8754 mapped:2949468
pagetables:10916
Jul 17 01:52:26 ATHENA kernel: DMA free:11928kB min:32kB low:64kB
high:96kB active:0kB inactive:0kB present:16384kB pages_scanned:0
all_unreclaimable? no
Jul 17 01:52:26 ATHENA kernel: lowmem_reserve[]: 0 880 12784
Jul 17 01:52:26 ATHENA kernel: Normal free:382672kB min:1876kB
low:3752kB high:5628kB active:40092kB inactive:304120kB present:901120kB
pages_scanned:13988638 all_unreclaimable? y
es
Jul 17 01:52:26 ATHENA kernel: lowmem_reserve[]: 0 0 95232
Jul 17 01:52:26 ATHENA kernel: HighMem free:496kB min:512kB low:1024kB
high:1536kB active:865884kB inactive:10745524kB present:12189696kB
pages_scanned:78175404 all_unreclaimable?
yes
Jul 17 01:52:26 ATHENA kernel: lowmem_reserve[]: 0 0 0
Jul 17 01:52:26 ATHENA kernel: DMA: 2*4kB 4*8kB 3*16kB 2*32kB 4*64kB
2*128kB 2*256kB 1*512kB 0*1024kB 1*2048kB 2*4096kB = 11928kB
Jul 17 01:52:26 ATHENA kernel: Normal: 46*4kB 7669*8kB 1803*16kB
1122*32kB 158*64kB 44*128kB 6*256kB 3*512kB 0*1024kB 0*2048kB 58*4096kB
= 382672kB
Jul 17 01:52:26 ATHENA kernel: HighMem: 0*4kB 0*8kB 13*16kB 3*32kB
3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 496kB
Jul 17 01:52:26 ATHENA kernel: Swap cache: add 361070, delete 361073,
find 45148/59699, race 0+335
Jul 17 01:52:26 ATHENA kernel: Free swap: 0kB
Jul 17 01:52:26 ATHENA kernel: 3276800 pages of RAM
Jul 17 01:52:26 ATHENA kernel: 2916241 pages of HIGHMEM
Jul 17 01:52:26 ATHENA kernel: 159255 reserved pages
Jul 17 01:52:26 ATHENA kernel: 11756 pages shared
Jul 17 01:52:26 ATHENA kernel: 0 pages swap cached
Jul 17 01:52:26 ATHENA kernel: Out of Memory: Killed process 15713
(java).
Jul 17 01:52:26 ATHENA kernel: Mem-info:
Jul 17 01:52:26 ATHENA kernel: DMA per-cpu:
Jul 17 01:52:26 ATHENA kernel: cpu 0 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 0 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 1 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 1 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 2 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 2 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 3 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 3 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 4 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 4 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 5 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 5 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 6 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 6 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 7 hot: low 2, high 6, batch 1
Jul 17 01:52:26 ATHENA kernel: cpu 7 cold: low 0, high 2, batch 1
Jul 17 01:52:26 ATHENA kernel: Normal per-cpu:
Jul 17 01:52:26 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: HighMem per-cpu:
Jul 17 01:52:26 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 01:52:26 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 01:52:26 ATHENA kernel:
Jul 17 01:52:26 ATHENA kernel: Free pages: 395096kB (496kB
HighMem)
Jul 17 01:52:26 ATHENA kernel: Active:285039 inactive:2704024 dirty:0
writeback:0 unstable:0 free:98774 slab:8752 mapped:2949468
pagetables:10916
Jul 17 01:52:26 ATHENA kernel: DMA free:11928kB min:32kB low:64kB
high:96kB active:0kB inactive:0kB present:16384kB pages_scanned:0
all_unreclaimable? no
Jul 17 01:52:26 ATHENA kernel: lowmem_reserve[]: 0 880 12784
Jul 17 01:52:26 ATHENA kernel: Normal free:382672kB min:1876kB
low:3752kB high:5628kB active:101728kB inactive:243508kB
present:901120kB pages_scanned:14036185 all_unreclaimable?
yes
Jul 17 01:52:26 ATHENA kernel: lowmem_reserve[]: 0 0 95232
Jul 17 01:52:26 ATHENA kernel: HighMem free:496kB min:512kB low:1024kB
high:1536kB active:1038512kB inactive:10572588kB present:12189696kB
pages_scanned:78251647 all_unreclaimable
? yes
Jul 17 01:52:26 ATHENA kernel: lowmem_reserve[]: 0 0 0
Jul 17 01:52:26 ATHENA kernel: DMA: 2*4kB 4*8kB 3*16kB 2*32kB 4*64kB
2*128kB 2*256kB 1*512kB 0*1024kB 1*2048kB 2*4096kB = 11928kB
Jul 17 01:52:26 ATHENA kernel: Normal: 46*4kB 7669*8kB 1803*16kB
1122*32kB 158*64kB 44*128kB 6*256kB 3*512kB 0*1024kB 0*2048kB 58*4096kB
= 382672kB
Jul 17 01:52:26 ATHENA kernel: HighMem: 0*4kB 0*8kB 13*16kB 3*32kB
3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 496kB
Jul 17 01:52:26 ATHENA kernel: Swap cache: add 361070, delete 361073,
find 45148/59699, race 0+335
Jul 17 01:52:26 ATHENA kernel: Free swap: 0kB
Jul 17 01:52:26 ATHENA kernel: 3276800 pages of RAM
Jul 17 01:52:26 ATHENA kernel: 2916241 pages of HIGHMEM
Jul 17 01:52:26 ATHENA kernel: 159255 reserved pages
Jul 17 01:52:26 ATHENA kernel: 11721 pages shared
Jul 17 01:52:26 ATHENA kernel: 0 pages swap cached
Jul 17 01:52:26 ATHENA kernel: Out of Memory: Killed process 15522
(java).
Jul 17 01:52:29 ATHENA sshd[15730]: Did not receive identification
string from 165.219.91.223

At this point the PostgreSQL log file shows "unexpected EOF on client
connection" for each of the connections held by the killed java
processes.

Things are quiet in the logs again for about an hour. Then:

Jul 17 02:10:48 ATHENA /USR/SBIN/CRON[15884]: (root) CMD ( rm -f
/var/spool/cron/lastrun/cron.hourly)
Jul 17 02:26:08 ATHENA /USR/SBIN/CRON[15890]: (root) CMD
(/sbin/evlogmgr -c 'age > "30d"')
Jul 17 02:51:46 ATHENA -- MARK --
Jul 17 02:51:45 ATHENA kernel: Mem-info:
Jul 17 02:51:45 ATHENA kernel: DMA per-cpu:
Jul 17 02:51:45 ATHENA kernel: cpu 0 hot: low 2, high 6, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 0 cold: low 0, high 2, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 1 hot: low 2, high 6, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 1 cold: low 0, high 2, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 2 hot: low 2, high 6, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 2 cold: low 0, high 2, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 3 hot: low 2, high 6, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 3 cold: low 0, high 2, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 4 hot: low 2, high 6, batch 1
Jul 17 02:51:45 ATHENA kernel: cpu 4 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 5 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 5 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 6 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 6 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 7 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 7 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: Normal per-cpu:
Jul 17 02:51:46 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: HighMem per-cpu:
Jul 17 02:51:46 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel:
Jul 17 02:51:46 ATHENA kernel: Free pages: 394756kB (496kB
HighMem)
Jul 17 02:51:46 ATHENA kernel: Active:896711 inactive:2100141 dirty:0
writeback:0 unstable:0 free:98689 slab:4921 mapped:2956734
pagetables:9842
Jul 17 02:51:46 ATHENA kernel: DMA free:11928kB min:32kB low:64kB
high:96kB active:0kB inactive:0kB present:16384kB pages_scanned:0
all_unreclaimable? no
Jul 17 02:51:46 ATHENA kernel: lowmem_reserve[]: 0 880 12784
Jul 17 02:51:46 ATHENA kernel: Normal free:382332kB min:1876kB
low:3752kB high:5628kB active:249164kB inactive:124252kB
present:901120kB pages_scanned:950251 all_unreclaimable? ye
s
Jul 17 02:51:46 ATHENA kernel: lowmem_reserve[]: 0 0 95232
Jul 17 02:51:46 ATHENA kernel: HighMem free:496kB min:512kB low:1024kB
high:1536kB active:3337680kB inactive:8276312kB present:12189696kB
pages_scanned:11916278 all_unreclaimable?
yes
Jul 17 02:51:46 ATHENA kernel: lowmem_reserve[]: 0 0 0
Jul 17 02:51:46 ATHENA kernel: DMA: 2*4kB 4*8kB 3*16kB 2*32kB 4*64kB
2*128kB 2*256kB 1*512kB 0*1024kB 1*2048kB 2*4096kB = 11928kB
Jul 17 02:51:46 ATHENA kernel: Normal: 31*4kB 6476*8kB 1886*16kB
1162*32kB 212*64kB 65*128kB 8*256kB 3*512kB 0*1024kB 0*2048kB 58*4096kB
= 382332kB
Jul 17 02:51:46 ATHENA kernel: HighMem: 0*4kB 0*8kB 1*16kB 1*32kB
1*64kB 1*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 496kB
Jul 17 02:51:46 ATHENA kernel: Swap cache: add 403814, delete 403818,
find 47998/63968, race 0+336
Jul 17 02:51:46 ATHENA kernel: Free swap: 0kB
Jul 17 02:51:46 ATHENA kernel: 3276800 pages of RAM
Jul 17 02:51:46 ATHENA kernel: 2916241 pages of HIGHMEM
Jul 17 02:51:46 ATHENA kernel: 159255 reserved pages
Jul 17 02:51:46 ATHENA kernel: 9232 pages shared
Jul 17 02:51:46 ATHENA kernel: 0 pages swap cached
Jul 17 02:51:46 ATHENA kernel: Out of Memory: Killed process 15868
(java).
Jul 17 02:51:46 ATHENA kernel: Mem-info:
Jul 17 02:51:46 ATHENA kernel: DMA per-cpu:
Jul 17 02:51:46 ATHENA kernel: cpu 0 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 0 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 1 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 1 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 2 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 2 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 3 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 3 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 4 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 4 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 5 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 5 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 6 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 6 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 7 hot: low 2, high 6, batch 1
Jul 17 02:51:46 ATHENA kernel: cpu 7 cold: low 0, high 2, batch 1
Jul 17 02:51:46 ATHENA kernel: Normal per-cpu:
Jul 17 02:51:46 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: HighMem per-cpu:
Jul 17 02:51:46 ATHENA kernel: cpu 0 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 0 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 1 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 2 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 3 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 4 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 5 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 6 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 hot: low 62, high 186, batch 31
Jul 17 02:51:46 ATHENA kernel: cpu 7 cold: low 0, high 62, batch 31
Jul 17 02:51:46 ATHENA kernel:
Jul 17 02:51:46 ATHENA kernel: Free pages: 395224kB (496kB
HighMem)
Jul 17 02:51:46 ATHENA kernel: Active:875366 inactive:2121468 dirty:0
writeback:0 unstable:0 free:98806 slab:4770 mapped:2956753
pagetables:9843
Jul 17 02:51:46 ATHENA kernel: DMA free:11928kB min:32kB low:64kB
high:96kB active:0kB inactive:0kB present:16384kB pages_scanned:0
all_unreclaimable? no
Jul 17 02:51:46 ATHENA kernel: lowmem_reserve[]: 0 880 12784
Jul 17 02:51:46 ATHENA kernel: Normal free:382800kB min:1876kB
low:3752kB high:5628kB active:212828kB inactive:159640kB
present:901120kB pages_scanned:792995 all_unreclaimable? ye
s
Jul 17 02:51:46 ATHENA kernel: lowmem_reserve[]: 0 0 95232
Jul 17 02:51:46 ATHENA kernel: HighMem free:496kB min:512kB low:1024kB
high:1536kB active:3288636kB inactive:8326232kB present:12189696kB
pages_scanned:12919854 all_unreclaimable?
yes
Jul 17 02:51:46 ATHENA kernel: lowmem_reserve[]: 0 0 0
Jul 17 02:51:46 ATHENA kernel: DMA: 2*4kB 4*8kB 3*16kB 2*32kB 4*64kB
2*128kB 2*256kB 1*512kB 0*1024kB 1*2048kB 2*4096kB = 11928kB
Jul 17 02:51:46 ATHENA kernel: Normal: 0*4kB 6530*8kB 1896*16kB
1162*32kB 212*64kB 65*128kB 8*256kB 3*512kB 0*1024kB 0*2048kB 58*4096kB
= 382800kB
Jul 17 02:51:46 ATHENA kernel: HighMem: 0*4kB 0*8kB 1*16kB 1*32kB
1*64kB 1*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 496kB
Jul 17 02:51:46 ATHENA kernel: Swap cache: add 403814, delete 403818,
find 47998/63968, race 0+336
Jul 17 02:51:46 ATHENA kernel: Free swap: 0kB
Jul 17 02:51:46 ATHENA kernel: 3276800 pages of RAM
Jul 17 02:51:46 ATHENA kernel: 2916241 pages of HIGHMEM
Jul 17 02:51:46 ATHENA kernel: 159255 reserved pages
Jul 17 02:51:46 ATHENA kernel: 9410 pages shared
Jul 17 02:51:46 ATHENA kernel: 0 pages swap cached
Jul 17 02:51:46 ATHENA kernel: Out of Memory: Killed process 15257
(postgres).
Jul 17 02:59:01 ATHENA /USR/SBIN/CRON[15991]: (root) CMD ( rm -f
/var/spool/cron/lastrun/cron.hourly)
Jul 17 03:11:46 ATHENA -- MARK --
Jul 17 03:31:46 ATHENA -- MARK --

At this point the PostgreSQL log (attached) gets very busy, and
connectivity to the machine is possible again. Before I was in
another DBA attempted a fast shutdown, which didn't complete until he
killed the five processes still left trying to run the functions. The
database started OK:

[2008-07-17 07:22:42.010 CDT] 17569 LOG: database system was shut down
at 2008-07-17 07:21:57 CDT
[2008-07-17 07:22:42.010 CDT] 17569 LOG: checkpoint record is at
568/B428B38
[2008-07-17 07:22:42.010 CDT] 17569 LOG: redo record is at
568/B428B38; undo record is at 0/0; shutdown TRUE
[2008-07-17 07:22:42.010 CDT] 17569 LOG: next transaction ID:
1/512039718; next OID: 5164114
[2008-07-17 07:22:42.010 CDT] 17569 LOG: next MultiXactId: 1; next
MultiXactOffset: 0
[2008-07-17 07:22:42.010 CDT] 17569 LOG: database system is ready

I've requested that they check pg_locks and pg_stat_activity if this
happens again. I suspect that the most interesting information was
lost when the kernel killed the postgres backend; but, should we catch
one of these in progress, and have an open connection which functions
for us, what other diagnostic steps would be good?

kgrittn(at)ATHENA:/opt/ccap/bigbird/jars> uname -a
Linux ATHENA 2.6.5-7.244-bigsmp #1 SMP Mon Dec 12 18:32:25 UTC 2005
i686 i686 i386 GNU/Linux
kgrittn(at)ATHENA:/opt/ccap/bigbird/jars> cat /proc/version
Linux version 2.6.5-7.244-bigsmp (geeko(at)buildhost) (gcc version 3.3.3
(SuSE Linux)) #1 SMP Mon Dec 12 18:32:25 UTC 2005
kgrittn(at)ATHENA:/opt/ccap/bigbird/jars> cat /etc/SuSE-release
SUSE LINUX Enterprise Server 9 (i586)
VERSION = 9
PATCHLEVEL = 3
ATHENA:~ # free -m
total used free shared buffers
cached
Mem: 12177 11789 388 0 0
11038
-/+ buffers/cache: 751 11426
Swap: 1027 5 1021
ATHENA:~ # df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda2 68G 5.6G 62G 9% /
tmpfs 6.0G 16K 6.0G 1% /dev/shm
/dev/sdb1 821G 269G 553G 33% /var/pgsql/data

8 of these: Intel(R) Xeon(TM) MP CPU 3.00GHz

BBU RAID controller with 256 MB of RAM

postgres(at)ATHENA:~> pg_config
BINDIR = /usr/local/pgsql-8.2.4/bin
DOCDIR = /usr/local/pgsql-8.2.4/doc
INCLUDEDIR = /usr/local/pgsql-8.2.4/include
PKGINCLUDEDIR = /usr/local/pgsql-8.2.4/include
INCLUDEDIR-SERVER = /usr/local/pgsql-8.2.4/include/server
LIBDIR = /usr/local/pgsql-8.2.4/lib
PKGLIBDIR = /usr/local/pgsql-8.2.4/lib
LOCALEDIR =
MANDIR = /usr/local/pgsql-8.2.4/man
SHAREDIR = /usr/local/pgsql-8.2.4/share
SYSCONFDIR = /usr/local/pgsql-8.2.4/etc
PGXS = /usr/local/pgsql-8.2.4/lib/pgxs/src/makefiles/pgxs.mk
CONFIGURE = '--prefix=/usr/local/pgsql-8.2.4'
'--enable-integer-datetimes' '--enable-debug' '--disable-nls'
CC = gcc
CPPFLAGS = -D_GNU_SOURCE
CFLAGS = -O2 -Wall -Wmissing-prototypes -Wpointer-arith -Winline
-Wendif-labels -fno-strict-aliasing -g
CFLAGS_SL = -fpic
LDFLAGS = -Wl,-rpath,'/usr/local/pgsql-8.2.4/lib'
LDFLAGS_SL =
LIBS = -lpgport -lz -lreadline -lcrypt -ldl -lm
VERSION = PostgreSQL 8.2.4

listen_addresses = '*'
max_connections = 200
shared_buffers = 160MB
temp_buffers = 50MB
work_mem = 10MB
maintenance_work_mem = 160MB
max_fsm_pages = 800000
bgwriter_lru_percent = 20.0
bgwriter_lru_maxpages = 200
bgwriter_all_percent = 10.0
bgwriter_all_maxpages = 600
wal_buffers = 160kB
checkpoint_segments = 10
archive_command = ''
random_page_cost = 2.0
effective_cache_size = 10GB
redirect_stderr = on
log_line_prefix = '[%m] %p %q<%u %d %r> '
stats_block_level = on
stats_row_level = on
autovacuum = on
autovacuum_naptime = 10s
autovacuum_vacuum_threshold = 1
autovacuum_analyze_threshold = 1
datestyle = 'iso, mdy'
lc_messages = 'C'
lc_monetary = 'C'
lc_numeric = 'C'
lc_time = 'C'
escape_string_warning = off
standard_conforming_strings = on
sql_inheritance = off

-Kevin