Re: EXPLAIN ANALYZE total runtime != walltime

Jon Lapham <lapham@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

Tom Lane wrote:

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

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 <lapham@jandr.org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------

Jon Lapham <lapham@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