negative duration times in query logs

From: "George Pavlov" <gpavlov(at)mynewplace(dot)com>
To: <pgsql-general(at)postgresql(dot)org>
Subject: negative duration times in query logs
Date: 2008-01-03 22:14:12
Message-ID: 8C5B026B51B6854CBE88121DBF097A86018F88B4@ehost010-33.exch010.intermedia.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

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

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Geoffrey 2008-01-04 00:17:00 Re: [OT] Slony (initial) Replication - Slow
Previous Message James B. Byrne 2008-01-03 21:57:33 CentOS-5 PostgreSQL 8.1.9 server instrumentation