Обсуждение: 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