Message-ID: From: "davecramer (@davecramer)" To: "pgjdbc/pgjdbc" Date: Wed, 28 May 2025 20:15:43 +0000 Subject: Re: [pgjdbc/pgjdbc] issue #3511: Performance Regression in JDBC Driver 42.7.5 - getCrossReference In-Reply-To: References: List-Id: X-GitHub-Author-Login: davecramer X-GitHub-Comment-Id: 2917499831 X-GitHub-Comment-Type: issue_comment X-GitHub-Issue: 3511 X-GitHub-Repo: pgjdbc/pgjdbc X-GitHub-Type: comment X-GitHub-Url: https://github.com/pgjdbc/pgjdbc/issues/3511#issuecomment-2917499831 Content-Type: text/plain; charset=utf-8 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 ```