Re: does wal archiving block the current client connection? - Mailing list pgsql-admin

On Mon, 2006-05-15 at 16:58 -0700, Jeff Frost wrote:

> The log is below.  Note that the problem began around 2a.m. around the time
> the complaint about checkpoint segments happens.  After a bit of research it
> appears that the checkpoint complaint happens when our db maintenance job
> kicks off at 2:00a.m. The crisis ended around 3:45a.m. with the restart of the
> NAS device and normal operations resumed just before the end of this log.
> There were also lots of CIFS errors of the following type in dmesg and in the
> log:
>
>   CIFS VFS: Send error in read = -9
>   CIFS VFS: Send error in read = -9

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?

> 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

--
  Simon Riggs
  EnterpriseDB   http://www.enterprisedb.com