WAL partition filling up after high WAL activity

[Richard Yen <richyen@xxxxxxxxxxxxxx>]

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(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(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