Subject: [pgjdbc/pgjdbc] issue #3511: Performance Regression in JDBC Driver 42.7.5 - getCrossReference

From: "danielhasan (@danielhasan)" <[email-masked]>
Date: Wed, 05 Feb 2025 14:14:13 +0000

I am reporting a performance issue encountered with the JDBC driver version 42.7.5 when using the getCrossReference method from the DatabaseMetaData interface. 

Issue:
In version 42.7.5, the execution time for getCrossReference has significantly increased. Specifically, the recovery time has gone from approximately 1 second in version 42.7.4 to 15 seconds when querying against a database with 450 tables.

Steps to Reproduce:

Use JDBC driver version 42.7.5.
Call the getCrossReference method on the DatabaseMetaData instance for a schema containing 450 tables.
Observe the time taken for the operation.
Expected Behavior:
The expected response time for the getCrossReference call using version 42.7.4 is approximately 1 second.

Actual Behavior:
The actual response time in version 42.7.5 has increased to approximately 15 seconds.

Environment:

JDBC Driver Version: 42.7.5
Previous Version (for Comparison): 42.7.4
Database Size: 450 tables
Recommendation:
Please investigate the performance degradation introduced in version 42.7.5 and consider reverting any changes that may have impacted the efficiency of the getCrossReference method.

Thank you for looking into this matter.

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Wed, 05 Feb 2025 15:40:39 +0000

Thanks for reporting this. We've noticed a similar performance impact during create index statements generated via Liquibase (4.30) with the 42.7.5 driver that reverting to 42.7.4 resolves.

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Fri, 07 Feb 2025 09:00:21 +0000

Thanks for the report

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Fri, 07 Feb 2025 11:55:55 +0000

Can one of you send me your schema's to test this with? The only thing that really changed in the query is 
```
Key Differences:
First Query:

Uses NULL::text AS PKTABLE_CAT and NULL::text AS FKTABLE_CAT, meaning these columns will always be NULL.
Second Query:

Uses current_database() AS "PKTABLE_CAT" and current_database() AS "FKTABLE_CAT", meaning these columns will contain the name of the current database.
```

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Fri, 07 Feb 2025 23:48:02 +0000

I could be muddying the waters here, but he's what I can provide. We recreate our test database as part of our automated test runs and we do that mostly via Liquibase. We don't populate the tables as part of this process so all tables are empty until tests run.

Here's our slightly obfuscated Liquibase that illustrates the issue:

```
    <!-- Property
        <property name="first_table_t" value="105" />
    -->

    <changeSet id="create-sequence" author="author">
        <createSequence schemaName="schema" sequenceName="seq_first_table" minValue="1" maxValue="1099511627775" cycle="true"/>
    </changeSet>

    <changeSet id="create-table" author="author">
        <createTable schemaName="schema" tableName="first_table">
            <column name="id"
                    defaultValueComputed="schema.next_id('schema.seq_first_table', ${first_table_t}, 1)"
                    type="BIGINT">
                <constraints primaryKey="true"/>
            </column>
            <column name="second_table_id" type="BIGINT">
                <constraints foreignKeyName="first_table_second_table_id_fkey"
                             referencedTableSchemaName="schema"
                             referencedTableName="second_table"
                             referencedColumnNames="id"
                             unique="true"
                             nullable="false"/>
            </column>
            <column name="completion_date" type="TIMESTAMPTZ">
                <constraints nullable="false" />
            </column>
            <column name="created_at" type="TIMESTAMPTZ" defaultValueComputed="NOW()">
                <constraints nullable="false" />
            </column>
            <column name="created_by_id" type="BIGINT">
                <constraints foreignKeyName="first_table_created_by_id_fkey"
                             referencedTableSchemaName="schema"
                             referencedTableName="user"
                             referencedColumnNames="id"/>
            </column>
            <column name="modified_at" type="TIMESTAMPTZ" defaultValueComputed="NOW()">
                <constraints nullable="false" />
            </column>
            <column name="modified_by_id" type="BIGINT">
                <constraints foreignKeyName="first_table_modified_by_id_fkey"
                             referencedTableSchemaName="schema"
                             referencedTableName="user"
                             referencedColumnNames="id"/>
            </column>
            <column name="status" type="VARCHAR(128)">
                <constraints nullable="false" />
            </column>
            <column name="invoice_id" type="VARCHAR(64)"></column>
        </createTable>
    </changeSet>

    <!-- *** SLOW QUERY -->
    <changeSet id="fix-index" author="author">
        <preConditions onFail="MARK_RAN">
            <not>
                <indexExists schemaName="schema" tableName="first_table" indexName="first_table_modified_by_id_idx"></indexExists>
            </not>
        </preConditions>
        <createIndex schemaName="schema" tableName="first_table" indexName="first_table_modified_by_id_idx">
            <column name="modified_by_id"></column>
        </createIndex>
    </changeSet>
```

Here's our slightly obfuscated SQL output from Liquibase:

```
CREATE SEQUENCE  IF NOT EXISTS schema.seq_first_table MINVALUE 1 MAXVALUE 1099511627775 CYCLE;

CREATE TABLE schema.first_table
  (
     id              BIGINT DEFAULT schema.Next_id('schema.seq_first_table', 105, 1
     ) NOT NULL,
     second_table_id        BIGINT NOT NULL,
     completion_date TIMESTAMP WITH time zone NOT NULL,
     created_at      TIMESTAMP WITH time zone DEFAULT Now() NOT NULL,
     created_by_id   BIGINT,
     modified_at     TIMESTAMP WITH time zone DEFAULT Now() NOT NULL,
     modified_by_id  BIGINT,
     status          VARCHAR(128) NOT NULL,
     invoice_id      VARCHAR(64),
     CONSTRAINT first_table_pkey PRIMARY KEY (id),
     CONSTRAINT first_table_second_table_id_fkey FOREIGN KEY (second_table_id) REFERENCES
     schema.second_table(id),
     CONSTRAINT first_table_created_by_id_fkey FOREIGN KEY (created_by_id)
     REFERENCES schema."user"(id),
     CONSTRAINT first_table_modified_by_id_fkey FOREIGN KEY (modified_by_id)
     REFERENCES schema."user"(id),
     UNIQUE (second_table_id)
  ); 
  
 //*** SLOW QUERY
 CREATE INDEX first_table_modified_by_id_idx ON schema.first_table(modified_by_id);
```

//Output/timings with JDBC driver 42.7.4
```
Running Changeset: db.changelog-vXYZ.0.xml::create-sequence::author
[2025-02-07 18:15:21] INFO [liquibase.ui] Running Changeset: db.changelog-vXYZ.0.xml::create-sequence::author
[2025-02-07 18:15:21] INFO [liquibase.changelog] Sequence seq_first_table created
[2025-02-07 18:15:21] INFO [liquibase.changelog] ChangeSet db.changelog-vXYZ.0.xml::create-sequence::author ran successfully in 0ms
Running Changeset: db.changelog-vXYZ.0.xml::create-table::author
[2025-02-07 18:15:21] INFO [liquibase.ui] Running Changeset: db.changelog-vXYZ.0.xml::create-table::author
[2025-02-07 18:15:21] INFO [liquibase.changelog] Table first_table created
[2025-02-07 18:15:21] INFO [liquibase.changelog] ChangeSet db.changelog-vXYZ.0.xml::create-table::author ran successfully in 3ms
Running Changeset: db.changelog-vXYZ.0.xml::fix-index::author
[2025-02-07 18:15:21] INFO [liquibase.ui] Running Changeset: db.changelog-vXYZ.0.xml::fix-index::author
[2025-02-07 18:15:21] INFO [liquibase.snapshot] Creating snapshot
[2025-02-07 18:15:30] INFO [liquibase.changelog] Index first_table_modified_by_id_idx created
[2025-02-07 18:15:30] INFO [liquibase.changelog] ChangeSet db.changelog-vXYZ.0.xml::fix-index::author ran successfully in 9420ms
``` 

//Output/timings with JDBC driver 42.7.5
```
Running Changeset: db.changelog-vXYZ.0.xml::create-sequence::author
[2025-02-07 18:09:33] INFO [liquibase.ui] Running Changeset: db.changelog-vXYZ.0.xml::create-sequence::author
[2025-02-07 18:09:33] INFO [liquibase.changelog] Sequence seq_first_table created
[2025-02-07 18:09:33] INFO [liquibase.changelog] ChangeSet db.changelog-vXYZ.0.xml::create-sequence::author ran successfully in 1ms
Running Changeset: db.changelog-vXYZ.0.xml::create-table::author
[2025-02-07 18:09:33] INFO [liquibase.ui] Running Changeset: db.changelog-vXYZ.0.xml::create-table::author
[2025-02-07 18:09:33] INFO [liquibase.changelog] Table first_table created
[2025-02-07 18:09:33] INFO [liquibase.changelog] ChangeSet db.changelog-vXYZ.0.xml::create-table::author ran successfully in 2ms
Running Changeset: db.changelog-vXYZ.0.xml::fix-index::author
[2025-02-07 18:09:33] INFO [liquibase.ui] Running Changeset: db.changelog-vXYZ.0.xml::fix-index::author
[2025-02-07 18:09:33] INFO [liquibase.snapshot] Creating snapshot
[2025-02-07 18:09:54] INFO [liquibase.changelog] Index first_table_modified_by_id_idx created
[2025-02-07 18:09:54] INFO [liquibase.changelog] ChangeSet db.changelog-vXYZ.0.xml::fix-index::author ran successfully in 21515ms
```

So this index creation takes over twice as long with the newer driver. This is one of the few instances in our Liquibase where we aren't creating indexes concurrently, and via Liquibase's `<sql>` tag, so that could be a nuance.

Generally our entire schema recreation process takes 45 seconds with the 42.7.4 driver and about 1 min 30 seconds with the 42.7.5 driver.

I'm working with Postgres 16 but we've seen similar results with Postgres 15.

Hopefully this is useful. If I can provide more information let me know, but there are limits to what I'm able to share. 

Thanks for your efforts!

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Mon, 10 Feb 2025 14:26:59 +0000

Just to follow up on the above, commenting out the Liquibase preconditions where we check for index existence in the schema does seem to mitigate the performance impacts. Liquibase is deciding what mechanism to do those checks under the hood. In general those checks seem to be "expensive" relative to other DDL, but they became substantially moreso with the 42.7.5.

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Tue, 11 Feb 2025 10:48:42 +0000

Yeah, it has nothing to do with the version of postgres. We added some columns to the metadata and this caused the problems.
@SophiahHo any chance you can have a look at this ?

---

From: "SophiahHo (@SophiahHo)" <[email-masked]>
Date: Tue, 11 Feb 2025 16:31:58 +0000

The slowness is caused by the where clause now checking that the catalog name matches the current database name:  
https://github.com/pgjdbc/pgjdbc/blob/6437a20cac2d544bee36e79082bdad0a34704585/pgjdbc/src/main/java/org/postgresql/jdbc/PgDatabaseMetaData.java#L2525

Previously, this check was omitted. A check is required to avoid incorrect behaviour. For example, in the old version, if there was  a typo or inaccessible database for the `primaryCatalog` parameter, then getCrossReference would return results for the current database instead of empty results.

If you're calling getCrossReference directly for the current database, you can set `primaryCatalog` (and `foreignCatalog`) to null, and the  performance is similar to the old version.

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Mon, 17 Feb 2025 17:59:53 +0000

> [pgjdbc/pgjdbc/src/main/java/org/postgresql/jdbc/PgDatabaseMetaData.java](https://github.com/pgjdbc/pgjdbc/blob/6437a20cac2d544bee36e79082bdad0a34704585/pgjdbc/src/main/java/org/postgresql/jdbc/PgDatabaseMetaData.java#L2525)
> 
> Line 2525 in [6437a20](/pgjdbc/pgjdbc/commit/6437a20cac2d544bee36e79082bdad0a34704585)
> 
>  sql += " AND current_database() = " + escapeQuotes(primaryCatalog); 

If this is the only reason for doing this then do this without using SQL as the connection knows the database

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 07 May 2025 18:32:19 +0000

@danielhasan 
Here's the file I am using which is very similar to what you provided 
```<?xml version="1.0" encoding="utf-8" ?>
<databaseChangeLog
xmlns="http://www.liquibase.org/xml/ns/dbchangelog"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xmlns:ext="http://www.liquibase.org/xml/ns/dbchangelog-ext"
    xsi:schemaLocation="http://www.liquibase.org/xml/ns/dbchangelog http://www.liquibase.org/xml/ns/dbchangelog/dbchangelog-4.31.xsd
    http://www.liquibase.org/xml/ns/dbchangelog-ext http://www.liquibase.org/xml/ns/dbchangelog/dbchangelog-ext.xsd">

    <changeSet id="create-sequence" author="author">
        <createSequence schemaName="ts" sequenceName="seq_first_table" minValue="1" maxValue="1099511627775" cycle="true"/>
    </changeSet>
    <changeSet id="create-table" author="author">
        <createTable schemaName="ts" tableName="user">
	        <column name="id"
                    defaultValueComputed="nextval('ts.seq_first_table')"
                    type="BIGINT">
                <constraints primaryKey="true"/>
            </column>
            <column name="first" type="text"/>
            <column name="last" type="text"/>
	    </createTable>
        <createTable schemaName="ts" tableName="second_table">
            <column name="id"
                    defaultValueComputed="nextval('ts.seq_first_table')"
                    type="BIGINT">
                <constraints primaryKey="true"/>
            </column>
            
                <constraints foreignKeyName="second_table_created_by_id_fkey"
                             referencedTableSchemaName="ts"
                             referencedTableSchemaName="ts"
        
        <createTable schemaName="ts" tableName="first_table">
            <column name="id"
                    defaultValueComputed="nextval('ts.seq_first_table')"
                    type="BIGINT">
                             referencedTableSchemaName="ts"
                             referencedTableSchemaName="ts"
                             referencedTableSchemaName="ts"

    <!-- *** SLOW QUERY -->
    <changeSet id="fix-index" author="author">
        <preConditions onFail="MARK_RAN">
            <not>
                <indexExists schemaName="ts" tableName="first_table" indexName="first_table_modified_by_id_idx"></indexExists>
            </not>
        </preConditions>
        <createIndex schemaName="ts" tableName="first_table" indexName="first_table_modified_by_id_idx">
            <column name="modified_by_id"></column>
        </createIndex>
    </changeSet>
</databaseChangeLog>
```
I don't really see much difference between the 42.7.5 and 42.7.6. I certainly don't see anything taking 21 seconds

DAve

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Wed, 28 May 2025 13:58:30 +0000

@davecramer wanted to follow up now that I see `42.7.6` was released.

I've got a Liquibase changlog like so:

```
    <changeSet id="PLAT-1997-1-fkey-rename" author="rdhzl">
        <preConditions onFail="MARK_RAN">
            <!-- Ensure the expected constraint exists and the desired constraint name does not -->
            <foreignKeyConstraintExists schemaName="hippo"
                                        foreignKeyName="ext_referral_x_ext_resource_history_ext_referral_history_id_fke"
            />
            <not>
                <foreignKeyConstraintExists schemaName="hippo"
                                            foreignKeyName="erxerh_ext_referral_history_id_erh_id_fkey"
                />
            </not>
        </preConditions>
        <sql>
            <![CDATA[
                ALTER TABLE hippo.ext_referral_x_ext_resource_history
                RENAME CONSTRAINT ext_referral_x_ext_resource_history_ext_referral_history_id_fke
                TO erxerh_ext_referral_history_id_erh_id_fkey
            ]]>
        </sql>
        <rollback/> <!--declining the rollback -->
    </changeSet>
```

With the `42.7.4` version of the driver this takes approx 900ms to execute:
```
Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:18:00] INFO [liquibase.ui] Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:18:00] FINE [liquibase.changelog] Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:18:00] FINE [liquibase.executor] Changeset db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:18:01] INFO [liquibase.snapshot] Creating snapshot
[2025-05-28 09:18:01] FINE [liquibase.changelog] Reading ChangeSet: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:18:01] FINE [liquibase.executor] Executing Statement: 
ALTER TABLE hippo.ext_referral_x_ext_resource_history
                RENAME CONSTRAINT ext_referral_x_ext_resource_history_ext_referral_history_id_fke
                TO erxerh_ext_referral_history_id_erh_id_fkey
[2025-05-28 09:18:01] FINE [liquibase.executor] 
ALTER TABLE hippo.ext_referral_x_ext_resource_history
                RENAME CONSTRAINT ext_referral_x_ext_resource_history_ext_referral_history_id_fke
                TO erxerh_ext_referral_history_id_erh_id_fkey
[2025-05-28 09:18:01] INFO [liquibase.changelog] Custom SQL executed
[2025-05-28 09:18:01] INFO [liquibase.changelog] ChangeSet db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl ran successfully in 943ms
```

With versions 42.7.5/42.7.6 it takes approx 9000ms to execute, so about a 10x difference:
```
Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:15:52] INFO [liquibase.ui] Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:15:52] FINE [liquibase.changelog] Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:15:52] FINE [liquibase.executor] Changeset db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:16:02] INFO [liquibase.snapshot] Creating snapshot
[2025-05-28 09:16:02] FINE [liquibase.changelog] Reading ChangeSet: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:16:02] FINE [liquibase.executor] Executing Statement: 
ALTER TABLE hippo.ext_referral_x_ext_resource_history
                RENAME CONSTRAINT ext_referral_x_ext_resource_history_ext_referral_history_id_fke
                TO erxerh_ext_referral_history_id_erh_id_fkey
[2025-05-28 09:16:02] FINE [liquibase.executor] 
ALTER TABLE hippo.ext_referral_x_ext_resource_history
                RENAME CONSTRAINT ext_referral_x_ext_resource_history_ext_referral_history_id_fke
                TO erxerh_ext_referral_history_id_erh_id_fkey
[2025-05-28 09:16:02] INFO [liquibase.changelog] Custom SQL executed
[2025-05-28 09:16:02] INFO [liquibase.changelog] ChangeSet db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl ran successfully in 9931ms
```

FWIW: If I remove the Liquibase pre-conditions from the changelog the execution time drops to approx 1ms with any version of the driver:
```
Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:52:13] INFO [liquibase.ui] Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:52:13] FINE [liquibase.changelog] Running Changeset: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:52:13] FINE [liquibase.executor] Changeset db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:52:13] FINE [liquibase.changelog] Reading ChangeSet: db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl
[2025-05-28 09:52:13] FINE [liquibase.executor] Executing Statement: 
ALTER TABLE hippo.ext_referral_x_ext_resource_history
                RENAME CONSTRAINT ext_referral_x_ext_resource_history_ext_referral_history_id_fke
                TO erxerh_ext_referral_history_id_erh_id_fkey
[2025-05-28 09:52:13] FINE [liquibase.executor] 
ALTER TABLE hippo.ext_referral_x_ext_resource_history
                RENAME CONSTRAINT ext_referral_x_ext_resource_history_ext_referral_history_id_fke
                TO erxerh_ext_referral_history_id_erh_id_fkey
[2025-05-28 09:52:13] INFO [liquibase.changelog] Custom SQL executed
[2025-05-28 09:52:13] INFO [liquibase.changelog] ChangeSet db.changelog-v50.0.xml::PLAT-1997-1-fkey-rename::rdhzl ran successfully in 0ms
```

Given the 10x difference in perf between `42.7.4`->`42.7.5`->`42.7.6` there's anything else that might be worth considering here? If there's additional info/testing I can try to help with I'll do my best. Thanks for your time!

I'm running with Liquibase 4.32.0 against PG16. As above this happens during a complete recreation of our schema.

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 28 May 2025 15:44:55 +0000

@rdhzl Any chance you can get logs from the postgresql server for 42.7.4 and 42.7.6 ? I'd like to see what is actually being executed

---

From: "vlsi (@vlsi)" <[email-masked]>
Date: Wed, 28 May 2025 15:48:02 +0000

@rdhzl , could you share a reproducible example?

By the way, it would be great if you could extract the relevant traces (see https://jdbc.postgresql.org/documentation/logging/#enable-logging-by-using-loggingproperties-file )

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Wed, 28 May 2025 19:15:30 +0000

Thanks @davecramer and @vlsi .

I've attached logs from the server. Hopefully these are helpful, but I don't typically use PG logs so if there's something that's missing let me know what I need to change in my config. 

In each file I've run our Liquibase migrations up to one of the slower changelogs and then shut down the server (it's my own local dev instance and this is the only thing running against it). I also trimmed the log files down to two liquibase changelogs: 1. a database tag statement that immediately proceeds the slow changelog, and then the actual changelog in question. It's interesting everything that gets logged between the database tag and the actual constraint rename.  

[42.7.4-postgresql-2025-05-28_144633.log](https://github.com/user-attachments/files/20493856/42.7.4-postgresql-2025-05-28_144633.log)
[42.7.5-postgresql-2025-05-28_144941.log](https://github.com/user-attachments/files/20493857/42.7.5-postgresql-2025-05-28_144941.log)
[42.7.6-postgresql-2025-05-28_145215.log](https://github.com/user-attachments/files/20493855/42.7.6-postgresql-2025-05-28_145215.log)

@vlsi I'll see what I can do about additional traces/examples.

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 28 May 2025 19:48:48 +0000

@rdhzl any chance you can turn on log_duration in postgresql.conf ?
log_duration = on

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 28 May 2025 20:15:43 +0000

Cool so what I can see is almost a 10x regression
42.7.4
line 290 2025-05-28 14:46:41.139 EDT [89769] LOG:  execute S_1: COMMIT
line 1.     2025-05-28 14:46:40.191 EDT [89769] LOG:  execute S_3: BEGIN

total time is 948ms

42.7.5
line 290 2025-05-28 14:49:58.798 EDT [89903] LOG:  execute S_1: COMMIT
line 1.     2025-05-28 14:49:49.320 EDT [89903] LOG:  execute S_3: BEGIN
9478ms

Here are the salient differences:

1. Deployment ID Change:
   • In 42.7.4: '8457996979'
   • In 42.7.5: '8458185965'
  This appears in the database changelog entry.

2. SQL Query Format Changes:
   • In 42.7.4: The SQL queries use plain column names like TABLE_CAT, TABLE_SCHEM, etc.
   • In 42.7.5: The SQL queries use quoted column names like "TABLE_CAT", "TABLE_SCHEM", etc.

3. Database Reference Change:
   • In 42.7.4: Using NULL AS TABLE_CAT in the queries
   • In 42.7.5: Using current_database() AS "TABLE_CAT" and adding a condition current_database() = 'hippo_db_test'

Seems adding the condition is the culprit:

```
postgres=# explain analyze SELECT NULL::text AS PKTABLE_CAT, pkn.nspname AS PKTABLE_SCHEM, pkc.relname AS PKTABLE_NAME, pka.attname AS PKCOLUMN_NAME, NULL::text AS FKTABLE_CAT, fkn.nspname AS FKTABLE_SCHEM, fkc.relname AS FKTABLE_NAME, fka.attname AS FKCOLUMN_NAME, pos.n AS KEY_SEQ, CASE con.confupdtype  WHEN 'c' THEN 0 WHEN 'n' THEN 2 WHEN 'd' THEN 4 WHEN 'r' THEN 1 WHEN 'p' THEN 1 WHEN 'a' THEN 3 ELSE NULL END AS UPDATE_RULE, CASE con.confdeltype  WHEN 'c' THEN 0 WHEN 'n' THEN 2 WHEN 'd' THEN 4 WHEN 'r' THEN 1 WHEN 'p' THEN 1 WHEN 'a' THEN 3 ELSE NULL END AS DELETE_RULE, con.conname AS FK_NAME, pkic.relname AS PK_NAME, CASE  WHEN con.condeferrable AND con.condeferred THEN 5 WHEN con.condeferrable THEN 6 ELSE 7 END AS DEFERRABILITY  FROM  pg_catalog.pg_namespace pkn, pg_catalog.pg_class pkc, pg_catalog.pg_attribute pka,  pg_catalog.pg_namespace fkn, pg_catalog.pg_class fkc, pg_catalog.pg_attribute fka,  pg_catalog.pg_constraint con,  pg_catalog.generate_series(1, 32) pos(n),  pg_catalog.pg_class pkic WHERE pkn.oid = pkc.relnamespace AND pkc.oid = pka.attrelid AND pka.attnum = con.confkey[pos.n] AND con.confrelid = pkc.oid  AND fkn.oid = fkc.relnamespace AND fkc.oid = fka.attrelid AND fka.attnum = con.conkey[pos.n] AND con.conrelid = fkc.oid  AND con.contype = 'f' AND (pkic.relkind = 'i' OR pkic.relkind = 'I') AND pkic.oid = con.conindid  AND fkn.nspname = 'hippo' AND fkc.relname = 'care_program_x_visit' ORDER BY pkn.nspname,pkc.relname, con.conname,pos.n;
                                                                                 QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=37.02..37.02 rows=1 width=592) (actual time=3.696..3.698 rows=0.00 loops=1)
   Sort Key: pkn.nspname, pkc.relname, con.conname, pos.n
   Sort Method: quicksort  Memory: 25kB
   Buffers: shared hit=8 read=6
   ->  Nested Loop  (cost=1.51..37.01 rows=1 width=592) (actual time=1.425..1.427 rows=0.00 loops=1)
         Join Filter: (fkn.oid = fkc.relnamespace)
         Buffers: shared hit=2 read=3
         ->  Nested Loop  (cost=1.51..35.92 rows=1 width=460) (actual time=1.425..1.426 rows=0.00 loops=1)
               Buffers: shared hit=2 read=3
               ->  Nested Loop  (cost=1.24..35.56 rows=1 width=400) (actual time=1.425..1.426 rows=0.00 loops=1)
                     Buffers: shared hit=2 read=3
                     ->  Nested Loop  (cost=0.96..27.25 rows=1 width=355) (actual time=1.425..1.426 rows=0.00 loops=1)
                           Join Filter: (pka.attnum = con.confkey[pos.n])
                           Buffers: shared hit=2 read=3
                           ->  Function Scan on generate_series pos  (cost=0.00..0.32 rows=32 width=4) (actual time=0.013..0.015 rows=32.00 loops=1)
                           ->  Materialize  (cost=0.96..25.50 rows=3 width=385) (actual time=0.044..0.044 rows=0.00 loops=32)
                                 Storage: Memory  Maximum Storage: 17kB
                                 Buffers: shared hit=2 read=3
                                 ->  Nested Loop  (cost=0.96..25.48 rows=3 width=385) (actual time=1.399..1.400 rows=0.00 loops=1)
                                       Buffers: shared hit=2 read=3
                                       ->  Nested Loop  (cost=0.68..24.34 rows=1 width=327) (actual time=1.399..1.399 rows=0.00 loops=1)
                                             Buffers: shared hit=2 read=3
                                             ->  Nested Loop  (cost=0.40..15.95 rows=1 width=267) (actual time=1.399..1.399 rows=0.00 loops=1)
                                                   Buffers: shared hit=2 read=3
                                                   ->  Nested Loop  (cost=0.27..15.75 rows=1 width=207) (actual time=1.399..1.399 rows=0.00 loops=1)
                                                         Buffers: shared hit=2 read=3
                                                         ->  Seq Scan on pg_constraint con  (cost=0.00..7.43 rows=1 width=135) (actual time=1.398..1.398 rows=0.00 loops=1)
                                                               Filter: (contype = 'f'::"char")
                                                               Rows Removed by Filter: 194
                                                               Buffers: shared hit=2 read=3
                                                         ->  Index Scan using pg_class_oid_index on pg_class pkc  (cost=0.27..8.29 rows=1 width=72) (never executed)
                                                               Index Cond: (oid = con.confrelid)
                                                               Index Searches: 0
                                                   ->  Index Scan using pg_namespace_oid_index on pg_namespace pkn  (cost=0.13..0.18 rows=1 width=68) (never executed)
                                                         Index Cond: (oid = pkc.relnamespace)
                                                         Index Searches: 0
                                             ->  Index Scan using pg_class_oid_index on pg_class pkic  (cost=0.27..8.30 rows=1 width=68) (never executed)
                                                   Index Cond: (oid = con.conindid)
                                                   Filter: ((relkind = 'i'::"char") OR (relkind = 'I'::"char"))
                                                   Index Searches: 0
                                       ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute pka  (cost=0.28..1.06 rows=8 width=70) (never executed)
                                             Index Cond: (attrelid = pkc.oid)
                                             Index Searches: 0
                     ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute fka  (cost=0.28..8.30 rows=1 width=70) (never executed)
                           Index Cond: ((attrelid = con.conrelid) AND (attnum = (con.conkey)[pos.n]))
                           Index Searches: 0
               ->  Index Scan using pg_class_oid_index on pg_class fkc  (cost=0.27..0.32 rows=1 width=72) (never executed)
                     Index Cond: (oid = fka.attrelid)
                     Filter: (relname = 'care_program_x_visit'::name)
                     Index Searches: 0
         ->  Seq Scan on pg_namespace fkn  (cost=0.00..1.05 rows=1 width=68) (never executed)
               Filter: (nspname = 'hippo'::name)
 Planning:
   Buffers: shared hit=53
 Planning Time: 5.336 ms
 Execution Time: 3.806 ms
(56 rows)
```
```
postgres=# explain analyze SELECT current_database() AS "PKTABLE_CAT", pkn.nspname AS "PKTABLE_SCHEM", pkc.relname AS "PKTABLE_NAME", pka.attname AS "PKCOLUMN_NAME", current_database() AS "FKTABLE_CAT", fkn.nspname AS "FKTABLE_SCHEM", fkc.relname AS "FKTABLE_NAME", fka.attname AS "FKCOLUMN_NAME", pos.n AS "KEY_SEQ", CASE con.confupdtype  WHEN 'c' THEN 0 WHEN 'n' THEN 2 WHEN 'd' THEN 4 WHEN 'r' THEN 1 WHEN 'p' THEN 1 WHEN 'a' THEN 3 ELSE NULL END AS "UPDATE_RULE", CASE con.confdeltype  WHEN 'c' THEN 0 WHEN 'n' THEN 2 WHEN 'd' THEN 4 WHEN 'r' THEN 1 WHEN 'p' THEN 1 WHEN 'a' THEN 3 ELSE NULL END AS "DELETE_RULE", con.conname AS "FK_NAME", pkic.relname AS "PK_NAME", CASE  WHEN co                                                                                       "DEFERRABILITY"  FROM  pg_catalog.pg_namespace pkn, pg_catalog.pg_class pkc, pg_catalog.pg_attribute pka,  pg_catalog.pg_names                                                                                                                                                             s pkic WHERE pkn.oid = pkc.relnamespace AND pkc.oid = pka.attrelid AND pka.attnum = con.confkey[pos.n] AND con.confrelid = pkc.oid  AND fkn.oid = fkc.relnamespace AND fkc.oid = fka.attrelid AND fka.attnum = con.conkey[pos.n] AND con.conrelid = fkc.oid  AND con.contype = 'f' AND (pkic.relkind = 'i' OR pkic.relkind = 'I') AND pkic.oid = con.conindid  AND current_database() = 'hippo_db_test' AND fkn.nspname = 'hippo' AND fkc.relname = 'care_program_x_visit' ORDER BY pkn.nspname,pkc.relname, con.conname,pos.n;
                                                                                QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=36.99..36.99 rows=1 width=656) (actual time=0.299..0.301 rows=0.00 loops=1)
   Sort Key: pkn.nspname, pkc.relname, con.conname, pos.n
   Sort Method: quicksort  Memory: 25kB
   ->  Result  (cost=1.51..36.98 rows=1 width=656) (actual time=0.293..0.295 rows=0.00 loops=1)
         One-Time Filter: (current_database() = 'hippo_db_test'::name)
         ->  Nested Loop  (cost=1.51..36.94 rows=1 width=520) (never executed)
               ->  Nested Loop  (cost=1.38..36.75 rows=1 width=460) (never executed)
                     Join Filter: (fkn.oid = fkc.relnamespace)
                     ->  Nested Loop  (cost=1.11..36.42 rows=1 width=408) (never executed)
                           ->  Nested Loop  (cost=0.83..28.12 rows=1 width=363) (never executed)
                                 Join Filter: (pka.attnum = con.confkey[pos.n])
                                 ->  Function Scan on generate_series pos  (cost=0.00..0.32 rows=32 width=4) (never executed)
                                 ->  Materialize  (cost=0.83..26.36 rows=3 width=393) (never executed)
                                       ->  Nested Loop  (cost=0.83..26.35 rows=3 width=393) (never executed)
                                             ->  Nested Loop  (cost=0.55..25.21 rows=1 width=335) (never executed)
                                                   ->  Nested Loop  (cost=0.27..16.81 rows=1 width=275) (never executed)
                                                         ->  Nested Loop  (cost=0.27..15.75 rows=1 width=207) (never executed)
                                                               ->  Seq Scan on pg_constraint con  (cost=0.00..7.43 rows=1 width=135) (never executed)
                                                                     Filter: (contype = 'f'::"char")
                                                               ->  Index Scan using pg_class_oid_index on pg_class pkc  (cost=0.27..8.29 rows=1 width=72) (never executed)
                                                                     Index Cond: (oid = con.confrelid)
                                                                     Index Searches: 0
                                                         ->  Seq Scan on pg_namespace fkn  (cost=0.00..1.05 rows=1 width=68) (never executed)
                                                               Filter: (nspname = 'hippo'::name)
                                                   ->  Index Scan using pg_class_oid_index on pg_class pkic  (cost=0.27..8.30 rows=1 width=68) (never executed)
                                                         Index Cond: (oid = con.conindid)
                                                         Filter: ((relkind = 'i'::"char") OR (relkind = 'I'::"char"))
                                                         Index Searches: 0
                                             ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute pka  (cost=0.28..1.06 rows=8 width=70) (never executed)
                                                   Index Cond: (attrelid = pkc.oid)
                                                   Index Searches: 0
                           ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute fka  (cost=0.28..8.30 rows=1 width=70) (never executed)
                                 Index Cond: ((attrelid = con.conrelid) AND (attnum = (con.conkey)[pos.n]))
                                 Index Searches: 0
                     ->  Index Scan using pg_class_oid_index on pg_class fkc  (cost=0.27..0.32 rows=1 width=72) (never executed)
                           Index Cond: (oid = fka.attrelid)
                           Filter: (relname = 'care_program_x_visit'::name)
                           Index Searches: 0
               ->  Index Scan using pg_namespace_oid_index on pg_namespace pkn  (cost=0.13..0.18 rows=1 width=68) (never executed)
                     Index Cond: (oid = pkc.relnamespace)
                     Index Searches: 0
 Planning:
   Buffers: shared hit=53
 Planning Time: 53.300 ms
 Execution Time: 0.369 ms
```

---

From: "vlsi (@vlsi)" <[email-masked]>
Date: Wed, 28 May 2025 20:20:10 +0000

It is strange adding the filter impacts the plan in such a way, however, it looks like I've made the same change in https://github.com/pgjdbc/pgjdbc/pull/3641, and I get 40ms->4ms boost on my machine.

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Wed, 28 May 2025 20:21:25 +0000

@davecramer / @vlsi Awesome analysis. Is there still value in the jdbc driver logs and the revised postgres logs with duration=on or do you think you have what you need? Thanks again!

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 28 May 2025 21:22:52 +0000

@rdhzl no, we're good. Thanks for the logs.

---

From: "adamsaghy (@adamsaghy)" <[email-masked]>
Date: Fri, 12 Sep 2025 21:48:45 +0000

Any news on this? Due to the recent CVE-2025-49146, i am about to upgrade from 42.7.4 to 42.7.7, but i am not yet confident performance regression wont be an issue anymore...

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 17 Sep 2025 10:00:54 +0000

I'm working on a release, should be in the next few days that should address this

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Fri, 19 Sep 2025 14:20:58 +0000

This appears to be addressed via: https://github.com/pgjdbc/pgjdbc/releases/tag/REL42.7.8

---

From: "rdhzl (@rdhzl)" <[email-masked]>
Date: Fri, 19 Sep 2025 14:48:11 +0000

Thanks @vlsi and @davecramer for your efforts on this!

---

From: "IOhacker (@IOhacker)" <[email-masked]>
Date: Mon, 06 Oct 2025 02:39:15 +0000

@adamsaghy fyi