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

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

From: "Marc G(dot) Fournier" <scrappy(at)postgresql(dot)org>
To: Aldor <an(at)mediaroot(dot)de>
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-25 18:56:36
Message-ID: 20050825155331.V1044@ganymede.hub.org (view raw or flat)
Thread:
Lists: pgsql-admin
On Thu, 25 Aug 2005, Aldor wrote:

> As I know EXPLAIN ANALYZE runs the query. I think you are just running the 
> query two times. The first time you run the query it will take a long time to 
> be processed - after the first run the query planner will remember the best 
> way to run the query so your second run runs much faster.
>
> I can reproduce this behavior for some queries under 8.0.1 - so I'm not 100% 
> sure if it is the same behavior under 7.4.2.
>
> I'm still wondering why you first query takes about 4107.987 ms - this kind 
> of query has usually have to run much much faster.

That would work if I were to get really occasional high values in syslog, 
but this is almost a consist thing over a very short period of time:

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';

And you will notice that the last two are the exact same md5 value ...

> When did you vacuumed the table the last time?

pg_autovacuum is running to keep things up to date, and I just ran a 
VACUUM FULL *and* a REINDEX, just to make sure things are clean ...

No matter when I try it, I can't seem to get a value above 10ms for that 
query above when I do it from psql ...



>
> Marc G. Fournier wrote:
>> 
>> 'k, I've been wracking my brains over this today, and I'm either 
>> mis-understanding what is being reported *or* its reporting wrong ...
>> 
>> According to syslog:
>> 
>> LOG:  duration: 4107.987 ms  statement: UPDATE session SET hit_time=now() 
>> WHERE md5='8b8e7b7ff9b1b2ed5fc60218ced28d00';
>> 
>> But, if I do an EXPLAIN ANALYZE:
>> 
>> # explain analyze UPDATE session SET hit_time=now() WHERE 
>> md5='702c6cb20d5eb254c3feb2991e7e5e31';
>>                                                          QUERY PLAN
>> 
>> ----------------------------------------------------------------------------------------------------------------------------
>>  Index Scan using session_md5_key on "session"  (cost=0.00..6.01 rows=1 
>> width=93) (actual time=0.060..0.060 rows=0 loops=1)
>>    Index Cond: (md5 = '702c6cb20d5eb254c3feb2991e7e5e31'::bpchar)
>>  Total runtime: 0.171 ms
>> (3 rows)
>> 
>> And it doesn't matter what value I put for md5, I still get <1ms ...
>> 
>> I could see some variations, but almost 4000x slower  to *really* run the 
>> query vs an explain analyze?
>> 
>> This is with 7.4.2 ...
>> 
>> ----
>> Marc G. Fournier           Hub.Org Networking Services (http://www.hub.org)
>> Email: scrappy(at)hub(dot)org           Yahoo!: yscrappy              ICQ: 7615664
>> 
>> ---------------------------(end of broadcast)---------------------------
>> TIP 2: Don't 'kill -9' the postmaster
>> 
>

----
Marc G. Fournier           Hub.Org Networking Services (http://www.hub.org)
Email: scrappy(at)hub(dot)org           Yahoo!: yscrappy              ICQ: 7615664

In response to

Responses

pgsql-admin by date

Next:From: AldorDate: 2005-08-25 19:32:29
Subject: Re: What is syslog:duration reporting ... ?
Previous:From: AldorDate: 2005-08-25 18:50:25
Subject: Re: What is syslog:duration reporting ... ?

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