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