Обсуждение: Select on partitioned table is very slow

Dear all,

After detecting some performance issues accessing a partitioned table in a postgres database we created a simple Java test to analyse the possible causes of this problem. The test is very simple. It just creates a database connection and executes a query on a partitioned table including the partition key column in the where clause. What we expect is that the EXPLAIN ANALYZE returns a single INDEX SCAN on the child partitioned table, as reported when this *same* query is executed from the pgadmin or psql clients. What we actually get is a PARALLEL SEQ SCAN on all the tables belonging to the partition. Here some more information

Database: 

• PostgreSQL, version: 13.7

JAVA

• openjdk version "1.8.0_292"
• JDBC: PostgreSQL JDBC Driver, version: 42.4.2

TABLE DEFINITION

CREATE TABLE IF NOT EXISTS test_product_ui_partition.product_ui
(    id bigint NOT NULL DEFAULT nextval('test_product_ui_partition.product_ui_seq'::regclass),    bundle_description citext COLLATE pg_catalog."default",    bundle_distribution_path character varying COLLATE pg_catalog."default",    mission_id citext COLLATE pg_catalog."default" NOT NULL,
...    has_facets boolean,    CONSTRAINT product_ui_pkey PRIMARY KEY (id, mission_id)
) PARTITION BY LIST (mission_id);

-- Relevant indexes

CREATE INDEX IF NOT EXISTS product_ui_mission_id_idx    ON test_product_ui_partition.product_ui USING btree    (mission_id COLLATE pg_catalog."default" ASC NULLS LAST);

CREATE INDEX IF NOT EXISTS product_ui_logical_identifier_idx    ON test_product_ui_partition.product_ui USING btree    (logical_identifier COLLATE pg_catalog."default" ASC NULLS LAST)

TABLE SIZES

          Schema           |    Name         |       Type        |  Owner   | Persistence | Access method |  Size   | 
---------------------------+-----------------+-------------------+----------+-------------+---------------+---------
 test_product_ui_partition | product_ui      | partitioned table | postgres | permanent   |               | 0 bytes | 
---------------------------+-----------------+-------+----------+-------------+---------------+-------+-------------
 test_product_ui_partition | product_ui_em16 | table             | postgres | permanent   | heap          | 19 GB   | 
---------------------------+---------------+-------+----------+-------------+---------------+-------+---------------
 test_product_ui_partition | product_ui_bc   | table             | postgres | permanent   | heap          | 66 MB   | 

TEST QUERY

select logical_identifier, version_id, lastproduct    from test_product_ui_partition.product_ui pui     where pui.mission_id='urn:esa:psa:context:investigation:mission.em16'       and pui.logical_identifier='urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'

This query returns one single row

EXPLAIN ANALYZE FROM PGADMIN

Index Scan using product_ui_em16_logical_identifier_idx on product_ui_em16 pui  (cost=0.69..19.75 rows=7 width=112) (actual time=0.133..0.134 rows=1 loops=1)
[...]  Index Cond: (logical_identifier = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::citext)"
[...]  Filter: (mission_id = 'urn:esa:psa:context:investigation:mission.em16'::citext)"
Planning Time: 0.237 ms
Execution Time: 0.149 ms

EXPLAIN ANALYZE FROM JAVA TEST

class org.postgresql.jdbc.PgConnection
PostgreSQL
version: 13.7
PostgreSQL JDBC Driver
version: 42.4.2
Query: explain analyze select logical_identifier, version_id, lastproduct from test_product_ui_partition.product_ui pui where pui.mission_id='urn:esa:psa:context:investigation:mission.em16' and pui.logical_identifier='urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'
Gather  (cost=1000.00..5617399.10 rows=19 width=82) (actual time=9987.415..9999.325 rows=1 loops=1)  Workers Planned: 2  Workers Launched: 2  ->  Parallel Append  (cost=0.00..5616397.20 rows=15 width=82) (actual time=8240.465..9981.736 rows=0 loops=3)        ->  Parallel Seq Scan on product_ui_em16 pui_10  (cost=0.00..2603849.81 rows=3 width=112) (actual time=3048.850..4790.105 rows=0 loops=3)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 5337106        ->  Parallel Seq Scan on product_ui_rosetta pui_6  (cost=0.00..2382752.79 rows=1 width=57) (actual time=6070.946..6070.946 rows=0 loops=2)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 5878988        ->  Parallel Seq Scan on product_ui_mex pui_7  (cost=0.00..354434.31 rows=1 width=56) (actual time=1280.037..1280.037 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 1085822        ->  Parallel Seq Scan on product_ui_smart1 pui_8  (cost=0.00..148741.56 rows=1 width=63) (actual time=1045.532..1045.533 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 1187167        ->  Parallel Seq Scan on product_ui_vex pui_13  (cost=0.00..112914.84 rows=1 width=56) (actual time=968.542..968.542 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 1133382        ->  Parallel Seq Scan on product_ui_bc pui_9  (cost=0.00..8890.52 rows=1 width=83) (actual time=88.747..88.747 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 67763        ->  Parallel Seq Scan on product_ui_ch1 pui_2  (cost=0.00..2224.51 rows=1 width=59) (actual time=23.304..23.304 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 20345        ->  Parallel Seq Scan on product_ui_huygens pui_1  (cost=0.00..2090.82 rows=1 width=70) (actual time=21.786..21.786 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 19700        ->  Parallel Seq Scan on product_ui_ground_based pui_3  (cost=0.00..260.74 rows=1 width=75) (actual time=2.615..2.616 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 2237        ->  Parallel Seq Scan on product_ui_giotto pui_4  (cost=0.00..209.79 rows=1 width=47) (actual time=2.188..2.189 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 2129        ->  Parallel Seq Scan on product_ui_juice pui_12  (cost=0.00..13.88 rows=1 width=67) (actual time=0.132..0.132 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 100        ->  Parallel Seq Scan on product_ui_emrsp pui_11  (cost=0.00..10.26 rows=1 width=65) (actual time=0.000..0.000 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))        ->  Parallel Seq Scan on product_ui_hubble pui_5  (cost=0.00..3.29 rows=1 width=62) (actual time=0.047..0.047 rows=0 loops=1)              Filter: (((mission_id)::text = 'urn:esa:psa:context:investigation:mission.em16'::text) AND ((logical_identifier)::text = 'urn:esa:psa:em16_tgo_frd:data_raw:frd_raw_sc_n_20220729t000000-20220729t235959'::text))              Rows Removed by Filter: 33
Planning Time: 16.874 ms
Execution Time: 9999.496 ms
Elapsed: 10122 ms

Source code of the test is attached in the mail. It provides some other test cases as: 

• Query other non partitioned table, with correct performance
• Query the correct partitioned table according to the partition key column (mission_id). In this case only that table is scanned, but again, using PARALLEL SEQ SCAN and not the INDEX SCAN
  

Could you please provide any hint on the possible reasons of this behavior and the performance degradation that is affecting only the JAVA client.

Best regards,

Jose Osinde