slow queries on system tables

Are you autovacuuming and analyzing aggressively enough? Is there bloat or
other concern for these system tables? I expect it may be a concern based
on what I remember about your environment having thousands of tables and
perhaps autovacuum not keeping up (re: Too slow to create new schema and
their tables, functions, triggers).

Can you check results for last (auto)vacuum and analyze?
select * from pg_stat_all_tables where relname IN( 'pg_class',
'pg_attribute', 'pg_index' );

last values for autovacuum and autoanalyse are Null.

Thanks, I´ll change and see if that solve our problem

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

On 8/15/19 12:09 PM, PegoraroF10 wrote:

last values for autovacuum and autoanalyse are Null.

Thanks, I´ll change and see if that solve our problem

I thought we had been down this trail before:

/messages/by-id/1564168884421-0.post@n3.nabble.com

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

--
Adrian Klaver
adrian.klaver@aklaver.com

Well, not exactly.

Values for autovacuum and autoanalyse are Null because I did not configured
them for system tables yet, but I´m doing vacuum manually once a week. My
question now is why those selects varies that way.

Almost all times it spend 20ms but 2 o 3% of the times it spend 500ms, why ?
System tables are not cached ? What is Postgres doing on that time to get
that response times ?
Can I help Postgres on any way ?

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

PegoraroF10 <marcos@f10.com.br> writes:

Values for autovacuum and autoanalyse are Null because I did not configured
them for system tables yet, but I´m doing vacuum manually once a week. My
question now is why those selects varies that way.

Well, one point is that the execution time would probably vary hugely
depending on what's supplied for the parameters in

WHERE n.nspname LIKE $4 AND t.relname LIKE $5

which you haven't told us. I'm also wondering about just how many rows
get emitted by "generate_series($2, indnatts - $3)", and why that
particular part of the query makes any sense at all.

regards, tom lane

As I told you before, these queries cannot be changed because the driver
creates them.
As I cannot change them how can I help Postgres to run it faster, just that.

My log_min_duration_statement = 500ms, so I find SQL some dozens of this sql
inside it daily, but I´m sure this sql is used thousands and thousands a
day.

duration: 566.415 ms execute PRSTMTST1590201604/PORTALST1590201604: SELECT
current_database() AS TABLE_CATALOG, n.nspname AS TABLE_SCHEMA, t.relname AS
TABLE_NAME, t.oid AS TABLE_OID, current_database() AS INDEX_CATALOG,
n.nspname AS INDEX_SCHEMA, c.relname AS INDEX_NAME, c.oid AS INDEX_OID,
a.attname AS COLUMN_NAME, a.attnum AS COLUMN_POSITION,indoption[index] & 1
AS DESCENDING , indisunique::integer AS UNIQUE FROM (SELECT
generate_series(0, indnatts - 1), indrelid, indexrelid, indkey, indoption,
indisunique, indisprimary FROM pg_index i) i(index, indrelid, indexrelid,
indkey, indoption, indisunique, indisprimary) INNER JOIN pg_class c ON
c.oid = indexrelid INNER JOIN pg_class t ON t.oid = indrelid INNER JOIN
pg_namespace n ON n.oid = t.relnamespace INNER JOIN pg_attribute a ON
a.attrelid = indrelid AND a.attnum = indkey[index] WHERE n.nspname LIKE
'f10_0275, public' AND t.relname LIKE 'sys_var' ORDER BY
indisprimary::integer DESC, n.nspname, t.relname, c.relname, a.attnum

QUERY PLAN
Sort (cost=260362.69..260362.69 rows=1 width=470) (actual
time=59.526..59.527 rows=0 loops=1)
Sort Key: ((i.indisprimary)::integer) DESC, n.nspname, t.relname,
c.relname, a.attnum
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=1003.58..260362.68 rows=1 width=470) (actual
time=59.519..59.519 rows=0 loops=1)
-> Nested Loop (cost=1003.44..260360.98 rows=1 width=238) (actual
time=5.251..58.872 rows=424 loops=1)
-> Gather (cost=1003.02..260360.42 rows=1 width=174) (actual
time=5.232..72.894 rows=424 loops=1)
Workers Planned: 1
Workers Launched: 1
-> Nested Loop (cost=3.02..259360.32 rows=1 width=174)
(actual time=8.357..48.200 rows=212 loops=2)
Join Filter: (t.oid = a.attrelid)
-> Hash Join (cost=2.59..259357.51 rows=4
width=138) (actual time=8.322..46.124 rows=212 loops=2)
Hash Cond: (i.indrelid = t.oid)
-> ProjectSet (cost=0.00..258260.16
rows=51008000 width=66) (actual time=0.011..33.557 rows=53694 loops=2)
-> Parallel Seq Scan on pg_index i
(cost=0.00..2710.08 rows=51008 width=64) (actual time=0.007..6.804
rows=43564 loops=2)
-> Hash (cost=2.44..2.44 rows=12 width=72)
(actual time=7.614..7.615 rows=210 loops=2)
Buckets: 1024 Batches: 1 Memory
Usage: 30kB
-> Index Scan using
pg_class_relname_nsp_index on pg_class t (cost=0.42..2.44 rows=12 width=72)
(actual time=0.029..7.556 rows=210 loops=2)
Index Cond: ((relname >=
'sys'::name) AND (relname < 'syt'::name))
Filter: (relname ~~
'sys_account'::text)
Rows Removed by Filter: 1696
-> Index Scan using
pg_attribute_relid_attnum_index on pg_attribute a (cost=0.42..0.69 rows=1
width=70) (actual time=0.009..0.009 rows=1 loops=424)
Index Cond: ((attrelid = i.indrelid) AND
(attnum = (i.indkey)[(generate_series(0, (i.indnatts - 1)))]))
-> Index Scan using pg_class_oid_index on pg_class c
(cost=0.42..0.56 rows=1 width=68) (actual time=0.005..0.005 rows=1
loops=424)
Index Cond: (oid = i.indexrelid)
-> Index Scan using pg_namespace_oid_index on pg_namespace n
(cost=0.14..0.92 rows=1 width=68) (actual time=0.001..0.001 rows=0
loops=424)
Index Cond: (oid = t.relnamespace)
Filter: (nspname ~~ 'f10_0511, public'::text)
Rows Removed by Filter: 1
Planning Time: 1.176 ms
Execution Time: 76.031 ms

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

Coming back to my problem, today happened again, that search comes slow.
Explaining again, auto vacuum and auto analyse for pg_* tables are not
configured one by one, so its using that defaults of scale_factor = 0.2 and
threshold = 50. Today, when that problem of speed came back, the view
pg_stat_sys_tables for pg_class table shows that it ran 415 times autovacuum
only this week and there are 75187 updates on this table. How can I have
been updated 75000 times this table only in a week ? What kind of statement
does an update on this table ? And why did it run 415 times autovacuum and
only 1 autoanalyse ?
relname seq_scan seq_tup_read idx_scan idx_tup_fetch n_tup_ins n_tup_upd
n_tup_del n_tup_hot_upd n_live_tup n_dead_tup n_mod_since_analyze
last_vacuum last_autovacuum last_analyze last_autoanalyze vacuum_count
autovacuum_count analyze_count autoanalyze_count
pg_class 5395512 38598962913 616674711 2219978581 2243 75187 625 44008
169891 5645 7435 NULL 2019-08-22 19:58:48.497317 NULL 2019-08-22
13:03:02.770579 0 415 0 1

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

Might the issue be with pg_index or pg_attribute rather than pg_class? Is
the query still slow? Do you have the output of explain analyze for use on
https://explain.depesz.com/ or the output of EXPLAIN (ANALYZE, COSTS,
VERBOSE, BUFFERS, FORMAT JSON) for use on
http://tatiyants.com/pev/#/plans/new website?

On 8/23/19 2:47 PM, PegoraroF10 wrote:

Coming back to my problem, today happened again, that search comes slow.
Explaining again, auto vacuum and auto analyse for pg_* tables are not
configured one by one, so its using that defaults of scale_factor = 0.2
and threshold = 50. Today, when that problem of speed came back, the
view pg_stat_sys_tables for pg_class table shows that it ran 415 times
autovacuum only this week and there are 75187 updates on this table. How
can I have been updated 75000 times this table only in a week ? What

If you are still doing this:

/messages/by-id/1563909633976-0.post@n3.nabble.com

then it is not surprising.

kind of statement does an update on this table ? And why did it run 415
times autovacuum and only 1 autoanalyse ?

Can you show the actual settings in postgresql.conf for:

autovacuum_analyze_threshold

autovacuum_analyze_scale_factor

Also do you have an include in postgresql.conf pointing to another file?

I know you said they are using the defaults but the scale_factor you
show above is the default for autovacuum_vacuum_scale_factor. For
autovacuum_analyze_scale_factor the default is 0.1, which makes wonder.

relname seq_scan seq_tup_read idx_scan idx_tup_fetch n_tup_ins
n_tup_upd n_tup_del n_tup_hot_upd n_live_tup n_dead_tup
n_mod_since_analyze last_vacuum last_autovacuum last_analyze
last_autoanalyze vacuum_count autovacuum_count analyze_count
autoanalyze_count
pg_class 5395512 38598962913 616674711 2219978581 2243 75187 625 44008
169891 5645 7435 NULL 2019-08-22 19:58:48.497317 NULL 2019-08-22
13:03:02.770579 0 415 0 1

------------------------------------------------------------------------
Sent from the PostgreSQL - general mailing list archive
<https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html&gt; at
Nabble.com.

--
Adrian Klaver
adrian.klaver@aklaver.com

https://explain.depesz.com/s/5Rrd

EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS) SELECT
current_database() AS TABLE_CATALOG, n.nspname AS TABLE_SCHEMA, t.relname AS
TABLE_NAME, t.oid AS TABLE_OID, current_database() AS INDEX_CATALOG,
n.nspname AS INDEX_SCHEMA, c.relname AS INDEX_NAME, c.oid AS INDEX_OID,
a.attname AS COLUMN_NAME, a.attnum AS COLUMN_POSITION,indoption[index] & 1
AS DESCENDING , indisunique::integer AS UNIQUE FROM (SELECT
generate_series(0, indnatts - 1), indrelid, indexrelid, indkey, indoption,
indisunique, indisprimary FROM pg_index i) i(index, indrelid, indexrelid,
indkey, indoption, indisunique, indisprimary) INNER JOIN pg_class c ON
c.oid = indexrelid INNER JOIN pg_class t ON t.oid = indrelid INNER JOIN
pg_namespace n ON n.oid = t.relnamespace INNER JOIN pg_attribute a ON
a.attrelid = indrelid AND a.attnum = indkey[index] WHERE n.nspname LIKE
'f10_0275, public' AND t.relname LIKE 'sys_var' ORDER BY
indisprimary::integer DESC, n.nspname, t.relname, c.relname, a.attnum;

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

autovacuum_analyze_threshold = 50;
autovacuum_analyze_scale_factor = 0.1

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

Can you manually execute vacuum analyze on all three involved tables and
again share the plan for the same query? If it is significantly improved,
it would seem like following the recommendation to tune autovacuum (and
analyze) to be more frequent would be prudent.

You haven't seemed to change from default vacuum/analyze settings despite
the default parameters being suggested only for bare minimum hardware and
very light use databases.

This week we added just 5 new customers. Every schema has 100 tables, 300
indices, 400 triggers.
I cannot imagine our script doing 75000 updates just for adding those
schemas.

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

On 8/23/19 3:47 PM, PegoraroF10 wrote:

This week we added just 5 new customers. Every schema has 100 tables, 300
indices, 400 triggers.
I cannot imagine our script doing 75000 updates just for adding those
schemas.

Very rough calculation:

https://www.postgresql.org/docs/11/catalog-pg-class.html

The catalog pg_class catalogs tables and most everything else that has
columns or is otherwise similar to a table. This includes indexes (but
see also pg_index), sequences (but see also pg_sequence), views,
materialized views, composite types, and TOAST tables; see relkind. ...

From above, not counting TOAST tables:

5 * (100 + 300) = 2,000 new entries.

From previous post you said you had 190 schemas at that time.

190 * 400 = 76,000 entries
+ 2,000
78,000

In pg_class rel* fields:

"It is updated by VACUUM, ANALYZE, and a few DDL commands such as CREATE
INDEX."

Assuming tables/indexes have changed enough to trigger vacuum run:

78,000 * 1 vacuum = 78,000 updates

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

--
Adrian Klaver
adrian.klaver@aklaver.com

these values were collected before vacuum analyse:select (select reltuples
from pg_Class where relName = t.relName), * from pg_stat_sys_tables t where
schemaname = 'pg_catalog' and relname in
('pg_class','pg_attribute','pg_index');
reltuples relid schemaname relname seq_scan seq_tup_read idx_scan
idx_tup_fetch n_tup_ins n_tup_upd n_tup_del n_tup_hot_upd n_live_tup
n_dead_tup n_mod_since_analyze last_vacuum last_autovacuum last_analyze
last_autoanalyze vacuum_count autovacuum_count analyze_count
autoanalyze_count
930475 1249 pg_catalog pg_attribute 22462 61582178 646833988 2785143399
25381 776 15287 566 10094 15497 41444 NULL NULL NULL NULL 0 0 0 0
169186 1259 pg_catalog pg_class 5541140 39631813757 638041068 2316793709
2243 75187 625 44008 169891 5645 7435 NULL 2019-08-22 19:58:48.497317 NULL
2019-08-22 13:03:02.770579 0 415 0 1
87387 2610 pg_catalog pg_index 5263825 33638625440 246528384 590160274 1142
0 208 0 934 208 1350 NULL NULL NULL NULL 0 0 0 0
Then ... vacuum analyze pg_catalog.pg_index;vacuum analyze
pg_catalog.pg_attribute;vacuum analyze pg_catalog.pg_class;
reltuples relid schemaname relname seq_scan seq_tup_read idx_scan
idx_tup_fetch n_tup_ins n_tup_upd n_tup_del n_tup_hot_upd n_live_tup
n_dead_tup n_mod_since_analyze last_vacuum last_autovacuum last_analyze
last_autoanalyze vacuum_count autovacuum_count analyze_count
autoanalyze_count
940569 1249 pg_catalog pg_attribute 22550 61582570 646919000 2785430403
25381 776 15287 566 940569 0 0 2019-08-24 09:01:26.334472 NULL 2019-08-24
09:01:27.169883 NULL 1 0 1 0
150903 1259 pg_catalog pg_class 5542002 39640547448 638133339 2316941739
2243 75187 625 44008 150903 0 0 2019-08-24 09:01:33.130845 2019-08-22
19:58:48.497317 2019-08-24 09:01:33.441355 2019-08-22 13:03:02.770579 1 415
1 1
88321 2610 pg_catalog pg_index 5263994 33639781274 246576056 590229532 1142
0 208 0 88321 0 0 2019-08-24 09:01:18.080615 NULL 2019-08-24 09:01:18.275907
NULL 1 0 1 0
and this is explain before
https://explain.depesz.com/s/fUNB
and after
https://explain.depesz.com/s/1FZR

--
Sent from: https://www.postgresql-archive.org/PostgreSQL-general-f1843780.html