[GENERAL] Very slow catalog query
Hi, I have a DB with a large number schemas (around 10K) and a large number of tables (400K). The app became slow lately, and logging the slow queries, I see more than a few like this: SELECT: LOG: duration: 169547.424 ms statement: SELECT attr.attname, name.nspname, seq.relname FROM pg_class seq, pg_attribute attr, pg_depend dep, pg_namespace name, pg_constraint cons WHERE seq.oid = dep.objid AND seq.relnamespace = name.oid AND seq.relkind = 'S' AND attr.attrelid = dep.refobjid AND attr.attnum = dep.refobjsubid AND attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1] AND cons.contype = 'p' AND dep.refobjid = 'activities'::regclass Almost all slow queries are of this type, though most of those do finish really fast. From time to time it gets really slow. Some details on the setup: Dual Opteron with 4GB RAM RAID1 for WAL on 10K SCSI RAID10 over 6 x 10K scsi drives for main the rest for the DB files Auto vaccum is on, and in addition I do some vacuuming for specific high use tables nightly Any ideas how to start finding the culprit? Bye, Guy. -- Family management on rails: http://www.famundo.com My development related blog: http://devblog.famundo.com -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
Re: [GENERAL] Very slow catalog query
On Monday 31 March 2008 15:13:25 Just Someone wrote: Hi, I have a DB with a large number schemas (around 10K) and a large number of tables (400K). The app became slow lately, and logging the slow queries, I see more than a few like this: SELECT: LOG: duration: 169547.424 ms statement: SELECT attr.attname, name.nspname, seq.relname FROM pg_class seq, pg_attribute attr, pg_depend dep, pg_namespace name, pg_constraint cons WHERE seq.oid = dep.objid AND seq.relnamespace = name.oid AND seq.relkind = 'S' AND attr.attrelid = dep.refobjid AND attr.attnum = dep.refobjsubid AND attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1] AND cons.contype = 'p' AND dep.refobjid = 'activities'::regclass Almost all slow queries are of this type, though most of those do finish really fast. From time to time it gets really slow. Some details on the setup: Dual Opteron with 4GB RAM RAID1 for WAL on 10K SCSI RAID10 over 6 x 10K scsi drives for main the rest for the DB files Auto vaccum is on, and in addition I do some vacuuming for specific high use tables nightly Any ideas how to start finding the culprit? Bye, Guy. -- Family management on rails: http://www.famundo.com My development related blog: http://devblog.famundo.com Hi 'Just Someone' I'm wondering... just 4GB of ram? What's the normal hammering -- a.k.a. user access -- to all of this? PG, as expected, launches a separate process for each connection. this eats up resources quite quickly Did you check your system processes with 'top' ? how's it looking for swap usage? Regards, -- Pedro Doria Meunier Ips. da Olaria, Edf. Jardins do Garajau, 4, r/c Y 9125-162 Caniço Madeira - Portugal -- Skype : pdoriam Mobile: +351961720188 signature.asc Description: This is a digitally signed message part.
Re: [GENERAL] Very slow catalog query
Just Someone [EMAIL PROTECTED] writes: Any ideas how to start finding the culprit? EXPLAIN ANALYZE? What would be particularly interesting is to compare the results for fast and slow cases of the same query. regards, tom lane -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
Re: [GENERAL] Very slow catalog query
Hi, I'm wondering... just 4GB of ram? What's the normal hammering -- a.k.a. user access -- to all of this? PG, as expected, launches a separate process for each connection. this eats up resources quite quickly Did you check your system processes with 'top' ? how's it looking for swap usage? Swap usage is almost nil. And I only have a constant number of connections (about 10-15) as it serves as the backend for a Web application. Transactions run at about 20-40 per second, but mostly very short and simple ones. Thanks, Guy. -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
Re: [GENERAL] Very slow catalog query
Hi Tom, Here is the result of explain analyze (though this one took 1500ms and not 169000): On Mon, Mar 31, 2008 at 7:37 AM, Tom Lane [EMAIL PROTECTED] wrote: Just Someone [EMAIL PROTECTED] writes: Any ideas how to start finding the culprit? EXPLAIN ANALYZE? explain analyze SELECT attr.attname, name.nspname, seq.relname FROM pg_class seq, pg_attribute attr, pg_depend dep, pg_namespace name, pg_constraint cons WHERE seq.oid = dep.objid AND seq.relnamespace = name.oid AND seq.relkind = 'S' AND attr.attrelid = dep.refobjid AND attr.attnum = dep.refobjsubid AND attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1] AND cons.contype = 'p' AND dep.refobjid = 'activities'::regclass; QUERY PLAN Nested Loop (cost=64956.07..65025.73 rows=31 width=192) (actual time=1547.720..1547.749 rows=1 loops=1) - Nested Loop (cost=64956.07..64987.48 rows=1 width=166) (actual time=1547.662..1547.684 rows=1 loops=1) - Nested Loop (cost=64956.07..64981.47 rows=1 width=106) (actual time=1547.616..1547.631 rows=1 loops=1) - Merge Join (cost=64956.07..64957.36 rows=4 width=42) (actual time=1547.484..1547.502 rows=3 loops=1) Merge Cond: (outer.?column3? = inner.refobjsubid) - Sort (cost=4.08..4.08 rows=3 width=30) (actual time=0.149..0.151 rows=1 loops=1) Sort Key: cons.conkey[1] - Index Scan using pg_constraint_conrelid_index on pg_constraint cons (cost=0.00..4.05 rows=3 width=30) (actual time=0.110..0.112 rows=1 loops=1) Index Cond: (30375069::oid = conrelid) Filter: (contype = 'p'::char) - Sort (cost=64951.99..64952.61 rows=247 width=12) (actual time=1547.303..1547.318 rows=9 loops=1) Sort Key: dep.refobjsubid - Index Scan using pg_depend_reference_index on pg_depend dep (cost=0.00..64942.17 rows=247 width=12) (actual time=396.542..1547.172 rows=22 loops=1) Index Cond: (refobjid = 30375069::oid) - Index Scan using pg_class_oid_index on pg_class seq (cost=0.00..6.02 rows=1 width=72) (actual time=0.034..0.035 rows=0 loops=3) Index Cond: (seq.oid = outer.objid) Filter: (relkind = 'S'::char) - Index Scan using pg_namespace_oid_index on pg_namespace name (cost=0.00..6.00 rows=1 width=68) (actual time=0.039..0.041 rows=1 loops=1) Index Cond: (outer.relnamespace = name.oid) - Index Scan using pg_attribute_relid_attnum_index on pg_attribute attr (cost=0.00..38.00 rows=20 width=70) (actual time=0.050..0.052 rows=1 loops=1) Index Cond: ((30375069::oid = attr.attrelid) AND (attr.attnum = outer.refobjsubid)) Total runtime: 1548.082 ms Bye, Guy. -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
Re: [GENERAL] Very slow catalog query
Just Someone [EMAIL PROTECTED] writes: Here is the result of explain analyze (though this one took 1500ms and not 169000): Well, it's hard to be sure what the problem is when you're not showing us a problem case ... but I notice that this indexscan is estimated awfully high: - Index Scan using pg_depend_reference_index on pg_depend dep (cost=0.00..64942.17 rows=247 width=12) (actual time=396.542..1547.172 rows=22 loops=1) Index Cond: (refobjid = 30375069::oid) The reason is not far to seek: the scan is checking only the second index key, meaning that it has to scan the entire index. (I am surprised it didn't use a seqscan instead. Are you using enable_seqscan = off? Not a great idea.) Since you know you are looking for a table, you could improve matters by adding a constraint on refclassid: dep.refclassid = 'pg_class'::regclass regards, tom lane -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
Re: [GENERAL] Very slow catalog query
Hi Tom, Well, it's hard to be sure what the problem is when you're not showing us a problem case ... but I notice that this indexscan is estimated awfully high: Whenever I do it manually it works fast. But in the log I see lots of slow ones. Could it be caused by auto vacuum? Or by check pointing or WAL writing? Are there way to check that? - Index Scan using pg_depend_reference_index on pg_depend dep (cost=0.00..64942.17 rows=247 width=12) (actual time=396.542..1547.172 rows=22 loops=1) Index Cond: (refobjid = 30375069::oid) The reason is not far to seek: the scan is checking only the second index key, meaning that it has to scan the entire index. (I am surprised it didn't use a seqscan instead. Are you using enable_seqscan = off? Not a great idea.) Since you know you are looking for a table, you could improve matters by adding a constraint on refclassid: dep.refclassid = 'pg_class'::regclass enable_setscan is on. Is there a way to analyze/vacuum those tables? I will look if I can also improve the query to be more exact. Bye, Guy. -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
