postgres 9.0 date aberration in logs

pg.ddx.io  pgsql-admin@postgresql.org mailing list archive  
help / color / mirror / Atom feed

From: Greg Williamson <gwilliamson39@yahoo.com>
To: pgsql-admin@postgresql.org <pgsql-admin@postgresql.org>
Subject: postgres 9.0 date aberration in logs
Date: Tue, 7 Feb 2012 10:43:27 -0800 (PST)
Message-ID: <1328640207.42210.YahooMailNeo@web46103.mail.sp1.yahoo.com> (raw)

The server seems to have written the wrong date for the first 45 minutes or so of Tuesday before switching in mid-stream:
<...>
2012-01-31 23:58:05 PST [13586]: [29677-1] LOG:  checkpoint starting: time
2012-01-31 23:58:08 PST [13586]: [29678-1] LOG:  checkpoint complete: wrote 16 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=3.008 s, sync=
0.001 s, total=3.010 s
2012-02-07 00:00:41 PST [30535]: [333-1] LOG:  checkpoint starting: time
2012-02-07 00:00:42 PST [30535]: [334-1] LOG:  checkpoint complete: wrote 9 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=1.603 s, sync=0.0
01 s, total=1.605 s
<...>

No editing -- honest !

This is what the log dates look like:
ls -ltr  /var/log/pg_log9.0
total 8652
-rw------- 1 postgres postgres 1729857 Feb  1 23:59 postgresql-Wed.log
-rw------- 1 postgres postgres  930974 Feb  2 23:57 postgresql-Thu.log
-rw------- 1 postgres postgres  441021 Feb  3 23:57 postgresql-Fri.log
-rw------- 1 postgres postgres 1041907 Feb  4 23:57 postgresql-Sat.log
-rw------- 1 postgres postgres 1546812 Feb  5 23:58 postgresql-Sun.log
-rw------- 1 postgres postgres 1180910 Feb  6 23:55 postgresql-Mon.log
-rw------- 1 postgres postgres 1943900 Feb  7 10:40 postgresql-Tue.log


This is the end of Monday's log:
-bash-3.2$ tail /var/log/pg_log9.0/postgresql-Mon.log
2012-02-06 23:35:41 PST [30535]: [323-1] LOG:  checkpoint starting: time
2012-02-06 23:35:42 PST [30535]: [324-1] LOG:  checkpoint complete: wrote 10 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=1.804 s, sync=0.001 s, total=1.807 s
2012-02-06 23:40:41 PST [30535]: [325-1] LOG:  checkpoint starting: time
2012-02-06 23:40:42 PST [30535]: [326-1] LOG:  checkpoint complete: wrote 10 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=1.802 s, sync=0.001 s, total=1.805 s
2012-02-06 23:45:41 PST [30535]: [327-1] LOG:  checkpoint starting: time
2012-02-06 23:45:43 PST [30535]: [328-1] LOG:  checkpoint complete: wrote 11 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=2.002 s, sync=0.001 s, total=2.005 s
2012-02-06 23:50:41 PST [30535]: [329-1] LOG:  checkpoint starting: time
2012-02-06 23:50:42 PST [30535]: [330-1] LOG:  checkpoint complete: wrote 6 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=1.007 s, sync=0.000 s, total=1.009 s
2012-02-06 23:55:41 PST [30535]: [331-1] LOG:  checkpoint starting: time
2012-02-06 23:55:42 PST [30535]: [332-1] LOG:  checkpoint complete: wrote 10 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=1.805 s, sync=0.001 s, total=1.807 s


And the start of Tuesday's:
head  /var/log/pg_log9.0/postgresql-Tue.log 
2012-01-31 00:03:53 PST [13586]: [29091-1] LOG:  checkpoint starting: time
2012-01-31 00:03:54 PST [13586]: [29092-1] LOG:  checkpoint complete: wrote 9 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=1.602 s, sync=0.001 s, total=1.604 s
2012-01-31 00:04:45 PST [6186]: [36-1] LOG:  duration: 1831.813 ms  execute fetch from S_2/C_3: select<...>


The system log doesn't show anything hinky:
ess /var/log/messages

<...>
Feb  6 23:56:56 sf1ddb001 puppet-agent[28309]: Finished catalog run in 10.51 seconds
Feb  7 00:15:53 sf1ddb001 xinetd[6141]: START: amanda pid=17175 from=192.168.50.89
Feb  7 00:16:05 sf1ddb001 xinetd[6141]: EXIT: amanda status=0 pid=17175 duration=12(sec)
Feb  7 00:18:37 sf1ddb001 xinetd[6141]: START: amanda pid=17507 from=192.168.50.89
Feb  7 00:18:37 sf1ddb001 xinetd[6141]: EXIT: amanda status=0 pid=17507 duration=0(sec)
Feb  7 00:18:55 sf1ddb001 xinetd[6141]: START: amanda pid=17776 from=192.168.50.89
Feb  7 00:18:55 sf1ddb001 xinetd[6141]: EXIT: amanda status=0 pid=17776 duration=0(sec)
Feb  7 00:19:10 sf1ddb001 xinetd[6141]: START: amanda pid=17859 from=192.168.50.89
Feb  7 00:19:10 sf1ddb001 xinetd[6141]: EXIT: amanda status=0 pid=17859 duration=0(sec)
Feb  7 00:19:26 sf1ddb001 xinetd[6141]: START: amanda pid=17880 from=192.168.50.89
Feb  7 00:19:26 sf1ddb001 xinetd[6141]: EXIT: amanda status=0 pid=17880 duration=0(sec)
Feb  7 00:19:55 sf1ddb001 xinetd[6141]: START: amanda pid=17922 from=192.168.50.89
Feb  7 00:20:02 sf1ddb001 xinetd[6141]: EXIT: amanda status=0 pid=17922 duration=7(sec)
Feb  7 00:27:12 sf1ddb001 puppet-agent[28309]: Finished catalog run in 10.36 seconds
Feb  7 00:57:27 sf1ddb001 puppet-agent[28309]: Finished catalog run in 10.16 seconds
Feb  7 01:27:43 sf1ddb001 puppet-agent[28309]: Finished catalog run in 10.86 seconds
Feb  7 01:57:59 sf1ddb001 puppet-agent[28309]: Finished catalog run in 10.48 seconds
<...>

Has anyone ever seen anything like this ? 

Thanks for any suggestions, advice, etc.

Greg WIlliamson
DBA
Powerreviews

view thread (3+ messages)  latest in thread

Message-ID: <1328640207.42210.YahooMailNeo@web46103.mail.sp1.yahoo.com>
Permalink:  ../1328640207.42210.YahooMailNeo@web46103.mail.sp1.yahoo.com/
Also on:    postgresql.org/message-id/1328640207.42210.YahooMailNeo@web46103.mail.sp1.yahoo.com

 ·

reply

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: pgsql-admin@postgresql.org
  Cc: gwilliamson39@yahoo.com
  Subject: Re: postgres 9.0 date aberration in logs
  In-Reply-To: <1328640207.42210.YahooMailNeo@web46103.mail.sp1.yahoo.com>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox