Обсуждение: What is syslog:duration reporting ... ?

'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

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
>

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

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
>

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

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

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

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

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

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

On Fri, Aug 26, 2005 at 02:27:04PM +0100, Aldor wrote:
> 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.

Perhaps you're overlooking the possibility that the first update
was part of a transaction that didn't commit until ~20 seconds after
the update was issued, and that the second update was started
sometime in between.  Another possibility is that other transactions
were happening but weren't logged because their statements executed
in less time than the log_min_duration_statement setting (but the
transactions themselves might have lasted much longer).  Marc, what
*is* the log_min_duration_statement setting?

Here's a hypothetical example that would account for the above log
entries, using T1, T2, and T3 for three different transactions (of
which only T2 and T3 are shown in the log excerpt, and then only
their long-lasting UPDATE statements):

14:53:29  T1 BEGIN
14:53:30  T1 UPDATE (completes immediately)
14:53:31  T2 BEGIN
14:53:32  T2 UPDATE (blocks because of T1's UPDATE)
14:53:33  T1 COMMIT (T2's UPDATE unblocks and is logged as taking 1192.789 ms)
14:53:40  T3 BEGIN
14:53:41  T3 UPDATE (blocks)
14:53:53  T2 COMMIT (T3's UPDATE unblocks and is logged as taking 12159.162 ms)

Depending on the application, a transaction lasting 20 seconds or
more might not be unreasonable (or it might indeed be unreasonable,
yet still happening).  But Marc will have to investigate to see
what's really going on; I simply offer one possible explanation.

--
Michael Fuhr