PG_DUMP producing lots of WAL archive logs

I am seeing, what appears to me, strange behavior during PG_DUMP backups.

These pg_dump backups have been running for weeks with no issue, and run very quickly.

Here is the previous days run from the log:

2012-05-23 07:10:04 PDT::@:[14715]: LOG: checkpoint starting: time
2012-05-23 07:10:04 PDT::@:[14715]: LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added,
0 removed, 0 recycled; write=0.001 s, sync=0.000 s, total=0.004 s; sync files=0, longest=0.000 s, average=0.000 s
2012-05-23 07:15:04 PDT::@:[14715]: LOG: checkpoint starting: time
2012-05-23 07:15:04 PDT::@:[14715]: LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added,
0 removed, 0 recycled; write=0.001 s, sync=0.000 s, total=0.007 s; sync files=0, longest=0.000 s, average=0.000 s
2012-05-23 07:16:44 PDT:127.0.0.1(33321):postgres(at)login:[31846]: LOG: duration: 100484.921 ms statement: COPY login.ac
count (guid, email, encoded_password, date_of_birth, first_name, last_name, screen_name, gender, is_locked, is_legacy, d
ate_registered, is_admin, parent_id, date_confirmed) TO stdout;
2012-05-23 07:16:46 PDT:127.0.0.1(33321):postgres(at)login:[31846]: LOG: duration: 554.281 ms statement: COPY login.accou
nttermsofuse (account_id, terms_of_use_id, date_accepted) TO stdout;
2012-05-23 07:17:04 PDT:127.0.0.1(33321):postgres(at)login:[31846]: LOG: duration: 18448.820 ms statement: COPY login.add
ress (id, account_id, line_1, line_2, city, region, zipcode, country) TO stdout;
2012-05-23 07:20:04 PDT::@:[14715]: LOG: checkpoint starting: time
2012-05-23 07:20:04 PDT::@:[14715]: LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added,
0 removed, 0 recycled; write=0.002 s, sync=0.000 s, total=0.045 s; sync files=0, longest=0.000 s, average=0.000 s
2012-05-23 07:25:04 PDT::@:[14715]: LOG: checkpoint starting: time

Yesterday, the database was dropped and the tables recreated and reloaded. During the load, archiving was turned off, the data was loaded via pgloader, then archiving was turned back on.
The pg_dump this morning was the first time it was run since archiving was turned on.
I can see that during the pg_dump, there were about 90 logs produced and the checkpoint took 18 minutes to complete!

2012-05-24 07:08:30 PDT::@:[1307]: LOG: checkpoint starting: time
2012-05-24 07:08:33 PDT::@:[1307]: LOG: checkpoint complete: wrote 16 buffers (0.0%); 0 transaction log file(s) added,
0 removed, 1 recycled; write=3.001 s, sync=0.015 s, total=3.018 s; sync files=10, longest=0.012 s, average=0.001 s
2012-05-24 07:15:56 PDT::@:[1307]: LOG: checkpoint starting: xlog
2012-05-24 07:16:43 PDT::@:[1307]: LOG: checkpoint complete: wrote 60685 buffers (92.6%); 0 transaction log file(s) add
ed, 0 removed, 13 recycled; write=46.811 s, sync=0.205 s, total=47.463 s; sync files=2, longest=0.205 s, average=0.102 s
2012-05-24 07:16:52 PDT::@:[1307]: LOG: checkpoint starting: xlog
2012-05-24 07:17:16 PDT:127.0.0.1(47903):postgres(at)login:[8275]: LOG: duration: 132512.452 ms statement: COPY login.acc
ount (guid, email, encoded_password, date_of_birth, first_name, last_name, screen_name, gender, is_locked, is_legacy, da
te_registered, is_admin, parent_id, date_confirmed) TO stdout;
2012-05-24 07:17:17 PDT:127.0.0.1(47903):postgres(at)login:[8275]: LOG: duration: 912.857 ms statement: COPY login.accoun
tprivacypolicy (account_id, privacy_policy_id, date_accepted) TO stdout;
2012-05-24 07:17:19 PDT:127.0.0.1(47903):postgres(at)login:[8275]: LOG: duration: 1890.924 ms statement: COPY login.accou
nttermsofuse (account_id, terms_of_use_id, date_accepted) TO stdout;
2012-05-24 07:17:41 PDT:127.0.0.1(47903):postgres(at)login:[8275]: LOG: duration: 21838.315 ms statement: COPY login.addr
ess (id, account_id, line_1, line_2, city, region, zipcode, country) TO stdout;
2012-05-24 07:17:42 PDT:127.0.0.1(47903):postgres(at)login:[8275]: LOG: duration: 1340.001 ms statement: COPY login.kids
(kid_id) TO stdout;
2012-05-24 07:17:44 PDT:127.0.0.1(47921):postgres(at)pgloader:[8592]: LOG: duration: 581.657 ms statement: SELECT tableoi
d, oid, nspname, (SELECT rolname FROM pg_catalog.pg_roles WHERE oid = nspowner) AS rolname, nspacl FROM pg_namespace
2012-05-24 07:24:17 PDT::@:[1307]: LOG: checkpoint complete: wrote 26737 buffers (40.8%); 0 transaction log file(s) add
ed, 0 removed, 51 recycled; write=445.529 s, sync=0.061 s, total=445.708 s; sync files=3, longest=0.061 s, average=0.020
s
2012-05-24 07:30:04 PDT::@:[1307]: LOG: checkpoint starting: force wait
2012-05-24 07:48:04 PDT::@:[1307]: LOG: checkpoint complete: wrote 14236 buffers (21.7%); 0 transaction log file(s) add
ed, 0 removed, 7 recycled; write=1079.602 s, sync=0.010 s, total=1079.626 s; sync files=3, longest=0.010 s, average=0.00
3 s
2012-05-24 07:50:04 PDT::@:[1307]: LOG: checkpoint starting: time
2012-05-24 07:50:04 PDT::@:[1307]: LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0
removed, 0 recycled; write=0.000 s, sync=0.000 s, total=0.277 s; sync files=0, longest=0.000 s, average=0.000 s
2012-05-24 08:10:04 PDT::@:[1307]: LOG: checkpoint starting: time

The pg_dump command I am running is:
pg_dump -Fc <database>

Would could cause so many archive logs to be created from a pg_dump, when there were none before? Would it have something to do with the fact that these tables were created unlogged?

If I pg_dump -Fc the largest tables, I don't get any archive logs created.

This is PG 9.1.3 on CentOS.

Here are some pertinent settings:

shared_buffers = 512MB # min 128kB
wal_level = hot_standby # minimal, archive, or hot_standby
fsync = on # turns forced synchronization on or off
# open_sync
full_page_writes = on # recover from partial page writes
checkpoint_segments = 32 # in logfile segments, min 1, 16MB each
checkpoint_timeout = 20min # range 30s-1h
checkpoint_completion_target = 0.9 # checkpoint target duration, 0.0 - 1.0
archive_mode = on # allows archiving to be done
archive_command = 'test ! -f /var/lib/pgsql/9.1/archive/%f && cp %p /var/lib/pgsql/9.1/archive/%f'
archive_timeout = 3600 # force a logfile segment switch after this
max_wal_senders = 3 # max number of walsender processes
# (change requires restart)
wal_keep_segments = 32 # in logfile segments, 16MB each; 0 disables

Thanks in advance, as evidenced below, Postgres is a new endeavor.

Adam

Adam Fuchs
Database Administrator
Oracle 8i,9i,10g Certified Professional

atman ('{a:}t-m*n)
Etymology: Skt i[{a-}tman], lit., breath, soul;
i[Hinduism] 1) n, the innermost essence of each individual 2) n,
the universal self