pg_table_is_visible slower in CockroachDB 23.1

[timgraham]

Describe the problem

The Django test suite takes 60-65 minutes with CockraochDB 23.1.x compared to 40-45 minutes with CockroachDB 22.2.x. Some attempts at improving performance were #93955 and #100871 but the issue remains.

To Reproduce

Running the inspectdb Django test app as an example (./runtests.py inspectdb --settings=test_roach), the run time went from 31 seconds in 22.2.x to 40 seconds with 23.1.x. I turned on slow query logging to 1ms to log all queries. Then I wrote a script to parse the logs and group similar queries. 8 seconds of the 9-second performance difference are attributed to five groups of queries that use pg_table_is_visible.

Queries that include pg_table_is_visible when running inspectdb test app:

      Statement      | 23.1.x seconds | 22.1.x seconds | Query Count |
SELECT ‹c›.‹conname› |          20.55 |          14.24 |         108 | 
SELECT ‹indexname›,  |          12.66 |          11.80 |         108 | 
SELECT ‹a›.‹attname› |           3.65 |           1.47 |          47 |
SELECT ‹c›.‹relname› |           2.15 |           0.94 |          35 | 
SELECT ‹a1›.‹attname |           1.94 |           0.30 |          47 |

Full queries:

SELECT ‹c›.‹relname›, CASE WHEN ‹c›.‹relispartition› THEN ‹'p'› WHEN ‹c›.‹relkind› IN (‹'m'›, ‹'v'›) THEN ‹'v'› ELSE ‹'t'› END, ‹''› FROM pg_catalog.pg_class AS ‹c› LEFT JOIN pg_catalog.pg_namespace AS ‹n› ON ‹n›.‹oid› = ‹c›.‹relnamespace› WHERE ((‹c›.‹relkind› IN (‹'f'›, ‹'m'›, ‹'p'›, ‹'r'›, ‹'v'›)) AND (‹n›.‹nspname› NOT IN (‹‹'pg_catalog'››, ‹‹'pg_toast'››))) AND pg_table_is_visible(‹c›.‹oid›)
SELECT ‹a1›.‹attname›, ‹c2›.‹relname›, ‹a2›.‹attname› FROM ‹""›.‹""›.‹pg_constraint› AS ‹con› LEFT JOIN ‹""›.‹""›.‹pg_class› AS ‹c1› ON ‹con›.‹conrelid› = ‹c1›.‹oid› LEFT JOIN ‹""›.‹""›.‹pg_class› AS ‹c2› ON ‹con›.‹confrelid› = ‹c2›.‹oid› LEFT JOIN ‹""›.‹""›.‹pg_attribute› AS ‹a1› ON (‹c1›.‹oid› = ‹a1›.‹attrelid›) AND (‹a1›.‹attnum› = ‹con›.‹conkey›[‹1›]) LEFT JOIN ‹""›.‹""›.‹pg_attribute› AS ‹a2› ON (‹c2›.‹oid› = ‹a2›.‹attrelid›) AND (‹a2›.‹attnum› = ‹con›.‹confkey›[‹1›]) WHERE (((‹c1›.‹relname› = ‹'inspectdb_charfielddbcollation'›) AND (‹con›.‹contype› = ‹'f'›)) AND (‹c1›.‹relnamespace› = ‹c2›.‹relnamespace›)) AND pg_table_is_visible(‹c1›.‹oid›)
SELECT ‹c›.‹conname›, ARRAY (SELECT ‹attname› FROM ROWS FROM (unnest(‹c›.‹conkey›)) WITH ORDINALITY AS ‹cols› (‹colid›, ‹arridx›) JOIN ‹""›.‹""›.‹pg_attribute› AS ‹ca› ON ‹cols›.‹colid› = ‹ca›.‹attnum› WHERE ‹ca›.‹attrelid› = ‹c›.‹conrelid› ORDER BY ‹cols›.‹arridx›), ‹c›.‹contype›, (SELECT (‹fkc›.‹relname› || ‹'.'›) || ‹fka›.‹attname› FROM ‹""›.‹""›.‹pg_attribute› AS ‹fka› JOIN ‹""›.‹""›.‹pg_class› AS ‹fkc› ON ‹fka›.‹attrelid› = ‹fkc›.‹oid› WHERE (‹fka›.‹attrelid› = ‹c›.‹confrelid›) AND (‹fka›.‹attnum› = ‹c›.‹confkey›[‹1›])), ‹cl›.‹reloptions› FROM ‹""›.‹""›.‹pg_constraint› AS ‹c› JOIN ‹""›.‹""›.‹pg_class› AS ‹cl› ON ‹c›.‹conrelid› = ‹cl›.‹oid› WHERE (‹cl›.‹relname› = ‹'inspectdb_charfielddbcollation'›) AND pg_table_is_visible(‹cl›.‹oid›)
SELECT ‹indexname›, array_agg(‹attname› ORDER BY ‹arridx›), ‹indisunique›, ‹indisprimary›, array_agg(‹ordering› ORDER BY ‹arridx›), ‹amname›, ‹exprdef›, ‹s2›.‹attoptions› FROM (SELECT ‹c2›.‹relname› AS ‹indexname›, ‹idx›.*, ‹attr›.‹attname›, ‹am›.‹amname›, CASE WHEN ‹idx›.‹indexprs› IS NOT NULL THEN pg_get_indexdef(‹idx›.‹indexrelid›) END AS ‹exprdef›, CASE ‹am›.‹amname› WHEN ‹'prefix'› THEN CASE (‹option› & ‹1›) WHEN ‹1› THEN ‹'DESC'› ELSE ‹'ASC'› END END AS ‹ordering›, ‹c2›.‹reloptions› AS ‹attoptions› FROM (SELECT * FROM ‹""›.‹""›.‹pg_index› AS ‹i›, ROWS FROM (unnest(‹i›.‹indkey›, ‹i›.‹indoption›)) WITH ORDINALITY AS ‹koi› (‹key›, ‹option›, ‹arridx›)) AS ‹idx› LEFT JOIN ‹""›.‹""›.‹pg_class› AS ‹c› ON ‹idx›.‹indrelid› = ‹c›.‹oid› LEFT JOIN ‹""›.‹""›.‹pg_class› AS ‹c2› ON ‹idx›.‹indexrelid› = ‹c2›.‹oid› LEFT JOIN ‹""›.‹""›.‹pg_am› AS ‹am› ON ‹c2›.‹relam› = ‹am›.‹oid› LEFT JOIN ‹""›.‹""›.‹pg_attribute› AS ‹attr› ON (‹attr›.‹attrelid› = ‹c›.‹oid›) AND (‹attr›.‹attnum› = ‹idx›.‹key›) WHERE (‹c›.‹relname› = ‹'inspectdb_charfielddbcollation'›) AND pg_table_is_visible(‹c›.‹oid›)) AS ‹s2› GROUP BY ‹indexname›, ‹indisunique›, ‹indisprimary›, ‹amname›, ‹exprdef›, ‹attoptions›
SELECT ‹a›.‹attname› AS ‹column_name›, NOT (‹a›.‹attnotnull› OR ((‹t›.‹typtype› = ‹'d'›) AND ‹t›.‹typnotnull›)) AS ‹is_nullable›, pg_get_expr(‹ad›.‹adbin›, ‹ad›.‹adrelid›) AS ‹column_default›, CASE WHEN ‹collname› = ‹'default'› THEN ‹NULL› ELSE ‹collname› END AS ‹collation›, ‹a›.‹attidentity› != ‹''› AS ‹is_autofield›, col_description(‹a›.‹attrelid›, ‹a›.‹attnum›) AS ‹column_comment› FROM ‹""›.‹""›.‹pg_attribute› AS ‹a› LEFT JOIN ‹""›.‹""›.‹pg_attrdef› AS ‹ad› ON (‹a›.‹attrelid› = ‹ad›.‹adrelid›) AND (‹a›.‹attnum› = ‹ad›.‹adnum›) LEFT JOIN ‹""›.‹""›.‹pg_collation› AS ‹co› ON ‹a›.‹attcollation› = ‹co›.‹oid› JOIN ‹""›.‹""›.‹pg_type› AS ‹t› ON ‹a›.‹atttypid› = ‹t›.‹oid› JOIN ‹""›.‹""›.‹pg_class› AS ‹c› ON ‹a›.‹attrelid› = ‹c›.‹oid› JOIN ‹""›.‹""›.‹pg_namespace› AS ‹n› ON ‹c›.‹relnamespace› = ‹n›.‹oid› WHERE (((‹c›.‹relkind› IN (‹'f'›, ‹'m'›, ‹'p'›, ‹'r'›, ‹'v'›)) AND (‹c›.‹relname› = ‹'inspectdb_charfielddbcollation'›)) AND (‹n›.‹nspname› NOT IN (‹‹'pg_catalog'››, ‹‹'pg_toast'››))) AND pg_table_is_visible(‹c›.‹oid›)

Environment:

• CockroachDB version v23.2.0-alpha built 2023/07/25 and v22.2.12

Jira issue: CRDB-30428

[blathers-crl]

Hello, I am Blathers. I am here to help you get the issue triaged.

Hoot - a bug! Though bugs are the bane of my existence, rest assured the wretched thing will get the best of care here.

I have CC'd a few people who may be able to assist you:

• @cockroachdb/sql-foundations (found keywords: pg_,Django)
• @yuzefovich (commented on sql: Django introspection query performance regression (still) #100871)
• @rafiss (commented on sql: Django introspection query performance regression (still) #100871, commented on sql: Django introspection query performance regression #93955)
• @DrewKimball (commented on sql: Django introspection query performance regression (still) #100871)
• @fqazi (assigned to sql: Django introspection query performance regression (still) #100871)

If we have not gotten back to your issue within a few business days, you can try the following:

• Join our community slack channel and ask on #cockroachdb.
• Try find someone from here if you know they worked closely on the area and CC them.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.}

[DrewKimball]

Would it be possible to see the entire statements that are slow?

[timgraham]

I've added them in the issue description.

[DrewKimball]

Disabling the join hint in the pg_table_is_visible SQL body caused execution time on my machine to go from ~50ms for each query to 20-30ms. We can remove the join hints for the builtin functions that are expected to be inlined, but I think we should also consider ignoring join hints for functions that are inlined.

[rafiss]

Disabling the join hint in the pg_table_is_visible SQL body caused execution time on my machine to go from ~50ms for each query to 20-30ms.

@DrewKimball could you say more about how you tested that? I tried the change in this draft PR #109377, and did not see much difference.

From runnning N=10 BENCHTIMEOUT=24h PKG=./pkg/bench/rttanalysis/ BENCHES=BenchmarkORMQueries/django ./scripts/bench 'HEAD^' 'HEAD'

goos: darwin
goarch: arm64
                                                         │ ./previous  │               ./new                │
                                                         │   sec/op    │   sec/op     vs base               │
ORMQueries/django_column_introspection_1_table-10          14.95m ± 2%   14.69m ± 1%  -1.78% (p=0.005 n=10)
ORMQueries/django_column_introspection_4_tables-10         14.65m ± 5%   14.71m ± 1%       ~ (p=0.631 n=10)
ORMQueries/django_column_introspection_8_tables-10         15.15m ± 2%   15.07m ± 3%       ~ (p=0.684 n=10)
ORMQueries/django_table_introspection_1_table-10           20.20m ± 3%   19.67m ± 2%  -2.60% (p=0.023 n=10)
ORMQueries/django_table_introspection_8_tables-10          20.49m ± 3%   20.26m ± 2%       ~ (p=0.165 n=10)
ORMQueries/django_comment_introspection_with_comments-10   24.19m ± 1%   24.30m ± 2%       ~ (p=0.529 n=10)
geomean                                                    17.93m        17.78m       -0.85%

                                                         │ ./previous │                ./new                │
                                                         │ roundtrips │ roundtrips  vs base                 │
ORMQueries/django_column_introspection_1_table-10          4.000 ± 0%   4.000 ± 0%       ~ (p=1.000 n=10) ¹
ORMQueries/django_column_introspection_4_tables-10         4.000 ± 0%   4.000 ± 0%       ~ (p=1.000 n=10) ¹
ORMQueries/django_column_introspection_8_tables-10         4.000 ± 0%   4.000 ± 0%       ~ (p=1.000 n=10) ¹
ORMQueries/django_table_introspection_1_table-10           5.000 ± 0%   5.000 ± 0%       ~ (p=1.000 n=10) ¹
ORMQueries/django_table_introspection_8_tables-10          5.000 ± 0%   5.000 ± 0%       ~ (p=1.000 n=10) ¹
ORMQueries/django_comment_introspection_with_comments-10   5.000 ± 0%   5.000 ± 0%       ~ (p=1.000 n=10) ¹
geomean                                                    4.472        4.472       +0.00%
¹ all samples are equal

                                                         │  ./previous  │                ./new                │
                                                         │     B/op     │     B/op      vs base               │
ORMQueries/django_column_introspection_1_table-10          10.05Mi ± 1%   10.11Mi ± 1%       ~ (p=0.353 n=10)
ORMQueries/django_column_introspection_4_tables-10         9.019Mi ± 1%   9.010Mi ± 2%       ~ (p=0.971 n=10)
ORMQueries/django_column_introspection_8_tables-10         7.760Mi ± 3%   7.724Mi ± 1%       ~ (p=0.315 n=10)
ORMQueries/django_table_introspection_1_table-10           12.55Mi ± 1%   12.48Mi ± 1%       ~ (p=0.089 n=10)
ORMQueries/django_table_introspection_8_tables-10          10.21Mi ± 1%   10.28Mi ± 2%       ~ (p=0.280 n=10)
ORMQueries/django_comment_introspection_with_comments-10   14.56Mi ± 1%   14.39Mi ± 1%  -1.20% (p=0.023 n=10)
geomean                                                    10.46Mi        10.45Mi       -0.17%

                                                         │ ./previous  │               ./new                │
                                                         │  allocs/op  │  allocs/op   vs base               │
ORMQueries/django_column_introspection_1_table-10          102.3k ± 1%   102.2k ± 1%       ~ (p=0.912 n=10)
ORMQueries/django_column_introspection_4_tables-10         88.80k ± 1%   88.58k ± 2%       ~ (p=0.684 n=10)
ORMQueries/django_column_introspection_8_tables-10         73.19k ± 2%   72.48k ± 2%       ~ (p=0.247 n=10)
ORMQueries/django_table_introspection_1_table-10           120.6k ± 1%   120.6k ± 1%       ~ (p=0.218 n=10)
ORMQueries/django_table_introspection_8_tables-10          92.54k ± 1%   93.32k ± 3%       ~ (p=0.393 n=10)
ORMQueries/django_comment_introspection_with_comments-10   128.8k ± 2%   126.5k ± 1%  -1.77% (p=0.005 n=10)
geomean                                                    99.24k        98.87k       -0.37%

[DrewKimball]

@DrewKimball could you say more about how you tested that? I tried the change in this draft PR #109377, and did not see much difference.

I just ran them manually on a local cluster on my machine - I didn't know we already had them in a benchmark. Though, I'm not sure that the benchmark is reproducing the issue, 14.95m means ms right? I'm guessing the slowness of these queries depends on the actual content of the tables involved.

[rafiss]

I'm guessing the slowness of these queries depends on the actual content of the tables involved.

Yeah maybe. Do you remember what you did manually in your local cluster to manifest this slowness?

[DrewKimball]

Yeah maybe. Do you remember what you did manually in your local cluster to manifest this slowness?

I didn't do anything in particular, but at the time I would have likely had the tpcc and tpch databases loaded. So, it might come down to the number and complexity of tables?