Thread: Query taking too long. Problem reading explain output.
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
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=16591994loops=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=2221loops=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=2221loops=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
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
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
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
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
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.
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