Thread: slow queries on system tables

slow queries on system tables

From
PegoraroF10
Date:
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



Re: slow queries on system tables

From
Michael Lewis
Date:
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' );

Re: slow queries on system tables

From
PegoraroF10
Date:
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



Re: slow queries on system tables

From
Adrian Klaver
Date:
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



Re: slow queries on system tables

From
PegoraroF10
Date:
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



Re: slow queries on system tables

From
Tom Lane
Date:
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



Re: slow queries on system tables

From
PegoraroF10
Date:
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



Re: slow queries on system tables

From
PegoraroF10
Date:
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 ?
relnameseq_scanseq_tup_readidx_scanidx_tup_fetchn_tup_insn_tup_updn_tup_deln_tup_hot_updn_live_tupn_dead_tupn_mod_since_analyzelast_vacuumlast_autovacuumlast_analyzelast_autoanalyzevacuum_countautovacuum_countanalyze_countautoanalyze_count
pg_class53955123859896291361667471122199785812243751876254400816989156457435NULL2019-08-22 19:58:48.497317NULL2019-08-22 13:03:02.770579041501


Sent from the PostgreSQL - general mailing list archive at Nabble.com.

Re: slow queries on system tables

From
Michael Lewis
Date:
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?

Re: slow queries on system tables

From
Adrian Klaver
Date:
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



Re: slow queries on system tables

From
PegoraroF10
Date:
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



Re: slow queries on system tables

From
PegoraroF10
Date:
autovacuum_analyze_threshold               = 50;
autovacuum_analyze_scale_factor           = 0.1



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



Re: slow queries on system tables

From
Michael Lewis
Date:
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.

Re: slow queries on system tables

From
PegoraroF10
Date:
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



Re: slow queries on system tables

From
Adrian Klaver
Date:
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



Re: slow queries on system tables

From
PegoraroF10
Date:
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');
reltuplesrelidschemanamerelnameseq_scanseq_tup_readidx_scanidx_tup_fetchn_tup_insn_tup_updn_tup_deln_tup_hot_updn_live_tupn_dead_tupn_mod_since_analyzelast_vacuumlast_autovacuumlast_analyzelast_autoanalyzevacuum_countautovacuum_countanalyze_countautoanalyze_count
9304751249pg_catalogpg_attribute224626158217864683398827851433992538177615287566100941549741444NULLNULLNULLNULL0000
1691861259pg_catalogpg_class55411403963181375763804106823167937092243751876254400816989156457435NULL2019-08-22 19:58:48.497317NULL2019-08-22 13:03:02.770579041501
873872610pg_catalogpg_index5263825336386254402465283845901602741142020809342081350NULLNULLNULLNULL0000
Then ... vacuum analyze pg_catalog.pg_index; vacuum analyze pg_catalog.pg_attribute; vacuum analyze pg_catalog.pg_class;
reltuplesrelidschemanamerelnameseq_scanseq_tup_readidx_scanidx_tup_fetchn_tup_insn_tup_updn_tup_deln_tup_hot_updn_live_tupn_dead_tupn_mod_since_analyzelast_vacuumlast_autovacuumlast_analyzelast_autoanalyzevacuum_countautovacuum_countanalyze_countautoanalyze_count
9405691249pg_catalogpg_attribute225506158257064691900027854304032538177615287566940569002019-08-24 09:01:26.334472NULL2019-08-24 09:01:27.169883NULL1010
1509031259pg_catalogpg_class554200239640547448638133339231694173922437518762544008150903002019-08-24 09:01:33.1308452019-08-22 19:58:48.4973172019-08-24 09:01:33.4413552019-08-22 13:03:02.770579141511
883212610pg_catalogpg_index52639943363978127424657605659022953211420208088321002019-08-24 09:01:18.080615NULL2019-08-24 09:01:18.275907NULL1010
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.