Thread: Log message " last_statrequest ... is later than collector's time" - what does it mean?

Stephan Vollmer <vollmer.stephan@googlemail.com> writes:
> I upgraded our test database from PostgreSQL 8.4.8 to 9.0.4 via pg_dumpall.
> The database seems to work fine, but now the logfile of the new database is
> flooded with log messages like these:

> 2011-09-16 13:48:54 CEST: LOG:  last_statrequest 2011-09-16
> 13:48:55.890743+02 is later than collector's time 2011-09-16
> 13:48:54.614476+02

Wow.  AFAIK this is an indication of major system clock problems,
as in there's at least one backend process that is seeing gettimeofday()
results significantly later than what the stats collector process is
seeing.  We have seen small processor-to-processor skews before, but
you've apparently got skews that are more than a second.  It was
presumably happening before too, but pre-9.0 the stats collector doesn't
bleat about it --- we added that logging to try to diagnose such
problems.

Now it's relatively harmless so far as this particular issue goes (I
think the log bleating is the only real consequence); but it's not hard
to envision very serious problems elsewhere, for instance gmake failing
to rebuild things because file timestamps are in the future compared to
what it thinks the time is.  You want to get that fixed.

> Configuration:
> - SUSE Linux Enterprise Server 10 (i586)
> - uname -a: Linux 2.6.16.21-0.8-bigsmp #1 SMP Mon Jul 3 18:25:39 UTC 2006
> i686 athlon i386 GNU/Linux

I'd file a bug report with SUSE.  But probably the first thing they'd
say is you should be using a less ancient kernel, so maybe upgrade that
first and see if the issue goes away.

            regards, tom lane

On Fri, Sep 16, 2011 at 19:16, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Stephan Vollmer <vollmer.stephan@googlemail.com> writes:
> > I upgraded our test database from PostgreSQL 8.4.8 to 9.0.4 via pg_dumpall.
> > The database seems to work fine, but now the logfile of the new database is
> > flooded with log messages like these:
>
> > 2011-09-16 13:48:54 CEST: LOG:  last_statrequest 2011-09-16
> > 13:48:55.890743+02 is later than collector's time 2011-09-16
> > 13:48:54.614476+02
>
> Wow.  AFAIK this is an indication of major system clock problems,
> as in there's at least one backend process that is seeing gettimeofday()
> results significantly later than what the stats collector process is
> seeing.  We have seen small processor-to-processor skews before, but
> you've apparently got skews that are more than a second.  It was
> presumably happening before too, but pre-9.0 the stats collector doesn't
> bleat about it --- we added that logging to try to diagnose such
> problems.
>
> Now it's relatively harmless so far as this particular issue goes (I
> think the log bleating is the only real consequence); but it's not hard
> to envision very serious problems elsewhere, for instance gmake failing
> to rebuild things because file timestamps are in the future compared to
> what it thinks the time is.  You want to get that fixed.

Thank you for this information! I agree that this problem should be
fixed, but unfortunately I'm not the server admin and there are other
applications running on this machine (even MySQL...). In the meantime,
is there a way to filter these log messages other than setting
"log_min_messages" to "fatal" which is not really desireable?


> > Configuration:
> > - SUSE Linux Enterprise Server 10 (i586)
> > - uname -a: Linux 2.6.16.21-0.8-bigsmp #1 SMP Mon Jul 3 18:25:39 UTC 2006
> > i686 athlon i386 GNU/Linux
>
> I'd file a bug report with SUSE.  But probably the first thing they'd
> say is you should be using a less ancient kernel, so maybe upgrade that
> first and see if the issue goes away.

I'll try to persuade the admin to install at least the latest patch
version of this old kernel.

Thanks for your help and kind regards,
Stephan

Stephan Vollmer <vollmer.stephan@googlemail.com> writes:
>>> 2011-09-16 13:48:54 CEST: LOG: �last_statrequest 2011-09-16
>>> 13:48:55.890743+02 is later than collector's time 2011-09-16
>>> 13:48:54.614476+02

> is there a way to filter these log messages other than setting
> "log_min_messages" to "fatal" which is not really desireable?

Nope, not without changing the source code.  If you don't mind
recompiling then it's easy enough to remove the elog call (look in
src/backend/postmaster/pgstat.c).

            regards, tom lane