sql: Django introspection query performance regression (still)

[timgraham]

Describe the problem

A regression is causing the following query (which Django's test suite runs quite often) to take 1-2 seconds (instead of milliseconds).

To Reproduce

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 c
LEFT JOIN pg_catalog.pg_namespace 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_catalog.pg_table_is_visible(c.oid)

Environment:

• CockroachDB version v23.1.0-alpha.8-dev-af563f889
  Build Time: 2023/04/06 20:05:50

Additional context

The same issue was reported in #93955 where performance was improved a little.

Related PRs:

• sql: improve performance of pg_foo_is_visible #94325
• builtins: mark some pg_.* builtins as strict #96397

The full Django test suite runtime is up from ~40 minutes with 22.2.x to ~1.5 hrs (though I'm not sure it's entirely attributable to this query).

Jira issue: CRDB-26663

[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-sessions (found keywords: pg_,Django)
• @rafiss (commented on sql: Django introspection query performance regression #93955)

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.}

[yuzefovich]

I think it's a GA-blocker until we triage further, cc @mgartner

[rafiss]

I believe we had previously narrowed this down to pg_table_is_visible being changed to be a pre-defined SQL function, but we should double check.

[DrewKimball]

Unless changes have been made to the descriptor cache since 22.2, this might be due to some difference between how UDFs interact with the cache and how the internal executor does it. Either way, the fix might be to improve the behavior with many uncached descriptor ids.

I loaded a database with 15000 tables similar to the example here. Running the query from this issue on that database took about 1.4s on my machine. I tried marking the builtin as volatile so it wouldn't be inlined, and that increased the time to ~3s. Running the query on 22.2.2 ranged from ~600ms to ~900ms on my machine. Fetching uncached descriptors in cachedCatalogReader.GetByIDs happens twice when the query is executed, and one of those calls takes about 1s. I tried running with this diff (which may or may not be correct):

diff --git a/pkg/sql/catalog/internal/catkv/catalog_reader_cached.go b/pkg/sql/catalog/internal/catkv/catalog_reader_cached.go
index 0f4e0e2b0d4..ea5fbdefed0 100644
--- a/pkg/sql/catalog/internal/catkv/catalog_reader_cached.go
+++ b/pkg/sql/catalog/internal/catkv/catalog_reader_cached.go
@@ -308,6 +308,9 @@ func (c *cachedCatalogReader) GetByIDs(
                ids[i], ids[numUncached] = ids[numUncached], id
                numUncached++
        }
+       if numUncached > 1000 {
+               return c.ScanAll(ctx, txn)
+       }
        if numUncached > 0 && !(c.hasScanAll && !isDescriptorRequired) {
                uncachedIDs := ids[:numUncached]
                read, err := c.cr.GetByIDs(ctx, txn, uncachedIDs, isDescriptorRequired, expectedType)

to pessimistically scan for all IDs at once if too many were uncached. ScanAll takes ~300-400ms in this case, and the resulting overall execution time on my machine was consistently ~800ms.

[rafiss]

Nice findings @DrewKimball! let me check with others on the schema team about your patch.

[rafiss]

@DrewKimball I think we can use your patch. Do you plan to push it, or would your like our team to take over?

[DrewKimball]

I'm not sure I'd want to push it as-is - I didn't do any testing to figure out whether this was a good threshold to transition to ScanAll, just picked it to trigger for my 15,000 descriptor test case. Is there any intuition about whether 1000 is really a good value or not?

[fqazi]

@DrewKimball I think we can get away with dropping it a bit lower to about ~500 descriptors and treat those as reads that need every single descriptor. I believe this is a reasonable solution shorter term and long term we need some type of caching to fix these scenarios