pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedexplain analyze reports 20x more time than actual
2+ messages / 2 participants
[nested] [flat]
* explain analyze reports 20x more time than actual
@ 2006-06-30 04:52 Craig A. James <cjames@modgraph-usa.com>
2006-06-30 06:04 ` Re: explain analyze reports 20x more time than actual Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 2+ messages in thread
From: Craig A. James @ 2006-06-30 04:52 UTC (permalink / raw)
To: pgsql-performance
I have a query that needs to run faster, with the obvious solution being to add an index. But to confirm this, I ran explain analyze. When I run the actual query, it consistently takes 6-7 seconds by the wall clock. My application with a "verbose" mode enabled reports 6.6 seconds consistently. However, when I run EXPLAIN ANALYZE, it takes 120 seconds! This is 20x longer, and it leads me to distrust the plan that it claims to be executing. How can the actual run time be so much faster than that claimed by EXPLAIN ANALYZE? How can I find out the actual plan it's using?
Thanks,
Craig
Details:
Postgres 8.0.3
shared_buffers = 20000
work_mem = 500000
effective_cache_size = 430000
Dell w/ Xeon
Linux kernel 2.6.9-1.667smp
4 GB memory
=> explain analyze select SAMPLE.SAMPLE_ID, SAMPLE.VERSION_ID,SAMPLE.SUPPLIER_ID,SAMPLE.CATALOGUE_ID,SAMPLE.PREP_ID from HITLIST_ROWS_281430 join SAMPLE on (HITLIST_ROWS_281430.OBJECTID = SAMPLE.SAMPLE_ID) where SAMPLE.VERSION_ID in (7513672,7513650,7513634,7513620,7513592,7513590,7513582,7513576,7513562,7513560) order by HITLIST_ROWS_281430.SortOrder;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=234964.38..234964.52 rows=58 width=24) (actual time=120510.842..120510.889 rows=10 loops=1)
Sort Key: hitlist_rows_281430.sortorder
-> Hash Join (cost=353.68..234962.68 rows=58 width=24) (actual time=81433.194..120510.753 rows=10 loops=1)
Hash Cond: ("outer".objectid = "inner".sample_id)
-> Seq Scan on hitlist_rows_281430 (cost=0.00..177121.61 rows=11497361 width=8) (actual time=0.008..64434.110 rows=11497361 loops=1)
-> Hash (cost=353.48..353.48 rows=82 width=20) (actual time=0.293..0.293 rows=0 loops=1)
-> Index Scan using i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id on sample (cost=0.00..353.48 rows=82 width=20) (actual time=0.042..0.201 rows=12 loops=1)
Index Cond: ((version_id = 7513672) OR (version_id = 7513650) OR (version_id = 7513634) OR (version_id = 7513620) OR (version_id = 7513592) OR (version_id = 7513590) OR (version_id = 7513582) OR (version_id = 7513576) OR (version_id = 7513562) OR (version_id = 7513560))
Total runtime: 120511.485 ms
(9 rows)
^ permalink raw reply [nested|flat] 2+ messages in thread
* Re: explain analyze reports 20x more time than actual
2006-06-30 04:52 explain analyze reports 20x more time than actual Craig A. James <cjames@modgraph-usa.com>
@ 2006-06-30 06:04 ` Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 0 replies; 2+ messages in thread
From: Tom Lane @ 2006-06-30 06:04 UTC (permalink / raw)
To: Craig A. James <cjames@modgraph-usa.com>; +Cc: pgsql-performance
"Craig A. James" <cjames@modgraph-usa.com> writes:
> I have a query that needs to run faster, with the obvious solution
> being to add an index. But to confirm this, I ran explain analyze.
> When I run the actual query, it consistently takes 6-7 seconds by the
> wall clock. My application with a "verbose" mode enabled reports 6.6
> seconds consistently. However, when I run EXPLAIN ANALYZE, it takes
> 120 seconds!
See recent discussions --- if you've got duff PC hardware, it seems that
reading the clock takes forever :-(. In this case I'd assume that the
cost of the seqscan (11497361 rows returned) is being overstated because
of the 2*11497361 gettimeofday calls involved.
regards, tom lane
^ permalink raw reply [nested|flat] 2+ messages in thread
end of thread, other threads:[~2006-06-30 06:04 UTC | newest]
Thread overview: 2+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2006-06-30 04:52 explain analyze reports 20x more time than actual Craig A. James <cjames@modgraph-usa.com>
2006-06-30 06:04 ` Tom Lane <tgl@sss.pgh.pa.us>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox