Skip site navigation (1) Skip section navigation (2)

Re: What is syslog:duration reporting ... ?

From: Aldor <an(at)mediaroot(dot)de>
To: Michael Fuhr <mike(at)fuhr(dot)org>
Cc: "Marc G(dot) Fournier" <scrappy(at)postgresql(dot)org>,pgsql-admin(at)postgresql(dot)org
Subject: Re: What is syslog:duration reporting ... ?
Date: 2005-08-26 13:27:04
Message-ID: 430F18A8.8030401@mediaroot.de (view raw or flat)
Thread:
Lists: pgsql-admin
Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG:  duration:
 > 1192.789 ms  statement: UPDATE session SET hit_time=now() WHERE
 > md5='d84613009a95296fb511c2cb051ad618';

 > Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG:  duration:
 > 12159.162 ms  statement: UPDATE session SET hit_time=now() WHERE
 > md5='d84613009a95296fb511c2cb051ad618';

20 seconds - 13 seconds (execution time) = 7 seconds

So it also happens when they are not close to each other.

The hint with the log_min_duration is a good idea.

Michael Fuhr wrote:
> On Fri, Aug 26, 2005 at 12:50:29AM +0100, Aldor wrote:
> 
>>Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG:  duration: 
>>567.559 ms  statement: UPDATE session SET hit_time=now() WHERE 
>>md5='7537b74eab488de54d6e0167d1919207';
>>Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG:  duration: 
>>565.966 ms  statement: UPDATE session SET hit_time=now() WHERE 
>>md5='d84613009a95296fb511c2cb051ad618';
>>Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG:  duration: 
>>1192.789 ms  statement: UPDATE session SET hit_time=now() WHERE 
>>md5='d84613009a95296fb511c2cb051ad618';
>>Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG:  duration: 
>>12159.162 ms  statement: UPDATE session SET hit_time=now() WHERE 
>>md5='d84613009a95296fb511c2cb051ad618';
>>Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG:  duration: 
>>3283.185 ms  statement: UPDATE session SET hit_time=now() WHERE 
>>md5='7537b74eab488de54d6e0167d1919207';
>>Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG:  duration: 
>>2116.516 ms  statement: UPDATE session SET hit_time=now() WHERE 
>>md5='7537b74eab488de54d6e0167d1919207';
>>
>>Take a look to the timestamps... they are not really close to each other...
> 
> 
> Eh?  The timestamps show that the updates *are* close to each other.
> What we don't know is whether this log excerpt shows all statements
> that were executed during its time frame.  It might have been grep'ed
> from the full log file, or the log_min_duration_statement setting
> might be such that only statements lasting more than a certain
> amount of time are logged and we're not seeing similar updates that
> happened quickly, nor when any of the updates were committed.
> 
> Marc, does my hypothesis of updates being blocked by other transactions
> sound plausible in your environment?  How complete a log did you
> post -- is it everything, or are there other statements that you
> omitted or that weren't logged because of the log_min_duration_statement
> setting?
> 

In response to

Responses

pgsql-admin by date

Next:From: Michael FuhrDate: 2005-08-26 14:09:37
Subject: Re: What is syslog:duration reporting ... ?
Previous:From: John DeSoiDate: 2005-08-26 12:26:36
Subject: Re: Password and batch process

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group