pg.ddx.io pgsql-admin@postgresql.org mailing list archive
help / color / mirror / Atom feedpostgres 9.0 date aberration in logs
3+ messages / 2 participants
[nested] [flat]
* postgres 9.0 date aberration in logs
@ 2012-02-07 18:43 Greg Williamson <gwilliamson39@yahoo.com>
0 siblings, 1 reply; 3+ messages in thread
From: Greg Williamson @ 2012-02-07 18:43 UTC (permalink / raw)
To: pgsql-admin
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
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: postgres 9.0 date aberration in logs
@ 2012-02-07 18:59 Matheus de Oliveira <matioli.matheus@gmail.com>
parent: Greg Williamson <gwilliamson39@yahoo.com>
0 siblings, 1 reply; 3+ messages in thread
From: Matheus de Oliveira @ 2012-02-07 18:59 UTC (permalink / raw)
To: Greg Williamson <gwilliamson39@yahoo.com>; +Cc: pgsql-admin
To me seems that it just appended the data to your log. To avoid this set
the log_truncate_on_rotation to on, but notice that it will replace the old
logs.
--
Matheus de Oliveira
Bacharelado em Ciências de Computação
Laboratório de Computação de Alto Desempenho -
LCAD<http://www.lcad.icmc.usp.br/;
Instituto de Ciências Matemáticas e de Computação -
ICMC<http://www.icmc.usp.br/;
Universidade de São Paulo - USP <http://www.sc.usp.br/;
On Tue, Feb 7, 2012 at 4:43 PM, Greg Williamson <gwilliamson39@yahoo.com>wrote:
> 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
>
>
> --
> Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-admin
>
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: postgres 9.0 date aberration in logs
@ 2012-02-07 20:39 Greg Williamson <gwilliamson39@yahoo.com>
parent: Matheus de Oliveira <matioli.matheus@gmail.com>
0 siblings, 0 replies; 3+ messages in thread
From: Greg Williamson @ 2012-02-07 20:39 UTC (permalink / raw)
To: Matheus de Oliveira <matioli.matheus@gmail.com>; +Cc: pgsql-admin
Matheus --
>
>To me seems that it just appended the data to your log. To avoid this set the log_truncate_on_rotation to on, but notice that it will replace the old logs.
>
>
Thanks for the suggestion, but we seem to be using this already:
-bash-3.2$ grep log_truncate_on_rotation postgresql.conf
log_truncate_on_rotation = on# If on, an existing log file of the
Is it possible that this fails under some conditions ?
We are migrating to 9.1, which unfortunately showed the same issues at almost the same time; no complaints in system logs or restarts of the servers.
Very odd ...
Greg W.
^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2012-02-07 20:39 UTC | newest]
Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2012-02-07 18:43 postgres 9.0 date aberration in logs Greg Williamson <gwilliamson39@yahoo.com>
2012-02-07 18:59 ` Matheus de Oliveira <matioli.matheus@gmail.com>
2012-02-07 20:39 ` Greg Williamson <gwilliamson39@yahoo.com>
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