Обсуждение: negative duration times in query logs

Поиск
Список
Период
Сортировка

negative duration times in query logs

От
"George Pavlov"
Дата:
I started seeing some negative durations in my production query logs --
a "-" sign preceding the duration number, e.g.:

% grep 'duration: -' postgresql-Wed-*
postgresql-Wed-09.log:2008-01-02 08:56:33 PST [11705]: [538-1] LOG:
duration: -268280.421 ms
postgresql-Wed-15.log:2008-01-02 15:01:01 PST [30072]: [18-1] LOG:
duration: -1005.500 ms
postgresql-Wed-15.log:2008-01-02 15:01:01 PST [30066]: [14-1] LOG:
duration: -265.634 ms

These follow fairly standard queries that are issued hundreds if not
thousands times a day and ordinarily produce "normal" (positive)
durations.

Has anyone seen this before? Any special meaning to the minus sign
(maybe it does not mean negative, but something else?)

I am running:

PostgreSQL 8.1.10 on x86_64-redhat-linux-gnu, compiled by GCC gcc (GCC)
3.4.6 20060404 (Red Hat 3.4.6-3)

My logging setup is:

 log_connections                 | on
 log_destination                 | stderr
 log_disconnections              | on
 log_duration                    | on
 log_error_verbosity             | default
 log_executor_stats              | off
 log_hostname                    | off
 log_line_prefix                 | %t [%p]: [%l-1]
 log_min_duration_statement      | -1
 log_min_error_statement         | panic
 log_min_messages                | notice
 log_parser_stats                | off
 log_planner_stats               | off
 log_rotation_age                | 60
 log_rotation_size               | 0
 log_statement                   | all
 log_statement_stats             | off
 log_truncate_on_rotation        | on
 redirect_stderr                 | on

George

Re: negative duration times in query logs

От
Tom Lane
Дата:
"George Pavlov" <gpavlov@mynewplace.com> writes:
> I started seeing some negative durations in my production query logs --
> a "-" sign preceding the duration number, e.g.:

> % grep 'duration: -' postgresql-Wed-*
> postgresql-Wed-09.log:2008-01-02 08:56:33 PST [11705]: [538-1] LOG:
> duration: -268280.421 ms

AFAICS this is only possible if gettimeofday() goes backwards, ie,
a later call returns a time less than an earlier one did.

> I am running:
> PostgreSQL 8.1.10 on x86_64-redhat-linux-gnu, compiled by GCC gcc (GCC)
> 3.4.6 20060404 (Red Hat 3.4.6-3)

A quick search in Red Hat's bugzilla turns up several known instances of
time-going-backwards on various x86_64 hardware, eg
https://bugzilla.redhat.com/show_bug.cgi?id=241373
https://bugzilla.redhat.com/show_bug.cgi?id=244697
You might want to try to duplicate the problem using one of the test
programs mentioned there, and then add your hardware and kernel
details to the thread ... or open a new bug if it seems to be different
from these.

If your kernel isn't fully up-to-date, don't bother testing until you
have one that is ...

            regards, tom lane