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