Re: does wal archiving block the current client connection?

On Tue, 16 May 2006, Simon Riggs wrote:

> I don't see much evidence for a connection between archiver and these
> issues. The problems start after autovacuum of "vb_web" at 02:08. That
> seems much more likely to have something to do with client connections
> than the archiver - which is really nothing too special. However,
> archiver doesn't start processing files again after 02:06. When is the
> next "archived transaction log file" message?
>
> Whatever happened between 02:08 and 02:14 seems important. Do you have
> any other logs to cross-correlate for different events. What do the
> clients think happened? What did they do during that time?

I have the logs and after reviewing /var/log/messages for that time period,
there is no other activity besides postgres.  The next archived transaction
log file messages are:

May 14 02:24:54 db3 postgres[22009]: [4876-1] LOG:  archived transaction log
fil
e "000000010000001600000078"
May 14 02:34:05 db3 postgres[22009]: [4877-1] LOG:  archived transaction log
fil
e "000000010000001600000079"
May 14 02:35:49 db3 postgres[22009]: [4878-1] LOG:  archived transaction log
fil
e "00000001000000160000007A"
May 14 02:41:58 db3 postgres[22009]: [4879-1] LOG:  archived transaction log
fil
e "00000001000000160000007B"
May 14 02:57:35 db3 postgres[22009]: [4880-1] LOG:  archived transaction log
fil
e "00000001000000160000007C"

The clients are all on two windows web servers, anybody know where to look for
errors with that?


>
>> May 15 01:57:31 db3 postgres[12723]: [1-1] LOG:  autovacuum: processing database "vb_web"
>> May 15 01:58:03 db3 crond(pam_unix)[12755]: session closed for user postgres
>> May 15 01:58:31 db3 postgres[12824]: [1-1] LOG:  autovacuum: processing database "template1"
>> May 15 01:59:01 db3 crond(pam_unix)[12858]: session closed for user postgres
>> May 15 01:59:31 db3 postgres[12928]: [1-1] LOG:  autovacuum: processing database "postgres"
>> May 15 02:00:10 db3 crond(pam_unix)[12964]: session closed for user postgres
>> May 15 02:00:11 db3 postgres[22008]: [1090-1] LOG:  checkpoints are occurring too frequently (10 seconds apart)
>> May 15 02:00:11 db3 postgres[22008]: [1090-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:00:14 db3 postgres[22009]: [4886-1] LOG:  archived transaction log file "00000001000000160000007F"
>> May 15 02:00:23 db3 postgres[22009]: [4887-1] LOG:  archived transaction log file "000000010000001600000080"
>> May 15 02:00:23 db3 postgres[22008]: [1091-1] LOG:  checkpoints are occurring too frequently (9 seconds apart)
>> May 15 02:00:23 db3 postgres[22008]: [1091-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:00:31 db3 postgres[22009]: [4888-1] LOG:  archived transaction log file "000000010000001600000081"
>> May 15 02:00:36 db3 postgres[13747]: [1-1] LOG:  autovacuum: processing database "vb_web"
>> May 15 02:00:36 db3 postgres[22008]: [1092-1] LOG:  checkpoints are occurring too frequently (13 seconds apart)
>> May 15 02:00:36 db3 postgres[22008]: [1092-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:00:38 db3 postgres[22009]: [4889-1] LOG:  archived transaction log file "000000010000001600000082"
>> May 15 02:00:45 db3 postgres[22009]: [4890-1] LOG:  archived transaction log file "000000010000001600000083"
>> May 15 02:00:53 db3 postgres[22009]: [4891-1] LOG:  archived transaction log file "000000010000001600000084"
>> May 15 02:00:54 db3 postgres[22008]: [1093-1] LOG:  checkpoints are occurring too frequently (18 seconds apart)
>> May 15 02:00:54 db3 postgres[22008]: [1093-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:01:00 db3 postgres[22009]: [4892-1] LOG:  archived transaction log file "000000010000001600000085"
>> May 15 02:01:05 db3 crond(pam_unix)[13815]: session closed for user postgres
>> May 15 02:01:07 db3 postgres[22009]: [4893-1] LOG:  archived transaction log file "000000010000001600000086"
>> May 15 02:01:13 db3 postgres[22008]: [1094-1] LOG:  checkpoints are occurring too frequently (19 seconds apart)
>> May 15 02:01:13 db3 postgres[22008]: [1094-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:01:14 db3 postgres[22009]: [4894-1] LOG:  archived transaction log file "000000010000001600000087"
>> May 15 02:01:23 db3 postgres[22009]: [4895-1] LOG:  archived transaction log file "000000010000001600000088"
>> May 15 02:01:25 db3 postgres[22008]: [1095-1] LOG:  checkpoints are occurring too frequently (12 seconds apart)
>> May 15 02:01:25 db3 postgres[22008]: [1095-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:01:31 db3 postgres[22009]: [4896-1] LOG:  archived transaction log file "000000010000001600000089"
>> May 15 02:01:35 db3 postgres[22008]: [1096-1] LOG:  checkpoints are occurring too frequently (10 seconds apart)
>> May 15 02:01:35 db3 postgres[22008]: [1096-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:01:39 db3 postgres[22009]: [4897-1] LOG:  archived transaction log file "00000001000000160000008A"
>> May 15 02:01:45 db3 postgres[22008]: [1097-1] LOG:  checkpoints are occurring too frequently (10 seconds apart)
>> May 15 02:01:45 db3 postgres[22008]: [1097-2] HINT:  Consider increasing the configuration parameter
"checkpoint_segments".
>> May 15 02:01:47 db3 postgres[22009]: [4898-1] LOG:  archived transaction log file "00000001000000160000008B"
>> May 15 02:01:47 db3 postgres[13964]: [1-1] LOG:  autovacuum: processing database "template1"
>> May 15 02:01:54 db3 postgres[22009]: [4899-1] LOG:  archived transaction log file "00000001000000160000008C"
>> May 15 02:02:00 db3 postgres[22009]: [4900-1] LOG:  archived transaction log file "00000001000000160000008D"
>> May 15 02:02:07 db3 crond(pam_unix)[14000]: session closed for user postgres
>> May 15 02:02:08 db3 postgres[22009]: [4901-1] LOG:  archived transaction log file "00000001000000160000008E"
>> May 15 02:02:15 db3 postgres[22009]: [4902-1] LOG:  archived transaction log file "00000001000000160000008F"
>> May 15 02:02:21 db3 postgres[22009]: [4903-1] LOG:  archived transaction log file "000000010000001600000090"
>> May 15 02:02:27 db3 postgres[22009]: [4904-1] LOG:  archived transaction log file "000000010000001600000091"
>> May 15 02:02:34 db3 postgres[22009]: [4905-1] LOG:  archived transaction log file "000000010000001600000092"
>> May 15 02:02:42 db3 postgres[22009]: [4906-1] LOG:  archived transaction log file "000000010000001600000093"
>> May 15 02:02:51 db3 postgres[14150]: [1-1] LOG:  autovacuum: processing database "postgres"
>> May 15 02:02:52 db3 postgres[22009]: [4907-1] LOG:  archived transaction log file "000000010000001600000094"
>> May 15 02:03:00 db3 postgres[22009]: [4908-1] LOG:  archived transaction log file "000000010000001600000095"
>> May 15 02:03:05 db3 crond(pam_unix)[14182]: session closed for user postgres
>> May 15 02:03:08 db3 postgres[22009]: [4909-1] LOG:  archived transaction log file "000000010000001600000096"
>> May 15 02:03:15 db3 postgres[22009]: [4910-1] LOG:  archived transaction log file "000000010000001600000097"
>> May 15 02:03:21 db3 postgres[22009]: [4911-1] LOG:  archived transaction log file "000000010000001600000098"
>> May 15 02:03:51 db3 postgres[14292]: [1-1] LOG:  autovacuum: processing database "vb_web"
>> May 15 02:04:08 db3 crond(pam_unix)[14305]: session closed for user postgres
>> May 15 02:04:51 db3 postgres[22009]: [4912-1] LOG:  archived transaction log file "000000010000001600000099"
>> May 15 02:05:05 db3 crond(pam_unix)[14415]: session closed for user postgres
>> May 15 02:06:05 db3 crond(pam_unix)[14517]: session closed for user postgres
>> May 15 02:06:24 db3 postgres[14582]: [1-1] LOG:  autovacuum: processing database "template1"
>> May 15 02:06:43 db3 postgres[22009]: [4913-1] LOG:  archived transaction log file "00000001000000160000009A"
>> May 15 02:07:07 db3 crond(pam_unix)[14632]: session closed for user postgres
>> May 15 02:07:33 db3 postgres[14702]: [1-1] LOG:  autovacuum: processing database "postgres"
>> May 15 02:08:48 db3 postgres[14724]: [1-1] LOG:  autovacuum: processing database "vb_web"
>> May 15 02:13:03 db3 postgres[14781]: [1-1] LOG:  unexpected EOF on client connection
>> May 15 02:14:42 db3 postgres[14796]: [1-1] LOG:  unexpected EOF on client connection
>> May 15 02:15:53 db3 postgres[14755]: [1-1] LOG:  unexpected EOF on client connection
>> May 15 02:16:11 db3 postgres[14856]: [1-1] LOG:  unexpected EOF on client connection
>> May 15 02:19:52 db3 postgres[14869]: [1-1] LOG:  unexpected EOF on client connection
>
>

--
Jeff Frost, Owner     <jeff@frostconsultingllc.com>
Frost Consulting, LLC     http://www.frostconsultingllc.com/
Phone: 650-780-7908    FAX: 650-649-1954