slow "select count(*) from information_schema.tables;" in some cases
Hi Sometimes simple sql's like this takes a very long time "select count(*) from information_schema.tables;" Other sql's not including system tables may work ok but login also takes a very long time. The CPU load on the server is around 25%. There is no iowait. This happens typically when we are running many functions in parallel creating many temp tables and unlogged tables I think. Here is a slow one: https://explain.depesz.com/s/tUt5 and here is fast one : https://explain.depesz.com/s/yYG4 Here are my settings (the server has around 256 GB og memory) : max_connections = 500 work_mem = 20MB effective_cache_size = 96GB effective_io_concurrency = 256 shared_buffers = 96GB temp_buffers = 80MB Any hints ? Thanks . Lars
Re: slow "select count(*) from information_schema.tables;" in some cases
On Mon, Feb 07, 2022 at 04:56:35PM +, Lars Aksel Opsahl wrote: > Sometimes simple sql's like this takes a very long time "select count(*) > from information_schema.tables;" > > Other sql's not including system tables may work ok but login also takes a > very long time. > > The CPU load on the server is around 25%. There is no iowait. > > This happens typically when we are running many functions in parallel > creating many temp tables and unlogged tables I think. > > Here is a slow one: > https://explain.depesz.com/s/tUt5 > > and here is fast one : > https://explain.depesz.com/s/yYG4 The only difference is that this is sometimes many times slower. Finalize Aggregate (cost=42021.15..42021.16 rows=1 width=8) (actual time=50602.755..117201.768 rows=1 loops=1) -> Gather (cost=42020.94..42021.15 rows=2 width=8) (actual time=130.527..117201.754 rows=3 loops=1) Workers Planned: 2 Workers Launched: 2 > Here are my settings (the server has around 256 GB og memory) : What version of postgres ? What OS/version ? https://wiki.postgresql.org/wiki/Slow_Query_Questions Are there any server logs around that time ? Or session logs for the slow query ? Is it because the table creation is locking (rows of) various system catalogs ? I'm not sure if it'd be a single, long delay that you could see easily with log_lock_waits, or a large number of small delays, maybe depending on whether your table creation is done within a transaction. -- Justin
Re: slow "select count(*) from information_schema.tables;" in some cases
>> >> Here is a slow one: >> https://explain.depesz.com/s/tUt5 >> >> and here is fast one : >> https://explain.depesz.com/s/yYG4 > >The only difference is that this is sometimes many times slower. > > Finalize Aggregate (cost=42021.15..42021.16 rows=1 width=8) (actual > time=50602.755..117201.768 rows=1 loops=1) > -> Gather (cost=42020.94..42021.15 rows=2 width=8) (actual > time=130.527..117201.754 rows=3 loops=1) > Workers Planned: 2 > Workers Launched: 2 > >> Here are my settings (the server has around 256 GB og memory) : > Hi Here is some more info. >What version of postgres ? What OS/version ? psql (14.1, server 12.6 (Ubuntu 12.6-0ubuntu0.20.04.1)) >https://wiki.postgresql.org/wiki/Slow_Query_Questions > >Are there any server logs around that time ? Yes but nothing in the logs that I could find. >Or session logs for the slow query ? > >Is it because the table creation is locking (rows of) various system catalogs ? >I'm not sure if it'd be a single, long delay that you could see easily with >log_lock_waits, or a large number of small delays, maybe depending on whether >your table creation is done within a transaction. Added log_lock_waits but could not anything new in the logs SHOW deadlock_timeout ; deadlock_timeout -- 1s SHOW log_lock_waits; log_lock_waits on (1 row) In the logs I only things like this LOG: duration: 71841.233 ms statement: CREATE UNLOGGED TABLE IF NOT EXISTS tmp_klimagass.styredata_tidligbygg_159298. LOG: duration: 12645.127 ms statement: GRANT SELECT ON TABLE tmp_klimagass.vaerdata_159296 TO org_mojo2_sl_read_role; LOG: duration: 15783.611 ms statement: EXPLAIN ANALYZE select count(*) from information_schema.tables; LOG: duration: 35594.903 ms statement: EXPLAIN ANALYZE select count(*) Can not find anything here either select relation::regclass, * from pg_locks where not granted; relation | locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath --+--+--+--+--+---++---+-+---+--++-+--+-+-- (0 rows) Time: 55.270 ms > >-- >Justin Thanks Lars
Re: slow "select count(*) from information_schema.tables;" in some cases
On Mon, Feb 7, 2022, 10:26 PM Lars Aksel Opsahl wrote: > Hi > > Sometimes simple sql's like this takes a very long time "select count(*) from > information_schema.tables;" > > Other sql's not including system tables may work ok but login also takes a > very long time. > > The CPU load on the server is around 25%. There is no iowait. > > > This happens typically when we are running many functions in parallel > creating many temp tables and unlogged tables I think. > > Here is a slow one: > > https://explain.depesz.com/s/tUt5 > > > and here is fast one : > > https://explain.depesz.com/s/yYG4 > > > Here are my settings (the server has around 256 GB og memory) : > > max_connections = 500 > > work_mem = 20MB > > effective_cache_size = 96GB > > effective_io_concurrency = 256 > > shared_buffers = 96GB > > temp_buffers = 80MB > > Any hints ? > > > Thanks . > > > Lars > Can you share the output of the below query? >From the past threads I have learnt that too many templates objects may add to bloat of system catalogs and may in start resulting in impacting performance. Make a note especially around pg_attribute pg_depends and check for bloat, if required, vacuum full? these objects to speed up. SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' ORDER BY 2 DESC LIMIT 20; can you show the output of this query >
Re: slow "select count(*) from information_schema.tables;" in some cases
>Vijaykumar Jain >Mon 2/7/2022 6:49 PM > >On Mon, Feb 7, 2022, 10:26 PM Lars Aksel Opsahl wrote: >Hi > Hi >Can you share the output of the below query? > >From the past threads I have learnt that too many templates objects may add to >bloat of system catalogs and may in start resulting in impacting performance. >Make a note especially around > >pg_attribute >pg_depends >and check for bloat, if required, vacuum full? these objects to speed up. > > > >SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT >JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' >ORDER BY 2 DESC LIMIT 20; can you show the output of this query SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' ORDER BY 2 DESC LIMIT 20; relname | pg_size_pretty + pg_attrdef_oid_index | 9744 kB pg_attrdef_adrelid_adnum_index | 9712 kB pg_type_typname_nsp_index | 87 MB pg_sequence_seqrelid_index | 8224 kB pg_foreign_table_relid_index | 8192 bytes pg_enum_typid_sortorder_index | 8192 bytes pg_largeobject_metadata| 8192 bytes pg_event_trigger_oid_index | 8192 bytes pg_extension | 8192 bytes pg_event_trigger_evtname_index | 8192 bytes pg_am | 8192 bytes pg_foreign_data_wrapper| 8192 bytes pg_foreign_server_name_index | 8192 bytes pg_enum_typid_label_index | 8192 bytes pg_default_acl | 8192 bytes pg_foreign_server_oid_index| 8192 bytes pg_db_role_setting | 8192 bytes pg_database| 8192 bytes pg_enum_oid_index | 8192 bytes pg_language| 8192 bytes (20 rows) Time: 22.354 ms VACUUM full pg_attribute; 40P01: deadlock detected VACUUM full pg_depends; 40P01: deadlock detected I have to test those later This works ok VACUUM pg_attribute; VACUUM pg_depends; VACUUM full pg_attrdef; VACUUM full pg_type ; VACUUM full pg_sequence; VACUUM full pg_type; SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' ORDER BY 2 DESC LIMIT 20; relname| pg_size_pretty --+ pg_type_oid_index| 960 kB pg_language | 8192 bytes pg_enum_typid_label_index| 8192 bytes pg_pltemplate| 8192 bytes pg_event_trigger_oid_index | 8192 bytes pg_foreign_server_oid_index | 8192 bytes pg_foreign_server_name_index | 8192 bytes pg_enum_oid_index| 8192 bytes pg_largeobject_metadata | 8192 bytes pg_foreign_table_relid_index | 8192 bytes pg_am| 8192 bytes pg_database | 8192 bytes pg_event_trigger_evtname_index | 8192 bytes pg_extension | 8192 bytes pg_partitioned_table_partrelid_index | 8192 bytes pg_enum_typid_sortorder_index| 8192 bytes pg_db_role_setting | 8192 bytes pg_default_acl | 8192 bytes pg_foreign_data_wrapper | 8192 bytes pg_publication_oid_index | 8192 bytes Still slow. Lars
Re: slow "select count(*) from information_schema.tables;" in some cases
Lars Aksel Opsahl writes: >> SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT >> JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' >> ORDER BY 2 DESC LIMIT 20; can you show the output of this query "ORDER BY 2" is giving you a textual sort of the sizes, which is entirely unhelpful. Try SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' ORDER BY pg_relation_size(C.oid) DESC LIMIT 20; regards, tom lane
Re: slow "select count(*) from information_schema.tables;" in some cases
>From: Tom Lane >Sent: Monday, February 7, 2022 8:02 PM >To: Lars Aksel Opsahl >Cc: Vijaykumar Jain ; Pgsql Performance > >Subject: Re: slow "select count(*) from information_schema.tables;" in some >cases > >Lars Aksel Opsahl writes: >>> SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C >>> LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = >>> 'pg_catalog' ORDER BY 2 DESC LIMIT 20; can you show the output of this query > >"ORDER BY 2" is giving you a textual sort of the sizes, which is entirely >unhelpful. Try > >SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT >JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' >ORDER BY pg_relation_size(C.oid) DESC LIMIT 20; > >regards, tom lane > Hi Then pg_attribute show up yes. I have to vacuum full later when server is free. SELECT relname, pg_size_pretty(pg_relation_size(C.oid)) FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname = 'pg_catalog' ORDER BY pg_relation_size(C.oid) DESC LIMIT 20; relname | pg_size_pretty ---+ pg_largeobject| 17 GB pg_attribute | 1452 MB pg_statistic | 1103 MB pg_class | 364 MB pg_attribute_relid_attnam_index | 307 MB pg_depend | 285 MB pg_largeobject_loid_pn_index | 279 MB pg_attribute_relid_attnum_index | 230 MB pg_depend_reference_index | 207 MB pg_depend_depender_index | 198 MB pg_class_relname_nsp_index| 133 MB pg_index | 111 MB pg_statistic_relid_att_inh_index | 101 MB pg_class_oid_index| 52 MB pg_class_tblspc_relfilenode_index | 46 MB pg_shdepend | 38 MB pg_shdepend_depender_index| 25 MB pg_index_indexrelid_index | 24 MB pg_shdepend_reference_index | 21 MB pg_index_indrelid_index | 18 MB (20 rows) Thanks
Re: slow "select count(*) from information_schema.tables;" in some cases
Hi Lars, > psql (14.1, server 12.6 (Ubuntu 12.6-0ubuntu0.20.04.1)) Maybe you can upgrade to 12.9 ( from 12.6 ) ( https://www.postgresql.org/docs/release/12.9/ ) And the next minor release = pg 12.10 is expected on February 10th, 2022 https://www.postgresql.org/developer/roadmap/ As I see - only a minor fix exists for "system columns": "Don't ignore system columns when estimating the number of groups using extended statistics (Tomas Vondra)" in 12.7 I have similar experiences with the system tables - vacuuming is extreme important in my case - I am calling "vacuum" in every ETL job - cleaning my system tables. select schemaname ,relname ,n_tup_ins ,n_tup_upd ,n_tup_del ,n_tup_hot_upd ,n_live_tup ,n_dead_tup from pg_stat_all_tables where n_dead_tup > 0 and schemaname='pg_catalog' ; Regards, Imre Lars Aksel Opsahl ezt írta (időpont: 2022. febr. 7., H, 18:40): > >> > > >> Here is a slow one: > > >> https://explain.depesz.com/s/tUt5 > > >> > > >> and here is fast one : > > >> https://explain.depesz.com/s/yYG4 > > > > > >The only difference is that this is sometimes many times slower. > > > > > > Finalize Aggregate (cost=42021.15..42021.16 rows=1 width=8) (actual > time=50602.755..117201.768 rows=1 loops=1) > > > -> Gather (cost=42020.94..42021.15 rows=2 width=8) (actual > time=130.527..117201.754 rows=3 loops=1) > > > Workers Planned: 2 > > > Workers Launched: 2 > > > > > >> Here are my settings (the server has around 256 GB og memory) : > > > > > > Hi > > > Here is some more info. > > > >What version of postgres ? What OS/version ? > > > psql (14.1, server 12.6 (Ubuntu 12.6-0ubuntu0.20.04.1)) > > >https://wiki.postgresql.org/wiki/Slow_Query_Questions > > > > > >Are there any server logs around that time ? > > > Yes but nothing in the logs that I could find. > > > >Or session logs for the slow query ? > > > > > >Is it because the table creation is locking (rows of) various system > catalogs ? > > >I'm not sure if it'd be a single, long delay that you could see easily > with > > >log_lock_waits, or a large number of small delays, maybe depending on > whether > > >your table creation is done within a transaction. > > > Added log_lock_waits but could not anything new in the logs > > > SHOW deadlock_timeout ; > > deadlock_timeout > > -- > > 1s > > SHOW log_lock_waits; > > log_lock_waits > > > > on > > (1 row) > > > In the logs I only things like this > > LOG: duration: 71841.233 ms statement: CREATE UNLOGGED TABLE IF NOT > EXISTS tmp_klimagass.styredata_tidligbygg_159298. > > > LOG: duration: 12645.127 ms statement: GRANT SELECT ON TABLE > tmp_klimagass.vaerdata_159296 TO org_mojo2_sl_read_role; > > LOG: duration: 15783.611 ms statement: EXPLAIN ANALYZE select count(*) > > from information_schema.tables; > > LOG: duration: 35594.903 ms statement: EXPLAIN ANALYZE select count(*) > > Can not find anything here either > > > select relation::regclass, * from pg_locks where not granted; > > relation | locktype | database | relation | page | tuple | virtualxid | > transactionid | classid | objid | objsubid | virtualtransaction | pid | > mode | granted | fastpath > > > --+--+--+--+--+---++---+-+---+--++-+--+-+-- > > (0 rows) > > > Time: 55.270 ms > > > > > > >-- > > >Justin > > Thanks > > Lars >
Query choosing Bad Index Path (ASC/DESC ordering).
Postgres version: 11.4
Problem:
Query choosing Bad Index Path (ASC/DESC ordering). Details are provided
below
Table:
\d public.distdbentityauditlog1_46625_temp_mahi3;
Table "public.distdbentityauditlog1_46625_temp_mahi3"
Column |Type | Collation | Nullable |
Default
--+-+---+--+-
zgid | bigint | | not null |
auditlogid | bigint | | not null |
recordid | bigint | | |
recordname | text| | |
module | character varying(50) | | not null |
actioninfo | character varying(255) | | not null |
relatedid| bigint | | |
relatedname | character varying(255) | | |
relatedmodule| character varying(50) | | |
accountid| bigint | | |
accountname | character varying(255) | | |
doneby | character varying(255) | | not null |
userid | bigint | | |
auditedtime | timestamp without time zone | | not null |
fieldhistoryinfo | text| | |
isauditlogdata | boolean | | not null |
otherdetails | text| | |
audittype| integer | | not null |
requesteruserid | bigint | | |
actiontype | integer | | not null |
source | integer | | not null |
module_lower | character varying(50) | | not null |
Indexes:
"distdbentityauditlog1_46625_temp_mahi3_pkey" PRIMARY KEY, btree (zgid,
auditedtime, auditlogid)
"distdbentityauditlog1_idx1_46625_temp_mahi3" btree (recordid)
"distdbentityauditlog1_idx2_46625_temp_mahi3" btree (auditlogid)
"distdbentityauditlog1_idx3_46625_temp_mahi3" btree (relatedid)
"distdbentityauditlog1_idx4_46625_temp_mahi3" gist (actioninfo
gist_trgm_ops)
"distdbentityauditlog1_idx5_46625_temp_mahi3" btree (actioninfo)
"distdbentityauditlog1_idx6_46625_temp_mahi3" btree (auditedtime DESC,
module)
explain (analyse, buffers, verbose) SELECT zgid, auditlogid, recordid,
recordname, module, actioninfo, relatedid, relatedname, relatedmodule,
accountid, accountname, doneby, userid, auditedtime, fieldhistoryinfo,
isauditlogdata, otherdetails, audittype, requesteruserid, actiontype,
source FROM public.distdbentityauditlog1_46625_temp_mahi3
distdbentityauditlog1 WHERE ((actiontype = ANY
('{2,9,14,55,56,67}'::integer[])) AND ((recordid =
'15842006928391817'::bigint) OR ((module)::text = 'Contacts'::text)) AND
((recordid = '15842006928391817'::bigint) OR (relatedid =
'15842006928391817'::bigint)) AND (audittype <> ALL
('{2,4,5,6}'::integer[])) AND (auditedtime >= '2021-03-27
09:43:17'::timestamp without time zone) AND (zgid = 100)) ORDER BY 14 DESC,
2 DESC LIMIT '10'::bigint;
Limit (cost=0.43..415.30 rows=10 width=400) (actual
time=7582.965..7583.477 rows=10 loops=1)
Output: zgid, auditlogid, recordid, recordname, module, actioninfo,
relatedid, relatedname, relatedmodule, accountid, accountname, doneby,
userid, auditedtime, fieldhistoryinfo, isauditlogdata, otherdetails,
audittype, requesteruserid, actiontype, source
Buffers: shared hit=552685 read=1464159
-> Index Scan Backward using
distdbentityauditlog1_46625_temp_mahi3_pkey on
public.distdbentityauditlog1_46625_temp_mahi3 distdbentityauditlog1
(cost=0.43..436281.55 rows=10516 width=400) (actual
time=7582.962..7583.470 rows=10
loops=1)
Output: zgid, auditlogid, recordid, recordname, module,
actioninfo, relatedid, relatedname, relatedmodule, accountid, accountname,
doneby, userid, auditedtime, fieldhistoryinfo, isauditlogdata,
otherdetails, audittype, requesteruserid, actiontype, source
Index Cond: ((distdbentityauditlog1.zgid = 100) AND
(distdbentityauditlog1.auditedtime >= '2021-03-27 09:43:17'::timestamp
without time zone))
Filter: (((distdbentityauditlog1.recordid =
'15842006928391817'::bigint) OR ((distdbentityauditlog1.module)::text =
'Contacts'::text)) AND ((distdbentityauditlog1.recordid =
'15842006928391817'::bigint) OR (distdbentityauditlog1.relatedid =
'15842006928391817'::bigint)) AND (distdbentityauditlog1.audittype <> ALL
('{2,4,5,6}'::integer[])) AND (distdbentityauditlog1.actiontype = ANY
('{2,9,14,55,56,67}'::integer[])))
Rows Removed by Filter: 2943989
Buffers: shared hit=552685 read=1464159
Planning Time: 0.567 ms
Execution Time: 7583.558 ms
(11 rows)
Doubt:
In Index Sc
