'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@hub.org Yahoo!: yscrappy ICQ: 7615664

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

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.

When did you vacuumed the table the last time?

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@hub.org Yahoo!: yscrappy ICQ: 7615664
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster
>

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

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@hub.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@hub.org Yahoo!: yscrappy ICQ: 7615664

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

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@hub.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@hub.org Yahoo!: yscrappy ICQ: 7615664
>

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

On Thu, Aug 25, 2005 at 03:56:36PM -0300, Marc G. Fournier wrote:
> On Thu, 25 Aug 2005, Aldor wrote:
> >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:

Are the updates happening inside a transaction? Is it possible
that they're being blocked by other transactions that update the
same record around the same time and don't commit immediately?
I can duplicate the results you're seeing by doing that.

--
Michael Fuhr

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

On Thu, Aug 25, 2005 at 01:55:08PM -0600, Michael Fuhr wrote:
> Are the updates happening inside a transaction? Is it possible
> that they're being blocked by other transactions that update the
> same record around the same time and don't commit immediately?
> I can duplicate the results you're seeing by doing that.

As for why you don't see long durations with EXPLAIN ANALYZE, here's
a possible explanation: "ordinary" updates of the same record might
happen close together because that's how the application works, but
by the time you run EXPLAIN ANALYZE no other transactions are updating
that record so the update executes immediately.

--
Michael Fuhr

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

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...

Michael Fuhr wrote:
> On Thu, Aug 25, 2005 at 01:55:08PM -0600, Michael Fuhr wrote:
>
>>Are the updates happening inside a transaction? Is it possible
>>that they're being blocked by other transactions that update the
>>same record around the same time and don't commit immediately?
>>I can duplicate the results you're seeing by doing that.
>
>
> As for why you don't see long durations with EXPLAIN ANALYZE, here's
> a possible explanation: "ordinary" updates of the same record might
> happen close together because that's how the application works, but
> by the time you run EXPLAIN ANALYZE no other transactions are updating
> that record so the update executes immediately.
>

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

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?

--
Michael Fuhr

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

On Thu, 25 Aug 2005, 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?

I'm working on it from that perspective ... apparently, there has been no
changes to teh database, only the application ... the weird thing is that
the application/database on teh development server (much less powerful)
isn't exhibiting the same problems, so I'm thinking there has to be
somethign slightly different between the two that they aren't thinking of
that they've made ...

Going to have to do a code review next, see if they've maybe thrown in a
TRANSACTION wouldn't realizing/thinking of it

Thanks ...


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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

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?
>

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org