Обсуждение: slow queries on system tables

The driver I´m using does some queries on system tables and obviously I
cannot change them because are driver inside. These two queries are usually
fast, but sometimes they take 8 or 15 times more to run. The question is,
can I change something on these tables ? Can i create an index, can I load
them into cache ? What can I do to speed up if I cannot change the way these
queries are written ?

Extracted from pg_stat_statements:
Query 1 - calls: 200000 times, min_time ~ 20ms, mean_time ~ 50ms, max_time ~
480ms
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($2, indnatts - $3), 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 $4 AND t.relname LIKE $5 ORDER BY
indisprimary::integer DESC, n.nspname, t.relname, c.relname, a.attnum

Query 1 - calls: 20000 times, min_time ~ 70ms, mean_time ~ 95ms, max_time ~
170ms.
SELECT pg_attribute.attname FROM pg_index, pg_class, pg_attribute  WHERE
upper(pg_class.relname) = $1 AND indrelid = pg_class.oid AND
pg_attribute.attrelid = pg_class.oid    AND pg_attribute.attnum =
any(pg_index.indkey) AND indisprimary




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

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:

https://www.postgresql.org/message-id/1564168884421-0.post%40n3.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 the PostgreSQL - general mailing list archive at Nabble.com.

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:

https://www.postgresql.org/message-id/1563909633976-0.post%40n3.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> 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

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 the PostgreSQL - general mailing list archive at Nabble.com.