WAL partition filling up after high WAL activity

Hi Everyone,

I recently saw a crash on one of our databases, and I was wondering if this
might be an indication of something with WAL that might be unexpectedly
creating more files than it needs to?

Nov 5 16:18:27 localhost postgres[25092]: [111-1] 2011-11-05 16:18:27.524
PDT [user=slony,db=uk dbhub.com <http://dbhub.sac.iparadigms.com/>(35180)
PID:25092 XID:2142895751]PANIC: could not write to file
"pg_xlog/xlogtemp.25092": No space left on device
Nov 5 16:18:27 localhost postgres[25092]: [111-2] 2011-11-05 16:18:27.524
PDT [user=slony,db=uk dbhub.com <http://dbhub.sac.iparadigms.com/>(35180)
PID:25092 XID:2142895751]STATEMENT: select "_sac_uk".forwardConfirm(2, 4, '
5003717188', '2011-11-05 16:18:26.977112');
Nov 5 16:18:27 localhost postgres[32121]: [7-1] 2011-11-05 16:18:27.531
PDT [user=,db= PID:32121 XID:0]LOG: server process (PID 25092) was
terminated by signal 6: Aborted
Nov 5 16:18:27 localhost postgres[32121]: [8-1] 2011-11-05 16:18:27.531
PDT [user=,db= PID:32121 XID:0]LOG: terminating any other active server
processes

If you look at this graph (http://cl.ly/2y0W27330t3o2J281H3K) the
partition actually fills up, and the logs show that postgres crashed.
After postgres crashed, it automatically restarted, cleared out its WAL
files, and began processing things again at 4:30PM.

From the graph, it looks like a vacuum on table m_dg_read finished at
4:08PM, which might explain why the downward slope levels off for a few
minutes:

> Nov 5 16:08:03 localhost postgres[18741]: [20-1] 2011-11-05 16:08:03.400
> PDT [user=,db= PID:18741 XID:0]LOG: automatic vacuum of table
> "uk.public.m_dg_read": index scans: 1
> Nov 5 16:08:03 localhost postgres[18741]: [20-2] pages: 0 removed,
> 65356 remain
> Nov 5 16:08:03 localhost postgres[18741]: [20-3] tuples: 31770
> removed, 1394263 remain
> Nov 5 16:08:03 localhost postgres[18741]: [20-4] system usage: CPU
> 2.08s/5.35u sec elapsed 619.39 sec

Looks like right afterwards, it got started on table m_object, which
finished at 4:18PM:

> Nov 5 16:18:19 localhost postgres[18686]: [9-1] 2011-11-05 16:18:19.448
> PDT [user=,db= PID:18686 XID:0]LOG: automatic vacuum of table
> "uk.public.m_object": index scans: 1
> Nov 5 16:18:19 localhost postgres[18686]: [9-2] pages: 0 removed,
> 152862 remain
> Nov 5 16:18:19 localhost postgres[18686]: [9-3] tuples: 17084
> removed, 12455761 remain
> Nov 5 16:18:19 localhost postgres[18686]: [9-4] system usage: CPU
> 4.55s/15.09u sec elapsed 1319.98 sec

It could very well be the case that upon the finish of m_object's vacuum,
another vacuum was beginning, and it eventually just crashed because there
was no room for another vacuum to finish.

We encountered a situation like this last summer on 7/4/2010 for a
different database cluster -- a big vacuum-for-wraparound on at 15GB table
filled the pg_xlog partition--this is how we started monitoring the pg_xlog
file size and wraparound countdown. Seems like there was some sort of
vacuum-for-wraparound process happening during the time of this crash, as
we also track the XID to see when we should expect a VACUUM FREEZE (
http://cl.ly/3s1S373I0l0v3E171Z0V)

Some configs:
checkpoint_segments=16
wal_buffers=8MB
#archive_mode=off
checkpoint_completion_target=0.9

Postgres version is 8.4.5

Note also that the pg_xlog partition is 9.7GB. No other apps run on the
machine besides pgbouncer, so it's highly unlikely that files are written
to this partition by another process. Also, our five largest tables are
the following:
gm3_load_times | 2231 MB
m_object_paper | 1692 MB
m_object | 1192 MB
m_report_stats | 911 MB
gm3_mark | 891 MB

My biggest question is: we know from the docs that there should be no more
than (2 + checkpoint_completion_target) * checkpoint_segments + 1 files.
For us, that would mean no more than 48 files, which equates to 384MB--far
lower than the 9.7GB partition size. **Why would WAL use up so much disk
space?**

Thanks for reading, and thanks in advance for any help you may provide.
--Richard