0

I have a problem where I don't understand the behaviour of the Postgresql 14.9 database planner on a partitioning table. I'm sorry if my explanation is long, but I wanted to give as many details as possible to help solve the problem. Any help would be great!

-- Background --

I'm using a 14.9 database on AWS RDS. The type of query I use most often (I'm a data analyst and it's me who creates the dashboards and applications using this data, but we don't have a dba) is to fetch all the 'test_run_id' corresponding to certain conditions of measurement sessions from a small table called 't_test_run' (80,000 rows) and then retrieve the associated values/metrics of tests from a table where all measurement results are stored and called 't_test_result' (hundred of millions of rows). So t_test_run is a sort of lookup table to retrieve data of interest in t_test_result.

As the t_test_result table has become impossible to maintain, I'd like to convert it to a partitioned table. I have therefore partitioned this t_test_result table into 't_test_result_partitioned' for testing purposes, with a PARTITION BY LIST on a field "fresh" which is TRUE or FALSE to separate recent data from older data (I have set a TRUE value for test results that are less than 6 months old because it is what I use all the time). I'm well aware that performance is rarely improved with partitioned tables, or even degraded if the planner has to scan many partitions, but I thought I'd get fairly close performance by explicitly targeting my queries on the recent partition (which would require me to change the queries embedded in my dashboards and my applications, but it's doable).

-- Problem --

When I execute a simple query that was almost instantaneous on my non-partitioned t_test_result table (even with a seq scan of t_test_run to filter test_run_location 'TJ'), I now have to wait 2 minutes even though I specify the name of the partition that corresponds to fresh = TRUE. And I don't understand the behaviour of the postgres planner because it does either a nested loop, a merge semi join or a merge join depending on the number of results returned by the CTE!

So, if I do this query on my unpartitioned table t_test_result which contains all the measurement results grouped by run of tests, which are called 'test_run_id':

WITH s AS (
      SELECT test_run_id FROM t_test_run
      WHERE test_run_location = 'TJ'
      --LIMIT 2000
)
SELECT * FROM t_test_result AS t WHERE t.test_run_id IN (SELECT * FROM s)

Explain analyze result:

Gather (actual time=3.621..10700.913 rows=92466 loops=1)
  Workers Planned: 2
  Workers Launched: 2
  Buffers: shared hit=54530 read=32071
  I/O Timings: read=17808.504
  ->  Nested Loop (actual time=2.711..8652.721 rows=30822 loops=3)
        Buffers: shared hit=54530 read=32071
        I/O Timings: read=17808.504
        ->  Parallel Seq Scan on t_test_run (actual time=0.216..111.558 rows=3859 loops=3)
              Filter: ((test_run_location)::text = 'TJ'::text)
              Rows Removed by Filter: 26173
              Buffers: shared hit=2 read=6217
              I/O Timings: read=300.924
        ->  Index Scan using i_test_result_01 on t_test_result t (actual time=1.933..2.211 rows=8 loops=11577)
              Index Cond: (test_run_id = t_test_run.test_run_id)
              Buffers: shared hit=54528 read=25854
              I/O Timings: read=17507.580
Planning:
  Buffers: shared hit=73 read=41
  I/O Timings: read=17.731
Planning Time: 26.051 ms
Execution Time: 10707.063 ms

It takes 10 secondes to get the results thanks to the index i_test_result_01 based on test_run_id

If I now do the same thing but on my partitioned table, t_test_result_partitioned, which contain an index based on the same field 'test_run_id' and target only the recent data contained in the partition 't_test_result_new' corresponding to fresh = TRUE :

WITH s AS (
      SELECT test_run_id FROM t_test_run
      WHERE test_run_location = 'TJ'
      --LIMIT 2000
)
SELECT * FROM t_test_result_new AS t WHERE t.test_run_id IN (SELECT * FROM s)

Explain analyze result:

Merge Join (actual time=1641.842..143426.127 rows=7726 loops=1)
  Merge Cond: (t.test_run_id = t_test_run.test_run_id)
  Buffers: shared hit=32861 read=9178500
  I/O Timings: read=112648.496
  ->  Index Scan using t_test_result_new_test_run_id_idx on t_test_result_new t (actual time=0.413..136127.719 rows=65077669 loops=1)
        Buffers: shared hit=32860 read=9174838
        I/O Timings: read=111477.826
  ->  Sort (actual time=1207.547..1208.471 rows=11577 loops=1)
        Sort Key: t_test_run.test_run_id
        Sort Method: quicksort  Memory: 927kB
        Buffers: shared hit=1 read=3662
        I/O Timings: read=1170.670
        ->  Bitmap Heap Scan on t_test_run (actual time=6.709..1204.264 rows=11577 loops=1)
              Recheck Cond: ((test_run_location)::text = 'TJ'::text)
              Heap Blocks: exact=3552
              Buffers: shared hit=1 read=3662
              I/O Timings: read=1170.670
              ->  Bitmap Index Scan on i_test_run_01 (actual time=5.815..5.815 rows=11590 loops=1)
                    Index Cond: ((test_run_location)::text = 'TJ'::text)
                    Buffers: shared read=104
                    I/O Timings: read=4.939
Planning:
  Buffers: shared read=9
  I/O Timings: read=3.343
Planning Time: 3.641 ms
Execution Time: 143426.654 ms

It takes now more than 2 minutes although there is just the last 6 months data in this partition! And although I have too an index: 't_test_result_new_test_run_id_idx' which is based on test_run_id...

If I now do the same thing but limiting the number of test_run_ids in the CTE to 2000...

WITH s AS (
      SELECT test_run_id FROM t_test_run
      WHERE test_run_location = 'TJ'
      LIMIT 2000
)
SELECT * FROM t_test_result_new AS t WHERE t.test_run_id IN (SELECT * FROM s)

Explain analyze result:

Nested Loop (actual time=5.009..5.010 rows=0 loops=1)
  Buffers: shared hit=8623
  ->  HashAggregate (actual time=1.707..1.995 rows=2000 loops=1)
        Group Key: t_test_run.test_run_id
        Batches: 1  Memory Usage: 241kB
        Buffers: shared hit=623
        ->  Limit (actual time=0.225..1.259 rows=2000 loops=1)
              Buffers: shared hit=623
              ->  Index Scan using i_test_run_01 on t_test_run (actual time=0.224..1.067 rows=2000 loops=1)
                    Index Cond: ((test_run_location)::text = 'TJ'::text)
                    Buffers: shared hit=623
  ->  Index Scan using t_test_result_new_test_run_id_idx on t_test_result_new t (actual time=0.001..0.001 rows=0 loops=2000)
        Index Cond: (test_run_id = t_test_run.test_run_id)
        Buffers: shared hit=8000
Planning:
  Buffers: shared hit=5
Planning Time: 0.232 ms
Execution Time: 5.063 ms

The query is now lightning fast again as before on the non-partitioned table!

If I now do the same thing, limiting the number of test_run_ids in the CTE to 5000...

Explain analyze result:

Merge Semi Join (actual time=4.605..4.607 rows=0 loops=1)
  Merge Cond: (t.test_run_id = t_test_run.test_run_id)
  Buffers: shared hit=1702
  ->  Index Scan using t_test_result_new_test_run_id_idx on t_test_result_new t (actual time=0.009..0.009 rows=1 loops=1)
        Buffers: shared hit=5
  ->  Sort (actual time=3.829..4.151 rows=5000 loops=1)
        Sort Key: t_test_run.test_run_id
        Sort Method: quicksort  Memory: 427kB
        Buffers: shared hit=1697
        ->  Limit (actual time=0.223..2.895 rows=5000 loops=1)
              Buffers: shared hit=1697
              ->  Index Scan using i_test_run_01 on t_test_run (actual time=0.223..2.419 rows=5000 loops=1)
                    Index Cond: ((test_run_location)::text = 'TJ'::text)
                    Buffers: shared hit=1697
Planning:
  Buffers: shared hit=5
Planning Time: 0.228 ms
Execution Time: 4.652 ms

It is still very fast whereas 5000 is almost half the number of test_run_id without any LIMIT statement (the CTE has 11 000 values when there is no LIMIT in it...)

From around 9000 in the LIMIT statement the planner switches to a Merge Join...

I've tried reindexing t_test_result_new_test_run_id_idx (based on test_run_id), redoing an ANALYZE on my partitioned tables, etc. I can't get any improvement in the planner's behaviour. The only way to improve things seems to be to also partition my reference table 't_test_run' on the same type of partition, only then will I find 'logical' behaviour again.

But the problem is that this t_test_run table is very complicated to partition because I have multiple dependencies on it, I have a sequence that automatically increments the test_run_id, etc. In short, I'd like to leave it alone, especially as I don't have any maintenance problems with this table (it only has 80,000 rows).

-- Questions --

  • Do you have an explanation for the behaviour of the postgres planner?
  • What solutions would be possible to improve performance without having to partition t_test_run?

Thanks for your help!

1 Answer 1

0

Well, there wasn't much of a response but I think I may finally answer myself... After a lot of experimenting (reindexing, clustering, settings changes,...) and reading of postgresql documentation, it seems that the postgresql planner in version 14 may have inconsistent behaviour in this type of case. I ended up testing an upgrade to version 15.6 then ANALYZE again the table and that solved the problem: the planner uses the partition structure of my database in a relevant way.

Result after all this upgrade/analyzes operations:

Gather (actual time=14.239..97022.341 rows=92466 loops=1)
  Workers Planned: 2
  Workers Launched: 2
  Buffers: shared hit=105515 read=22374
  I/O Timings: shared read=12792.156
  ->  Nested Loop (actual time=5.263..96842.482 rows=30822 loops=3)
        Buffers: shared hit=105515 read=22374
        I/O Timings: shared read=12792.156
        ->  Parallel Seq Scan on t_test_run (actual time=0.016..31.245 rows=3859 loops=3)
              Filter: ((test_run_location)::text = 'TJ'::text)
              Rows Removed by Filter: 26173
              Buffers: shared hit=6219
        ->  Append (actual time=0.542..1.172 rows=8 loops=11577)
              Buffers: shared hit=99296 read=22374
              I/O Timings: shared read=12792.156
              ->  Index Scan using t_test_result_old_01_test_run_id_idx on t_test_result_old_01 t_test_result_partitioned_1 (actual time=0.753..2.176 rows=8 loops=2991)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=14023 read=11071
                    I/O Timings: shared read=6374.831
              ->  Index Scan using t_test_result_old_02_test_run_id_idx on t_test_result_old_02 t_test_result_partitioned_2 (actual time=0.515..0.870 rows=8 loops=1061)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=5038 read=1881
                    I/O Timings: shared read=857.520
              ->  Index Scan using t_test_result_old_03_test_run_id_idx on t_test_result_old_03 t_test_result_partitioned_3 (actual time=0.724..1.321 rows=8 loops=1896)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=9002 read=3061
                    I/O Timings: shared read=2416.056
              ->  Index Scan using t_test_result_old_04_test_run_id_idx on t_test_result_old_04 t_test_result_partitioned_4 (actual time=0.428..0.684 rows=8 loops=791)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=3735 read=1174
                    I/O Timings: shared read=510.060
              ->  Index Scan using t_test_result_old_05_test_run_id_idx on t_test_result_old_05 t_test_result_partitioned_5 (actual time=0.469..0.905 rows=8 loops=1115)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=5246 read=1972
                    I/O Timings: shared read=967.398
              ->  Index Scan using t_test_result_old_06_test_run_id_idx on t_test_result_old_06 t_test_result_partitioned_6 (actual time=0.731..1.045 rows=8 loops=823)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=3918 read=1337
                    I/O Timings: shared read=821.033
              ->  Index Scan using t_test_result_old_07_test_run_id_idx on t_test_result_old_07 t_test_result_partitioned_7 (actual time=0.431..0.680 rows=8 loops=1301)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=6175 read=1878
                    I/O Timings: shared read=845.259
              ->  Index Scan using t_test_result_old_08_test_run_id_idx on t_test_result_old_08 t_test_result_partitioned_8 (actual time=0.033..0.059 rows=6 loops=773)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=3733
              ->  Seq Scan on t_test_result_old_09 t_test_result_partitioned_9 (actual time=0.000..0.000 rows=0 loops=542)
                    Filter: (t_test_run.test_run_id = test_run_id)
              ->  Index Scan using t_test_result_new_test_run_id_idx on t_test_result_new t_test_result_partitioned_10 (actual time=0.013..0.015 rows=1 loops=11577)
                    Index Cond: (test_run_id = t_test_run.test_run_id)
                    Buffers: shared hit=48426
Planning:
  Buffers: shared hit=645
Planning Time: 18.043 ms
Execution Time: 97057.657 ms

with a Nested Loop instead of Merge Join and a result of 9.7s instead of 143s in the 14.9 version. It is almost the same delay than with non-partitionned table which was at 10,7s. So I think it is now OK!

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.