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

From: Aldor <an(at)mediaroot(dot)de>
To: "Marc G(dot) Fournier" <scrappy(at)postgresql(dot)org>
Cc: pgsql-admin(at)postgresql(dot)org
Subject: Re: What is syslog:duration reporting ... ?
Date: 2005-08-25 19:32:29
Message-ID: 430E1CCD.6000700@mediaroot.de
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-admin

Can you post the code you created the INDEX with - I think there is
something which could explain the duration.

Marc G. Fournier wrote:
> 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

Browse pgsql-admin by date

  From Date Subject
Next Message Michael Fuhr 2005-08-25 19:55:09 Re: What is syslog:duration reporting ... ?
Previous Message Marc G. Fournier 2005-08-25 18:56:36 Re: What is syslog:duration reporting ... ?