Thread: performance; disk bad or something?
Hi,
There are some performance issues I am still confused over.
I've got a Linux box, raid1, 1GB memory
CPU-wise the server is mostly idle
PG 8.0.10,
shared_buffers = 10000
work_mem = 16348
maintenance_work_mem = 65536
Parameters are tweaked without much difference.
The following query is over a 12000 row table and apa_user is indexed.
I've recently vaccumed the db, analyze and recreated indexes on
apa_item_common.
So how on earth could this query take 10s to complete? Are my disks bad?
Are there other possible reasons?
If there were a couple of million rows I would still think it would run
way faster than this.
I cannot see odd messages in dmesg. It more or less started to act like
this over night.
Best regards,
Marcus
apa=> explain analyze
apa-> select
apa-> aic.objectid as aic_objectid
apa-> from
apa-> apa_item_common aic
apa-> where
apa-> aic.apa_user = 704 AND
apa-> aic.status = 30
apa-> ORDER BY aic.calc_rating desc
apa-> LIMIT 1000;
Limit (cost=5016.54..5019.04 rows=1000 width=8) (actual
time=9560.471..9562.201 rows=1000 loops=1)
-> Sort (cost=5016.54..5019.47 rows=1174 width=8) (actual
time=9560.469..9561.065 rows=1000 loops=1)
Sort Key: calc_rating
-> Index Scan using apa_item_common_x1 on apa_item_common aic
(cost=0.00..4956.68 rows=1174 width=8) (actual time=19.854..9557.606
rows=1226 loops=1)
Index Cond: (apa_user = 704)
Filter: (status = 30)
Total runtime: 9563.016 ms
(7 rows)
running the same query again, now it is cached then?
Limit (cost=5016.54..5019.04 rows=1000 width=8) (actual
time=7.261..9.016 rows=1000 loops=1)
-> Sort (cost=5016.54..5019.47 rows=1174 width=8) (actual
time=7.258..7.870 rows=1000 loops=1)
Sort Key: calc_rating
-> Index Scan using pond_item_common_x1 on pond_item_common
pic (cost=0.00..4956.68 rows=1174 width=8) (actual time=0.029..5.483
rows=1226 loops=1)
Index Cond: (pond_user = 704)
Filter: (status = 30)
Total runtime: 9.840 ms
(7 rows)
Marcus Engene <mengpg2@engene.se> writes:
> -> Index Scan using apa_item_common_x1 on apa_item_common aic
> (cost=0.00..4956.68 rows=1174 width=8) (actual time=19.854..9557.606
> rows=1226 loops=1)
If the table only has 12000 rows then it should never have used an index
scan here at all --- a plain seqscan is usually the best bet for
retrieving 10% of a table. Are you using nondefault planner settings?
How big is the table physically (VACUUM VERBOSE output about it might
tell something)?
regards, tom lane
Tom Lane skrev: > Marcus Engene <mengpg2@engene.se> writes: > >> -> Index Scan using apa_item_common_x1 on apa_item_common aic >> (cost=0.00..4956.68 rows=1174 width=8) (actual time=19.854..9557.606 >> rows=1226 loops=1) >> > > If the table only has 12000 rows then it should never have used an index > scan here at all --- a plain seqscan is usually the best bet for > retrieving 10% of a table. Are you using nondefault planner settings? > > How big is the table physically (VACUUM VERBOSE output about it might > tell something)? Hi and thanks for your answer! All planner settings in postgresql.conf are commented out. Until yesterday the only setting I've poked with is shared_buffers. Best regards, Marcus apa=> vacuum verbose apa_item_common; INFO: vacuuming "public.apa_item_common" INFO: index "apa_item_common_pkey" now contains 12863 row versions in 36 pages DETAIL: 1246 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.01u sec elapsed 0.21 sec. INFO: index "apa_item_common_x1" now contains 12863 row versions in 38 pages DETAIL: 1246 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.01u sec elapsed 0.72 sec. INFO: index "apa_item_common_fts" now contains 12863 row versions in 391 pages DETAIL: 1246 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.01s/0.01u sec elapsed 1.16 sec. INFO: index "apa_item_common_x2" now contains 12863 row versions in 36 pages DETAIL: 1246 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.51 sec. INFO: "apa_item_common": removed 9028 row versions in 3651 pages DETAIL: CPU 0.24s/0.36u sec elapsed 30.69 sec. INFO: "apa_item_common": found 9028 removable, 12863 nonremovable row versions in 14489 pages DETAIL: 0 dead row versions cannot be removed yet. There were 76646 unused item pointers. 0 pages are entirely empty. CPU 0.64s/0.47u sec elapsed 84.91 sec. INFO: vacuuming "pg_toast.pg_toast_181470" INFO: index "pg_toast_181470_index" now contains 1040 row versions in 5 pages DETAIL: 71 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.07 sec. INFO: "pg_toast_181470": removed 618 row versions in 383 pages DETAIL: CPU 0.01s/0.03u sec elapsed 4.55 sec. INFO: "pg_toast_181470": found 618 removable, 1040 nonremovable row versions in 1288 pages DETAIL: 0 dead row versions cannot be removed yet. There were 6121 unused item pointers. 0 pages are entirely empty. CPU 0.03s/0.04u sec elapsed 16.64 sec. VACUUM apa=>
On Sat, Apr 07, 2007 at 09:28:58AM +0200, Marcus Engene wrote: > INFO: "apa_item_common": removed 9028 row versions in 3651 pages > DETAIL: CPU 0.24s/0.36u sec elapsed 30.69 sec. > INFO: "apa_item_common": found 9028 removable, 12863 nonremovable row > versions in 14489 pages > DETAIL: 0 dead row versions cannot be removed yet. > There were 76646 unused item pointers. How often does this table receive updates and deletes and how often are you vacuuming it? It averages less than one row per page (12863 nonremovable row versions in 14489 pages) and appears to have become quite bloated with dead rows sometime in the past (76646 unused item pointers). Use CLUSTER or VACUUM FULL + REINDEX to compact the table and run ANALYZE afterwards to update the statistics, then make sure you're vacuuming it often enough to keep it from becoming bloated again. Is your free space map sufficiently sized? If you do a database-wide VACUUM VERBOSE, what are the last few lines of the output that mention free space map settings? -- Michael Fuhr
Michael Fuhr skrev: > On Sat, Apr 07, 2007 at 09:28:58AM +0200, Marcus Engene wrote: > >> INFO: "apa_item_common": removed 9028 row versions in 3651 pages >> DETAIL: CPU 0.24s/0.36u sec elapsed 30.69 sec. >> INFO: "apa_item_common": found 9028 removable, 12863 nonremovable row >> versions in 14489 pages >> DETAIL: 0 dead row versions cannot be removed yet. >> There were 76646 unused item pointers. >> > > How often does this table receive updates and deletes and how often > are you vacuuming it? It averages less than one row per page (12863 > nonremovable row versions in 14489 pages) and appears to have become > quite bloated with dead rows sometime in the past (76646 unused > item pointers). Use CLUSTER or VACUUM FULL + REINDEX to compact > the table and run ANALYZE afterwards to update the statistics, then > make sure you're vacuuming it often enough to keep it from becoming > bloated again. > > Is your free space map sufficiently sized? If you do a database-wide > VACUUM VERBOSE, what are the last few lines of the output that > mention free space map settings? > > If I should take a guess, there are 5 deletes per day and 5 updates or inserts per hour. The table is 1.5 years old and I try to vacuuming it once a week; although without "full". I normally do a reindex as well. I've googled a bit to find optimizer hints a la oracle's /*+ index(asdasd) */ but from what I can tell pg has chosen not to use that? I find them convenient for testing at least, even if I agree that one perhaps should avoid having them in a final product. Toggling role/chose in Oracle is something I've often had use for too. The original select seems to be consistantly fast now. That is good, but do I have a ticking bomb? 12k rows is little by any measure and if it was so slow by a little bloat it will be inevitable to reoccur again? Worth mentioning is perhaps that I also have a tsearch2 index on each row that is about 50words each. But timed lookups on that index, which one would expect to be the slowest(?), always seem to be blazingly fast. Is 8.2.x better at these simple things too or is it mainly complex multithreadable queries which will benefit from it? I hadn't touched any fsm settings but I've now set it to max_fsm_pages = 200000 # min max_fsm_relations*16, 6 bytes each 20k max_fsm_relations = 10000 # min 100, ~50 bytes each 1k Thanks for your help! Marcus apa=# vacuum full verbose apa_item_common; INFO: vacuuming "public.apa_item_common" INFO: "apa_item_common": found 176 removable, 12866 nonremovable row versions in 14489 pages DETAIL: 0 dead row versions cannot be removed yet. Nonremovable row versions range from 220 to 2032 bytes long. There were 85496 unused item pointers. Total free space (including removable row versions) is 103371272 bytes. 8673 pages are or will become empty, including 0 at the end of the table. 14479 pages containing 103370096 free bytes are potential move destinations. CPU 0.38s/0.04u sec elapsed 60.17 sec. INFO: index "apa_item_common_pkey" now contains 12866 row versions in 36 pages DETAIL: 176 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.01u sec elapsed 0.20 sec. INFO: index "apa_item_common_x1" now contains 12866 row versions in 38 pages DETAIL: 176 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.84 sec. INFO: index "apa_item_common_fts" now contains 12866 row versions in 396 pages DETAIL: 176 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.01s/0.01u sec elapsed 1.67 sec. INFO: index "apa_item_common_x2" now contains 12866 row versions in 36 pages DETAIL: 176 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.01u sec elapsed 0.88 sec. INFO: "apa_item_common": moved 10868 row versions, truncated 14489 to 1832 pages DETAIL: CPU 1.77s/21.13u sec elapsed 294.11 sec. INFO: index "apa_item_common_pkey" now contains 12866 row versions in 58 pages DETAIL: 10868 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.02u sec elapsed 0.35 sec. INFO: index "apa_item_common_x1" now contains 12866 row versions in 69 pages DETAIL: 10868 index row versions were removed. 4 index pages have been deleted, 4 are currently reusable. CPU 0.00s/0.02u sec elapsed 0.40 sec. INFO: index "apa_item_common_fts" now contains 12866 row versions in 671 pages DETAIL: 10868 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.02s/0.04u sec elapsed 1.80 sec. INFO: index "apa_item_common_x2" now contains 12866 row versions in 67 pages DETAIL: 10868 index row versions were removed. 21 index pages have been deleted, 21 are currently reusable. CPU 0.00s/0.01u sec elapsed 0.34 sec. INFO: vacuuming "pg_toast.pg_toast_181470" INFO: "pg_toast_181470": found 10 removable, 1040 nonremovable row versions in 1288 pages DETAIL: 0 dead row versions cannot be removed yet. Nonremovable row versions range from 174 to 2034 bytes long. There were 6729 unused item pointers. Total free space (including removable row versions) is 9236604 bytes. 732 pages are or will become empty, including 0 at the end of the table. 1288 pages containing 9236604 free bytes are potential move destinations. CPU 0.02s/0.00u sec elapsed 3.91 sec. INFO: index "pg_toast_181470_index" now contains 1040 row versions in 5 pages DETAIL: 10 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.17 sec. INFO: "pg_toast_181470": moved 832 row versions, truncated 1288 to 164 pages DETAIL: CPU 0.02s/0.14u sec elapsed 3.51 sec. INFO: index "pg_toast_181470_index" now contains 1040 row versions in 8 pages DETAIL: 832 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.00 sec. VACUUM apa=# analyze verbose apa_item_common; INFO: analyzing "public.apa_item_common" INFO: "apa_item_common": scanned 1871 of 1871 pages, containing 12875 live rows and 228 dead rows; 3000 rows in sample, 12875 estimated total rows ANALYZE apa=#
On Sat, Apr 07, 2007 at 01:49:38PM +0200, Marcus Engene wrote: > Michael Fuhr skrev: > >How often does this table receive updates and deletes and how often > >are you vacuuming it? > > If I should take a guess, there are 5 deletes per day and 5 updates or > inserts per hour. The table is 1.5 years old and I try to vacuuming it > once a week; although without "full". I normally do a reindex as well. The first VACUUM output showed 9028 removable and 12863 nonremovable rows, which indicates more activity than your guess. I'd suggest vacuuming the table (without FULL) more often than once per week; this table is small enough that vacuuming should take at most a few seconds if you do it often enough. One way to ensure that this happens is to use cron (or whatever your system's scheduler is) to run VACUUM ANALYZE nightly or more often. Or use autovacuum, which is available in 8.0 and earlier as a contributed module and in 8.1 and later as a core component (but not enabled by default). > I've googled a bit to find optimizer hints a la oracle's /*+ > index(asdasd) */ but from what I can tell pg has chosen not to use that? > I find them convenient for testing at least, even if I agree that one > perhaps should avoid having them in a final product. You can influence the query planner with configuration settings. Here's the relevant section in the 8.0 documentation: http://www.postgresql.org/docs/8.0/interactive/runtime-config.html#RUNTIME-CONFIG-QUERY I'd recommend increasing effective_cache_size if you're still using the default. Most of the remaining settings are best used only for debugging unless you can't get a reasonable query plan any other way, and then I'd recommend changing settings only for specific queries (and resetting them after those queries) and not changing the system-wide values. > The original select seems to be consistantly fast now. That is good, but > do I have a ticking bomb? 12k rows is little by any measure and if it > was so slow by a little bloat it will be inevitable to reoccur again? The table was more than a little bloated -- VACUUM FULL shrunk it from 14489 pages to 1832 pages, which means that the table was nearly 8 times larger than it needed to be. You could get an idea of the amount of bloat from the first VACUUM output: > INFO: "apa_item_common": found 9028 removable, 12863 nonremovable row > versions in 14489 pages > DETAIL: 0 dead row versions cannot be removed yet. > There were 76646 unused item pointers. The table had almost as many dead rows (9028) as live rows (12863) and it had additional space (76646) for many times more rows than the table contained. If you vacuum often enough then tables shouldn't become bloated. Autovacuum can help in this respect. > Is 8.2.x better at these simple things too or is it mainly complex > multithreadable queries which will benefit from it? 8.1 and later have autovacuum as a core component; if you enable it then the database will vacuum tables as needed (in 8.1 you might want to lower the default scale factors and thresholds; 8.2's defaults are halved compared to 8.1's). New major releases have other improvements such as better query planning. > I hadn't touched any fsm settings but I've now set it to > max_fsm_pages = 200000 # min max_fsm_relations*16, 6 bytes each 20k > max_fsm_relations = 10000 # min 100, ~50 bytes each 1k The output of a database-wide VACUUM VERBOSE will indicate whether the fsm settings are high enough. -- Michael Fuhr