EXPLAIN ANALYZE total runtime != walltime

[Jon Lapham]

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 <la****@jandr.org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------
---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster

[Stephan Szabo]

On Wed, 25 Aug 2004, Jon Lapham wrote:

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.

I think EXPLAIN ANALYZE time doesn't include after trigger time (for
example for foreign keys). Do any tables reference this one?

---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command
(send "unregister YourEmailAddressHere" to ma*******@postgresql.org)

[Tom Lane]

Jon Lapham <la****@jandr.org> writes:

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

I think that the foreign-key-checking triggers that are fired by the
DELETE will execute at end of statement, which is outside the time
window measured and reported by EXPLAIN ANALYZE. Better look at your FK
setup. The usual culprit for slow DELETE is an unindexed referencing
column in another table, but it could also be that the referencing
column is not the same datatype as the key column.

regards, tom lane

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

[Jon Lapham]

Tom Lane wrote:

Jon Lapham <la****@jandr.org> writes:

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

I think that the foreign-key-checking triggers that are fired by the
DELETE will execute at end of statement, which is outside the time
window measured and reported by EXPLAIN ANALYZE. Better look at your FK
setup. The usual culprit for slow DELETE is an unindexed referencing
column in another table, but it could also be that the referencing
column is not the same datatype as the key column.

Yup, you are right, I have another table that has a FK reference to the
table I am deleting. I'll look into improving performance by indexing
the referencing column.

Is there some way to get at something equvalent to UNIX's "time" command
for benchmarking purposes?

Was there something in the output of EXPLAIN ANALYZE VERBOSE that let
you to conclude that the timing difference was due to a FK referencing
this table?

I want to learn how you guys figure this stuff out...

Should something be mentioned in the docs about foreign-key-checking
triggers not being included in the total runtime of EXPLAIN ANALYZE? I
just checked (the 7.4.2 docs, anyway) and there is no mention of this.

Thanks for the help!
Jon

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <la****@jandr.org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------
---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?

http://archives.postgresql.org

[Jon Lapham]

Stephan Szabo wrote:

On Wed, 25 Aug 2004, Jon Lapham wrote:

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.

I think EXPLAIN ANALYZE time doesn't include after trigger time (for
example for foreign keys). Do any tables reference this one?

Yup, I have a referencing table, that is indeed the performance problem.
I'm just surprised that the "total runtime" is not the.. well... total
runtime. :)

Thanks,
Jon

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <la****@jandr.org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------
---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster

[Tom Lane]

Jon Lapham <la****@jandr.org> writes:

Was there something in the output of EXPLAIN ANALYZE VERBOSE that let
you to conclude that the timing difference was due to a FK referencing
this table?
No, just general knowledge of what sorts of things could possibly happen
outside the execution of the "statement proper". EXPLAIN ANALYZE's
report of total runtime is honest as far as it goes, but it doesn't
include transaction startup and shutdown because those happen before and
after the EXPLAIN code gets to run. Normally those are quick enough,
but end-of-statement triggers are a common reason for shutdown not to be
quick. So it was an educated guess...
Should something be mentioned in the docs about foreign-key-checking
triggers not being included in the total runtime of EXPLAIN ANALYZE?

Feel free to send in a docs patch with suggested wording. I think we
already do mention that planning time isn't accounted for (that part
happens before EXPLAIN starts...) and somewhere right around there would
likely be a good spot.

regards, tom lane

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