Re: Incorrect Total runtime Reported by Explain Analyze!?

Very good points thanks. In my case however, I was doing performance
tests and therefore I had a very controlled environment with a single
client (me) doing strictly read-only multi-join queries.

-----Original Message-----
From: Michael Fuhr [mailto:mike@fuhr.org]
Sent: Thursday, January 26, 2006 11:57 AM
To: Richard Huxton
Cc: Jozsef Szalay; pgsql-performance@postgresql.org
Subject: Re: [PERFORM] Incorrect Total runtime Reported by Explain
Analyze!?

On Thu, Jan 26, 2006 at 04:49:59PM +0000, Richard Huxton wrote:
> Jozsef Szalay wrote:
> >I have seen it on occasion that the total runtime reported by explain
> >analyze was much higher than the actual time the query needed to
> >complete. The differences in my case ranged between 20-120 seconds.
I'm
> >just curious if anyone else has experienced this and whether there is
> >something that I can do to convince explain analyze to report the
> >execution time of the query itself rather than the time of its own
> >execution. Engine version is 8.1.1.
>
> I think it's down to all the gettime() calls that have to be made to
> measure how long each stage of the query takes. In some cases these
can
> take a substantial part of the overall query time.

Another possibility is that the total query time was indeed that
long because the query was blocked waiting for a lock.  For example:

T1: BEGIN;
T2: BEGIN;
T1: SELECT * FROM foo WHERE id = 1 FOR UPDATE;
T2: EXPLAIN ANALYZE UPDATE foo SET x = x + 1 WHERE id = 1;
T1: (do something for a long time)
T1: COMMIT;

When T2's EXPLAIN ANALYZE finally returns it'll show something like
this:

test=> EXPLAIN ANALYZE UPDATE foo SET x = x + 1 WHERE id = 1;
                                                  QUERY PLAN

------------------------------------------------------------------------
---------------------------------------
 Index Scan using foo_pkey on foo  (cost=0.00..3.92 rows=1 width=14)
(actual time=0.123..0.138 rows=1 loops=1)
   Index Cond: (id = 1)
 Total runtime: 31926.304 ms
(3 rows)

SELECT queries can be blocked by operations that take an Access
Exclusive lock, such as CLUSTER, VACUUM FULL, or REINDEX.  Have you
ever examined pg_locks during one of these queries to look for
ungranted locks?

If this weren't 8.1 I'd ask if you had any triggers (including
foreign key constraints), whose execution time EXPLAIN ANALYZE
doesn't show in earlier versions.  For example:

8.1.2:
test=> EXPLAIN ANALYZE DELETE FROM foo WHERE id = 1;
                                                  QUERY PLAN

------------------------------------------------------------------------
--------------------------------------
 Index Scan using foo_pkey on foo  (cost=0.00..3.92 rows=1 width=6)
(actual time=0.136..0.154 rows=1 loops=1)
   Index Cond: (id = 1)
 Trigger for constraint bar_fooid_fkey: time=1538.054 calls=1
 Total runtime: 1539.732 ms
(4 rows)

8.0.6:
test=> EXPLAIN ANALYZE DELETE FROM foo WHERE id = 1;
                                                  QUERY PLAN

------------------------------------------------------------------------
--------------------------------------
 Index Scan using foo_pkey on foo  (cost=0.00..3.92 rows=1 width=6)
(actual time=0.124..0.147 rows=1 loops=1)
   Index Cond: (id = 1)
 Total runtime: 1746.173 ms
(3 rows)

--
Michael Fuhr