Обсуждение: EXPLAIN ANALYZE total runtime != walltime
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/
***-*--*----*-------*------------*--------------------*---------------
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?
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