pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedQuery taking too long. Problem reading explain output.
8+ messages / 5 participants
[nested] [flat]
* Query taking too long. Problem reading explain output.
@ 2007-10-03 08:03 Henrik <henke@mac.se>
2007-10-03 13:31 ` Re: Query taking too long. Problem reading explain output. Michael Fuhr <mike@fuhr.org>
2007-10-03 14:15 ` Re: Query taking too long. Problem reading explain output. Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 2 replies; 8+ messages in thread
From: Henrik @ 2007-10-03 08:03 UTC (permalink / raw)
To: pgsql-performance
Hello list,
I have a little query that takes too long and what I can see in the
explain output is a seq scan on my biggest table
( tbl_file_structure) which I can't explain why.
Here is the output. I hope this is formatted correctly. If not, let
me know and I'll paste it somewhere.
Postgres version is 8.2.4 running on a Linux system with 2GB RAM and
a Core 2 Duo processor.
HashAggregate (cost=418833.59..418833.63 rows=4 width=127) (actual
time=16331.326..16331.449 rows=160 loops=1)
-> Hash Left Join (cost=16290.37..418833.51 rows=4 width=127)
(actual time=4386.574..16330.727 rows=160 loops=1)
Hash Cond: (tbl_job.fk_job_group_id =
tbl_job_group.pk_job_group_id)
Filter: ((tbl_job_group.job_group_type = 'B'::bpchar) OR
(tbl_job_group.job_group_type IS NULL))
-> Merge Join (cost=16285.22..418828.08 rows=17
width=135) (actual time=4386.474..16330.253 rows=160 loops=1)
Merge Cond: (tbl_computer.pk_computer_id =
tbl_share.fk_computer_id)
-> Nested Loop (cost=16268.52..418810.55 rows=216
width=122) (actual time=4386.324..16329.638 rows=160 loops=1)
-> Index Scan using tbl_computer_pkey on
tbl_computer (cost=0.00..12.48 rows=1 width=20) (actual
time=0.013..0.024 rows=1 loops=1)
Filter: ((computer_name)::text =
'SOLARIS2'::text)
-> Hash Join (cost=16268.52..418795.91
rows=216 width=102) (actual time=4386.307..16329.425 rows=160 loops=1)
Hash Cond: (tbl_file.fk_filetype_id =
tbl_filetype.pk_filetype_id)
-> Hash Join (cost=16267.03..418791.44
rows=216 width=100) (actual time=4386.268..16329.119 rows=160 loops=1)
Hash Cond:
(tbl_file_structure.fk_structure_id = tbl_structure.pk_structure_id)
-> Hash Join
(cost=8605.68..410913.87 rows=19028 width=40) (actual
time=22.810..16196.414 rows=17926 loops=1)
Hash Cond:
(tbl_file_structure.fk_file_id = tbl_file.pk_file_id)
-> Seq Scan on
tbl_file_structure (cost=0.00..319157.94 rows=16591994 width=16)
(actual time=0.016..7979.083 rows=16591994 loops=1)
-> Hash
(cost=8573.62..8573.62 rows=2565 width=40) (actual
time=22.529..22.529 rows=2221 loops=1)
-> Bitmap Heap Scan on
tbl_file (cost=74.93..8573.62 rows=2565 width=40) (actual
time=1.597..20.691 rows=2221 loops=1)
Filter: (lower
((file_name)::text) ~~ 'index.php%'::text)
-> Bitmap Index
Scan on tbl_file_idx (cost=0.00..74.28 rows=2565 width=0) (actual
time=1.118..1.118 rows=2221 loops=1)
Index Cond:
((lower((file_name)::text) ~>=~ 'index.php'::character varying) AND
(lower((file_name)::text) ~<~ 'index.phq'::character varying))
-> Hash (cost=7487.57..7487.57
rows=13902 width=76) (actual time=100.905..100.905 rows=24571 loops=1)
-> Index Scan using
tbl_structure_idx3 on tbl_structure (cost=0.00..7487.57 rows=13902
width=76) (actual time=0.055..79.301 rows=24571 loops=1)
Index Cond:
(fk_archive_id = 56)
-> Hash (cost=1.22..1.22 rows=22
width=18) (actual time=0.032..0.032 rows=22 loops=1)
-> Seq Scan on tbl_filetype
(cost=0.00..1.22 rows=22 width=18) (actual time=0.004..0.016 rows=22
loops=1)
-> Sort (cost=16.70..16.70 rows=1 width=37) (actual
time=0.144..0.239 rows=1 loops=1)
Sort Key: tbl_share.fk_computer_id
-> Nested Loop (cost=4.26..16.69 rows=1
width=37) (actual time=0.072..0.115 rows=1 loops=1)
Join Filter: (tbl_share.pk_share_id =
tbl_archive.fk_share_id)
-> Nested Loop Left Join
(cost=4.26..15.42 rows=1 width=24) (actual time=0.055..0.097 rows=1
loops=1)
Join Filter: (tbl_archive.fk_job_id
= tbl_job.pk_job_id)
-> Bitmap Heap Scan on
tbl_archive (cost=4.26..8.27 rows=1 width=24) (actual
time=0.033..0.033 rows=1 loops=1)
Recheck Cond: (56 =
pk_archive_id)
Filter: archive_complete
-> Bitmap Index Scan on
tbl_archive_pkey (cost=0.00..4.26 rows=1 width=0) (actual
time=0.026..0.026 rows=1 loops=1)
Index Cond: (56 =
pk_archive_id)
-> Seq Scan on tbl_job
(cost=0.00..6.51 rows=51 width=16) (actual time=0.003..0.033 rows=51
loops=1)
-> Seq Scan on tbl_share
(cost=0.00..1.12 rows=12 width=29) (actual time=0.003..0.008 rows=12
loops=1)
-> Hash (cost=4.51..4.51 rows=51 width=13) (actual
time=0.084..0.084 rows=51 loops=1)
-> Seq Scan on tbl_job_group (cost=0.00..4.51
rows=51 width=13) (actual time=0.006..0.046 rows=51 loops=1)
Total runtime: 16331.890 ms
(42 rows)
Here is the query if needed.
explain analyze SELECT file_name FROM tbl_file_structure JOIN
tbl_file ON pk_file_id = fk_file_id JOIN tbl_structure ON
pk_structure_id = fk_structure_id JOIN tbl_archive ON pk_archive_id
=fk_archive_id JOIN tbl_share ON pk_share_id =fk_share_id JOIN
tbl_computer ON pk_computer_id = fk_computer_id JOIN tbl_filetype ON
pk_filetype_id = fk_filetype_id LEFT OUTER JOIN tbl_job ON
tbl_archive.fk_job_id = pk_job_id LEFT OUTER JOIN tbl_job_group ON
tbl_job.fk_job_group_id = pk_job_group_id WHERE LOWER(file_name) LIKE
LOWER('index.php%') AND (computer_name = 'SOLARIS2') AND
(fk_archive_id = 56) AND archive_complete = true AND (job_group_type
= 'B' OR job_group_type IS NULL) GROUP BY file_name, file_ctime,
structure_path, pk_computer_id, filetype_icon, computer_name,
share_name, share_path;
Thanks,
Henrik
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Query taking too long. Problem reading explain output.
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
@ 2007-10-03 13:31 ` Michael Fuhr <mike@fuhr.org>
1 sibling, 0 replies; 8+ messages in thread
From: Michael Fuhr @ 2007-10-03 13:31 UTC (permalink / raw)
To: Henrik <henke@mac.se>; +Cc: pgsql-performance
On Wed, Oct 03, 2007 at 10:03:53AM +0200, Henrik wrote:
> I have a little query that takes too long and what I can see in the
> explain output is a seq scan on my biggest table ( tbl_file_structure)
> which I can't explain why.
Here's where almost all of the time is taken:
> Hash Join (cost=8605.68..410913.87 rows=19028 width=40) (actual time=22.810..16196.414 rows=17926 loops=1)
> Hash Cond: (tbl_file_structure.fk_file_id = tbl_file.pk_file_id)
> -> Seq Scan on tbl_file_structure (cost=0.00..319157.94 rows=16591994 width=16) (actual time=0.016..7979.083 rows=16591994 loops=1)
> -> Hash (cost=8573.62..8573.62 rows=2565 width=40) (actual time=22.529..22.529 rows=2221 loops=1)
> -> Bitmap Heap Scan on tbl_file (cost=74.93..8573.62 rows=2565 width=40) (actual time=1.597..20.691 rows=2221 loops=1)
> Filter: (lower((file_name)::text) ~~ 'index.php%'::text)
> -> Bitmap Index Scan on tbl_file_idx (cost=0.00..74.28 rows=2565 width=0) (actual time=1.118..1.118 rows=2221 loops=1)
> Index Cond: ((lower((file_name)::text) ~>=~ 'index.php'::character varying) AND (lower((file_name)::text) ~<~ 'index.phq'::character varying))
Does tbl_file_structure have an index on fk_file_id? If so then
what's the EXPLAIN ANALYZE output if you set enable_seqscan to off?
I don't recommend disabling sequential scans permanently but doing
so can be useful when investigating why the planner thinks one plan
will be faster than another.
What are your settings for random_page_cost, effective_cache_size,
work_mem, and shared_buffers? If you're using the default
random_page_cost of 4 then what's the EXPLAIN ANALYZE output if you
reduce it to 3 or 2 (after setting enable_seqscan back to on)?
--
Michael Fuhr
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Query taking too long. Problem reading explain output.
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
@ 2007-10-03 14:15 ` Tom Lane <tgl@sss.pgh.pa.us>
2007-10-04 10:15 ` Re: Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
1 sibling, 1 reply; 8+ messages in thread
From: Tom Lane @ 2007-10-03 14:15 UTC (permalink / raw)
To: Henrik <henke@mac.se>; +Cc: pgsql-performance
Henrik <henke@mac.se> writes:
> Here is the query if needed.
> explain analyze SELECT file_name FROM tbl_file_structure JOIN
> tbl_file ON pk_file_id = fk_file_id JOIN tbl_structure ON
> pk_structure_id = fk_structure_id JOIN tbl_archive ON pk_archive_id
> =fk_archive_id JOIN tbl_share ON pk_share_id =fk_share_id JOIN
> tbl_computer ON pk_computer_id = fk_computer_id JOIN tbl_filetype ON
> pk_filetype_id = fk_filetype_id LEFT OUTER JOIN tbl_job ON
> tbl_archive.fk_job_id = pk_job_id LEFT OUTER JOIN tbl_job_group ON
> tbl_job.fk_job_group_id = pk_job_group_id WHERE LOWER(file_name) LIKE
> LOWER('index.php%') AND (computer_name = 'SOLARIS2') AND
> (fk_archive_id = 56) AND archive_complete = true AND (job_group_type
> = 'B' OR job_group_type IS NULL) GROUP BY file_name, file_ctime,
> structure_path, pk_computer_id, filetype_icon, computer_name,
> share_name, share_path;
[ counts the JOINs... ] Try raising join_collapse_limit. I think the
planner may be neglecting to consider the join order you need.
regards, tom lane
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Query taking too long. Problem reading explain output.
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-03 14:15 ` Re: Query taking too long. Problem reading explain output. Tom Lane <tgl@sss.pgh.pa.us>
@ 2007-10-04 10:15 ` Henrik <henke@mac.se>
2007-10-04 12:30 ` Re: Query taking too long. Problem reading explain output. Alvaro Herrera <alvherre@commandprompt.com>
0 siblings, 1 reply; 8+ messages in thread
From: Henrik @ 2007-10-04 10:15 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
3 okt 2007 kl. 16:15 skrev Tom Lane:
> Henrik <henke@mac.se> writes:
>> Here is the query if needed.
>> explain analyze SELECT file_name FROM tbl_file_structure JOIN
>> tbl_file ON pk_file_id = fk_file_id JOIN tbl_structure ON
>> pk_structure_id = fk_structure_id JOIN tbl_archive ON pk_archive_id
>> =fk_archive_id JOIN tbl_share ON pk_share_id =fk_share_id JOIN
>> tbl_computer ON pk_computer_id = fk_computer_id JOIN tbl_filetype ON
>> pk_filetype_id = fk_filetype_id LEFT OUTER JOIN tbl_job ON
>> tbl_archive.fk_job_id = pk_job_id LEFT OUTER JOIN tbl_job_group ON
>> tbl_job.fk_job_group_id = pk_job_group_id WHERE LOWER(file_name) LIKE
>> LOWER('index.php%') AND (computer_name = 'SOLARIS2') AND
>> (fk_archive_id = 56) AND archive_complete = true AND (job_group_type
>> = 'B' OR job_group_type IS NULL) GROUP BY file_name, file_ctime,
>> structure_path, pk_computer_id, filetype_icon, computer_name,
>> share_name, share_path;
>
> [ counts the JOINs... ] Try raising join_collapse_limit. I think the
> planner may be neglecting to consider the join order you need.
>
> regards, tom lane
Hi,
Ahh I had exactly 8 joins.
Following your suggestion I raised the join_collapse_limit from 8 to
10 and the planners decision sure changed but now I have some crazy
nested loops. Maybe I have some statistics wrong?
Same query this is the new explain analyze:
HashAggregate (cost=48.40..48.41 rows=1 width=127) (actual
time=22898.513..22898.613 rows=160 loops=1)
-> Nested Loop Left Join (cost=2.60..48.38 rows=1 width=127)
(actual time=10.984..22897.964 rows=160 loops=1)
Filter: ((tbl_job_group.job_group_type = 'B'::bpchar) OR
(tbl_job_group.job_group_type IS NULL))
-> Nested Loop Left Join (cost=2.60..43.94 rows=1
width=135) (actual time=10.976..22896.856 rows=160 loops=1)
Join Filter: (tbl_archive.fk_job_id = tbl_job.pk_job_id)
-> Nested Loop (cost=2.60..36.79 rows=1 width=135)
(actual time=10.955..22887.675 rows=160 loops=1)
Join Filter: (tbl_share.pk_share_id =
tbl_archive.fk_share_id)
-> Nested Loop (cost=0.01..30.18 rows=1
width=143) (actual time=10.941..22885.841 rows=160 loops=1)
Join Filter: (tbl_computer.pk_computer_id
= tbl_share.fk_computer_id)
-> Nested Loop (cost=0.01..28.91 rows=1
width=122) (actual time=10.925..22883.458 rows=160 loops=1)
-> Nested Loop (cost=0.01..26.73
rows=1 width=102) (actual time=10.915..22881.411 rows=160 loops=1)
-> Nested Loop
(cost=0.01..20.45 rows=1 width=41) (actual time=0.107..10693.572
rows=20166 loops=1)
-> Nested Loop
(cost=0.01..10.15 rows=1 width=41) (actual time=0.080..986.100
rows=2223 loops=1)
Join Filter:
(tbl_filetype.pk_filetype_id = tbl_file.fk_filetype_id)
-> Index Scan
using tbl_file_idx on tbl_file (cost=0.01..8.66 rows=1 width=39)
(actual time=0.057..931.546 rows=2223 loops=1)
Index Cond:
((lower((file_name)::text) ~>=~ 'index.php'::character varying) AND
(lower((file_name)::text) ~<~ 'index.phq'::character varying))
Filter:
(lower((file_name)::text) ~~ 'index.php%'::text)
-> Seq Scan on
tbl_filetype (cost=0.00..1.22 rows=22 width=18) (actual
time=0.002..0.011 rows=22 loops=2223)
-> Index Scan using
tbl_file_structure_idx on tbl_file_structure (cost=0.00..10.29
rows=1 width=16) (actual time=0.722..4.356 rows=9 loops=2223)
Index Cond:
(tbl_file.pk_file_id = tbl_file_structure.fk_file_id)
-> Index Scan using
tbl_structure_pkey on tbl_structure (cost=0.00..6.27 rows=1
width=77) (actual time=0.603..0.603 rows=0 loops=20166)
Index Cond:
(tbl_structure.pk_structure_id = tbl_file_structure.fk_structure_id)
Filter: (fk_archive_id
= 56)
-> Seq Scan on tbl_computer
(cost=0.00..2.16 rows=1 width=20) (actual time=0.004..0.010 rows=1
loops=160)
Filter:
((computer_name)::text = 'SOLARIS2'::text)
-> Seq Scan on tbl_share
(cost=0.00..1.12 rows=12 width=29) (actual time=0.002..0.007 rows=12
loops=160)
-> Bitmap Heap Scan on tbl_archive
(cost=2.59..6.60 rows=1 width=24) (actual time=0.007..0.008 rows=1
loops=160)
Recheck Cond: (56 = pk_archive_id)
Filter: archive_complete
-> Bitmap Index Scan on
tbl_archive_pkey (cost=0.00..2.59 rows=1 width=0) (actual
time=0.005..0.005 rows=1 loops=160)
Index Cond: (56 = pk_archive_id)
-> Seq Scan on tbl_job (cost=0.00..6.51 rows=51
width=16) (actual time=0.002..0.031 rows=51 loops=160)
-> Index Scan using tbl_job_group_pkey on tbl_job_group
(cost=0.00..4.42 rows=1 width=13) (actual time=0.003..0.004 rows=1
loops=160)
Index Cond: (tbl_job.fk_job_group_id =
tbl_job_group.pk_job_group_id)
Total runtime: 22898.840 ms
Thanks,
Henrik
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Query taking too long. Problem reading explain output.
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-03 14:15 ` Re: Query taking too long. Problem reading explain output. Tom Lane <tgl@sss.pgh.pa.us>
2007-10-04 10:15 ` Re: Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
@ 2007-10-04 12:30 ` Alvaro Herrera <alvherre@commandprompt.com>
2007-10-04 21:15 ` Re: Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-11 03:16 ` Re: Query taking too long. Problem reading explain output. Ow Mun Heng <Ow.Mun.Heng@wdc.com>
0 siblings, 2 replies; 8+ messages in thread
From: Alvaro Herrera @ 2007-10-04 12:30 UTC (permalink / raw)
To: Henrik <henke@mac.se>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-performance
Henrik wrote:
> Ahh I had exactly 8 joins.
> Following your suggestion I raised the join_collapse_limit from 8 to 10 and
> the planners decision sure changed but now I have some crazy nested loops.
> Maybe I have some statistics wrong?
Yeah. The problematic misestimation is exactly the innermost indexscan,
which is wrong by two orders of magnitude:
> -> Index Scan using
> tbl_file_idx on tbl_file (cost=0.01..8.66 rows=1 width=39) (actual
> time=0.057..931.546 rows=2223 loops=1)
> Index Cond:
> ((lower((file_name)::text) ~>=~ 'index.php'::character varying) AND
> (lower((file_name)::text) ~<~ 'index.phq'::character varying))
> Filter:
> (lower((file_name)::text) ~~ 'index.php%'::text)
This wreaks havoc on the rest of the plan. If this weren't
misestimated, it wouldn't be using those nested loops.
--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Query taking too long. Problem reading explain output.
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-03 14:15 ` Re: Query taking too long. Problem reading explain output. Tom Lane <tgl@sss.pgh.pa.us>
2007-10-04 10:15 ` Re: Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-04 12:30 ` Re: Query taking too long. Problem reading explain output. Alvaro Herrera <alvherre@commandprompt.com>
@ 2007-10-04 21:15 ` Henrik <henke@mac.se>
2007-10-04 23:43 ` Re: Query taking too long. Problem reading explain output. Alvaro Herrera <alvherre@commandprompt.com>
1 sibling, 1 reply; 8+ messages in thread
From: Henrik @ 2007-10-04 21:15 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-performance
4 okt 2007 kl. 14:30 skrev Alvaro Herrera:
> Henrik wrote:
>
>> Ahh I had exactly 8 joins.
>> Following your suggestion I raised the join_collapse_limit from 8
>> to 10 and
>> the planners decision sure changed but now I have some crazy
>> nested loops.
>> Maybe I have some statistics wrong?
>
> Yeah. The problematic misestimation is exactly the innermost
> indexscan,
> which is wrong by two orders of magnitude:
>
>> -> Index Scan
>> using
>> tbl_file_idx on tbl_file (cost=0.01..8.66 rows=1 width=39) (actual
>> time=0.057..931.546 rows=2223 loops=1)
>> Index Cond:
>> ((lower((file_name)::text) ~>=~ 'index.php'::character varying) AND
>> (lower((file_name)::text) ~<~ 'index.phq'::character varying))
>> Filter:
>> (lower((file_name)::text) ~~ 'index.php%'::text)
>
> This wreaks havoc on the rest of the plan. If this weren't
> misestimated, it wouldn't be using those nested loops.
>
Correct. I changed the statistics to 500 in tbl_file.file_name and
now the statistics is better. But now my big seq scan on
tbl_file_Structure back and I don't know why.
Pasting new explain analyze:
HashAggregate (cost=467442.44..467442.47 rows=3 width=127) (actual
time=25182.056..25182.169 rows=160 loops=1)
-> Hash Join (cost=16106.29..467442.38 rows=3 width=127)
(actual time=7825.803..25181.394 rows=160 loops=1)
Hash Cond: (tbl_file.fk_filetype_id =
tbl_filetype.pk_filetype_id)
-> Hash Join (cost=16079.94..467413.50 rows=184
width=100) (actual time=7793.171..25148.405 rows=160 loops=1)
Hash Cond: (tbl_file_structure.fk_structure_id =
tbl_structure.pk_structure_id)
-> Hash Join (cost=7295.70..458431.45 rows=17419
width=39) (actual time=619.779..23034.828 rows=20166 loops=1)
Hash Cond: (tbl_file_structure.fk_file_id =
tbl_file.pk_file_id)
-> Seq Scan on tbl_file_structure
(cost=0.00..357539.04 rows=18684504 width=16) (actual
time=5.648..12906.913 rows=18684505 loops=1)
-> Hash (cost=7269.04..7269.04 rows=2133
width=39) (actual time=613.852..613.852 rows=2223 loops=1)
-> Bitmap Heap Scan on tbl_file
(cost=62.50..7269.04 rows=2133 width=39) (actual time=14.672..611.803
rows=2223 loops=1)
Filter: (lower((file_name)::text)
~~ 'index.php%'::text)
-> Bitmap Index Scan on
tbl_file_idx (cost=0.00..61.97 rows=2133 width=0) (actual
time=14.205..14.205 rows=2223 loops=1)
Index Cond: ((lower
((file_name)::text) ~>=~ 'index.php'::character varying) AND (lower
((file_name)::text) ~<~ 'index.phq'::character varying))
-> Hash (cost=8601.81..8601.81 rows=14595 width=77)
(actual time=2076.717..2076.717 rows=24571 loops=1)
-> Index Scan using tbl_structure_idx3 on
tbl_structure (cost=0.00..8601.81 rows=14595 width=77) (actual
time=58.620..2050.555 rows=24571 loops=1)
Index Cond: (fk_archive_id = 56)
-> Hash (cost=26.08..26.08 rows=22 width=59) (actual
time=32.624..32.624 rows=22 loops=1)
-> Nested Loop (cost=2.59..26.08 rows=22 width=59)
(actual time=32.503..32.598 rows=22 loops=1)
-> Nested Loop Left Join (cost=2.59..24.64
rows=1 width=41) (actual time=32.332..32.384 rows=1 loops=1)
Filter: ((tbl_job_group.job_group_type =
'B'::bpchar) OR (tbl_job_group.job_group_type IS NULL))
-> Nested Loop Left Join
(cost=2.59..20.20 rows=1 width=49) (actual time=27.919..27.969 rows=1
loops=1)
Join Filter: (tbl_archive.fk_job_id
= tbl_job.pk_job_id)
-> Nested Loop (cost=2.59..13.05
rows=1 width=49) (actual time=27.897..27.904 rows=1 loops=1)
Join Filter:
(tbl_share.pk_share_id = tbl_archive.fk_share_id)
-> Nested Loop
(cost=0.00..6.43 rows=1 width=41) (actual time=19.638..19.642 rows=1
loops=1)
Join Filter:
(tbl_computer.pk_computer_id = tbl_share.fk_computer_id)
-> Seq Scan on
tbl_computer (cost=0.00..5.16 rows=1 width=20) (actual
time=19.611..19.614 rows=1 loops=1)
Filter:
((computer_name)::text = 'SOLARIS2'::text)
-> Seq Scan on
tbl_share (cost=0.00..1.12 rows=12 width=29) (actual
time=0.011..0.021 rows=12 loops=1)
-> Bitmap Heap Scan on
tbl_archive (cost=2.59..6.60 rows=1 width=24) (actual
time=8.255..8.255 rows=1 loops=1)
Recheck Cond: (56 =
pk_archive_id)
Filter: archive_complete
-> Bitmap Index Scan
on tbl_archive_pkey (cost=0.00..2.59 rows=1 width=0) (actual
time=8.250..8.250 rows=1 loops=1)
Index Cond: (56 =
pk_archive_id)
-> Seq Scan on tbl_job
(cost=0.00..6.51 rows=51 width=16) (actual time=0.003..0.034 rows=51
loops=1)
-> Index Scan using tbl_job_group_pkey
on tbl_job_group (cost=0.00..4.42 rows=1 width=13) (actual
time=4.408..4.410 rows=1 loops=1)
Index Cond:
(tbl_job.fk_job_group_id = tbl_job_group.pk_job_group_id)
-> Seq Scan on tbl_filetype (cost=0.00..1.22
rows=22 width=18) (actual time=0.169..0.178 rows=22 loops=1)
Total runtime: 25182.626 ms
Thanks.,
Henrik
> --
> Alvaro Herrera http://
> www.CommandPrompt.com/
> PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Query taking too long. Problem reading explain output.
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-03 14:15 ` Re: Query taking too long. Problem reading explain output. Tom Lane <tgl@sss.pgh.pa.us>
2007-10-04 10:15 ` Re: Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-04 12:30 ` Re: Query taking too long. Problem reading explain output. Alvaro Herrera <alvherre@commandprompt.com>
2007-10-04 21:15 ` Re: Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
@ 2007-10-04 23:43 ` Alvaro Herrera <alvherre@commandprompt.com>
0 siblings, 0 replies; 8+ messages in thread
From: Alvaro Herrera @ 2007-10-04 23:43 UTC (permalink / raw)
To: Henrik <henke@mac.se>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-performance
Henrik wrote:
> Correct. I changed the statistics to 500 in tbl_file.file_name and now the
> statistics is better. But now my big seq scan on tbl_file_Structure back
> and I don't know why.
Hmm, I think the problem here is that it needs to fetch ~200000 tuples
from tbl_file_structure one way or the other. When it misestimated the
tuples from tbl_file it thought it would only need to do the indexscan
in tbl_file_structure a few times, but now it realizes that it needs to
do it several thousands of times and it considers the seqscan to be
cheaper.
Perhaps you would benefit from a higher effective_cache_size or a lower
random_page_cost (or both).
I think this is a problem in the optimizer: it doesn't correctly take
into account the fact that the upper pages of the index are most likely
to be cached. This has been discussed a lot of times but it's not a
simple problem to fix.
--
Alvaro Herrera http://www.amazon.com/gp/registry/CTMLCN8V17R4
Este mail se entrega garantizadamente 100% libre de sarcasmo.
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Query taking too long. Problem reading explain output.
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-03 14:15 ` Re: Query taking too long. Problem reading explain output. Tom Lane <tgl@sss.pgh.pa.us>
2007-10-04 10:15 ` Re: Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-04 12:30 ` Re: Query taking too long. Problem reading explain output. Alvaro Herrera <alvherre@commandprompt.com>
@ 2007-10-11 03:16 ` Ow Mun Heng <Ow.Mun.Heng@wdc.com>
1 sibling, 0 replies; 8+ messages in thread
From: Ow Mun Heng @ 2007-10-11 03:16 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: Henrik <henke@mac.se>; Tom Lane <tgl@sss.pgh.pa.us>; pgsql-performance
On Thu, 2007-10-04 at 08:30 -0400, Alvaro Herrera wrote:
> Henrik wrote:
>
> > Ahh I had exactly 8 joins.
> > Following your suggestion I raised the join_collapse_limit from 8 to 10 and
> > the planners decision sure changed but now I have some crazy nested loops.
> > Maybe I have some statistics wrong?
>
> Yeah. The problematic misestimation is exactly the innermost indexscan,
> which is wrong by two orders of magnitude:
Nested Loops are evil.. and I've no clue on why PG has such big
mis-estimates. Mine are like 1:500
I've solved mine using SRFs
^ permalink raw reply [nested|flat] 8+ messages in thread
end of thread, other threads:[~2007-10-11 03:16 UTC | newest]
Thread overview: 8+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2007-10-03 08:03 Query taking too long. Problem reading explain output. Henrik <henke@mac.se>
2007-10-03 13:31 ` Michael Fuhr <mike@fuhr.org>
2007-10-03 14:15 ` Tom Lane <tgl@sss.pgh.pa.us>
2007-10-04 10:15 ` Henrik <henke@mac.se>
2007-10-04 12:30 ` Alvaro Herrera <alvherre@commandprompt.com>
2007-10-04 21:15 ` Henrik <henke@mac.se>
2007-10-04 23:43 ` Alvaro Herrera <alvherre@commandprompt.com>
2007-10-11 03:16 ` Ow Mun Heng <Ow.Mun.Heng@wdc.com>
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