EXPLAIN ANALYZE total runtime != walltime - Mailing list pgsql-general

I have been using the EXPLAIN ANALYZE command to debug some performance
bottlenecks in my database.  In doing so, I have found an oddity (to me
anyway).  The "19ms" total runtime reported below actually takes 25
seconds on my computer (no other CPU intensive processes running).  Is
this normal for EXPLAIN ANALYZE to report a total runtime so vastly
different from wall clock time?

During the "explain ANALYZE delete from msgid;" the CPU is pegged at
100% for the postmaster process, and the HD light only flashes
intermittently, so I do not think it is HD I/O.

I tossed in a "EXPLAIN ANALYZE VERBOSE" at the end of this email, in
case that helps anyone.

Thanks for any help!
-Jon

translator=> SELECT version();
                                                              version



---------------------------------------------------------------------------------------------------------------------------------
  PostgreSQL 7.4.2 on i386-redhat-linux-gnu, compiled by GCC
i386-redhat-linux-gcc (GCC) 3.3.3 20040216 (Red Hat Linux 3.3.3-2.1)
(1 row)

translator=> VACUUM ANALYZE ;
WARNING:  skipping "pg_shadow" --- only table or database owner can
vacuum it
WARNING:  skipping "pg_database" --- only table or database owner can
vacuum it
WARNING:  skipping "pg_group" --- only table or database owner can vacuum it
VACUUM
translator=> BEGIN ;
BEGIN
translator=> explain ANALYZE delete from msgid;
                                              QUERY PLAN

-----------------------------------------------------------------------------------------------------
  Seq Scan on msgid  (cost=0.00..23.81 rows=981 width=6) (actual
time=0.029..10.151 rows=981 loops=1)
  Total runtime: 19.755 ms
(2 rows)
translator=> \d msgid
                                Table "public.msgid"
   Column   |     Type      |                       Modifiers

-----------+---------------+-------------------------------------------------------
  id        | integer       | not null default
nextval('public.msgid_id_seq'::text)
  projectid | integer       | not null
  msgid     | text          | not null
  msgidmd5  | character(32) | not null
Indexes:
     "msgid_pkey" primary key, btree (id)
Foreign-key constraints:
     "$1" FOREIGN KEY (projectid) REFERENCES projects(id) ON DELETE CASCADE
translator=> rollback;
ROLLBACK
translator=> explain ANALYZE VERBOSE delete from msgid;
                                              QUERY PLAN

----------------------------------------------------------------------------------------------------
     {SEQSCAN
     :startup_cost 0.00
     :total_cost 23.81
     :plan_rows 981
     :plan_width 6
     :targetlist (
        {TARGETENTRY
        :resdom
           {RESDOM
           :resno 1
           :restype 27
           :restypmod -1
           :resname ctid
           :ressortgroupref 0
           :resorigtbl 0
           :resorigcol 0
           :resjunk true
           }
        :expr
           {VAR
           :varno 1
           :varattno -1
           :vartype 27
           :vartypmod -1
           :varlevelsup 0
           :varnoold 1
           :varoattno -1
           }
        }
     )

     :qual <>
     :lefttree <>
     :righttree <>
     :initPlan <>
     :extParam ()

     :allParam ()

     :nParamExec 0
     :scanrelid 1
     }

  Seq Scan on msgid  (cost=0.00..23.81 rows=981 width=6) (actual
time=0.031..6.444 rows=981 loops=1)
  Total runtime: 35.760 ms
(46 rows)


--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
  Jon Lapham  <lapham@jandr.org>                Rio de Janeiro, Brasil
  Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------