Improving deletes performance by limiting number of records to scan

[mateusz-sekara]

Motivation

We've noticed that Postgres has performance issues when running delete queries during reorgs. Although, the reorgs we noticed were very shallow (e.g. up to 10 blocks), Postgres wasn't able to come up with an efficient execution plan. It seems that the large number of logs in the table (~ 12kk in entire evm.logs), caused problems with estimating how many records will be fetched during that query.
Based on different experiments, applying an upper filter helps Postgres a lot. Besides that, we've also tested the brin index, but it didn't help in that case.

State of the environment during tests

=> select count(*) from evm.logs where evm_chain_id = 11155111;
 4377938
=> select count(*) from evm.log_poller_blocks where evm_chain_id = 11155111;
 100160

Deleting 100 logs from evm.logs

Lack of an upper limit impacts Postgres' query analyzer in a way in which it can't properly estimate the dataset size. Postgres decides to sequentially scan the entire index for specific evm_chain_id to gather matching logs for deletion. (upper bound limit for tests is just the latest (max) block_number from the db)

Before

=> begin;
explain analyze delete from evm.logs where evm_chain_id = 11155111 and block_number >= 5269551;
rollback;
BEGIN
                                                      QUERY PLAN
----------------------------------------------------------------------------------------------------------------------
 Delete on logs  (cost=0.00..855138.32 rows=2721241 width=6) (actual time=2645.049..2645.050 rows=0 loops=1)
   ->  Seq Scan on logs  (cost=0.00..855138.32 rows=2721241 width=6) (actual time=2638.169..2644.723 rows=87 loops=1)
         Filter: ((block_number >= 5269551) AND (evm_chain_id = '11155111'::numeric))
         Rows Removed by Filter: 12961268
 Planning Time: 0.114 ms
 Execution Time: 2645.075 ms
(6 rows)

After

=> begin;
explain analyze delete from evm.logs where evm_chain_id = 11155111 and block_number >= 5269551 and block_number <= 5269651;
rollback;
BEGIN
                                                         QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
 Delete on logs  (cost=0.56..153.09 rows=41 width=6) (actual time=0.429..0.429 rows=0 loops=1)
   ->  Index Scan using evm_logs_idx on logs  (cost=0.56..153.09 rows=41 width=6) (actual time=0.049..0.109 rows=87 loops=1)
         Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= 5269651))
 Planning Time: 0.119 ms
 Execution Time: 0.450 ms
(5 rows)

After (nested query with upper bound)

begin;
explain analyze delete from evm.logs where evm_chain_id = 11155111 and block_number >= 5269551 and block_number <= ((SELECT MAX(block_number) FROM evm.logs WHERE evm_chain_id = 11155111));
rollback;
BEGIN
                                                                                QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on logs  (cost=1295.57..75840.88 rows=21790 width=6) (actual time=0.482..0.483 rows=0 loops=1)
   InitPlan 2 (returns $1)
     ->  Result  (cost=1.18..1.19 rows=1 width=8) (actual time=0.056..0.056 rows=1 loops=1)
           InitPlan 1 (returns $0)
             ->  Limit  (cost=0.56..1.18 rows=1 width=8) (actual time=0.054..0.054 rows=1 loops=1)
                   ->  Index Only Scan Backward using evm_logs_idx on logs logs_1  (cost=0.56..2681558.66 rows=4358040 width=8) (actual time=0.053..0.053 rows=1 loops=1)
                         Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number IS NOT NULL))
                         Heap Fetches: 1
   ->  Bitmap Heap Scan on logs  (cost=1294.38..75839.69 rows=21790 width=6) (actual time=0.125..0.158 rows=87 loops=1)
         Recheck Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= $1))
         Heap Blocks: exact=9
         ->  Bitmap Index Scan on evm_logs_idx  (cost=0.00..1288.93 rows=21790 width=0) (actual time=0.114..0.114 rows=87 loops=1)
               Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= $1))
 Planning Time: 0.311 ms
 Execution Time: 0.525 ms
(15 rows)

Deleting 100 blocks from evm.log_poller_blocks

There is no big difference for evm.log_poller_block, probably because of the smaller dataset compared to logs. However, based on the query plans, you might spot that with an upper limit, it's easier for Postgres to pick the proper index, and query plan is more efficient. Also, the estimated cost during planning is lower.

Before

=> begin;

explain analyze delete from evm.log_poller_blocks where evm_chain_id = 11155111 and block_number >= 5269551;

rollback;
BEGIN
                                                                           QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on log_poller_blocks  (cost=2417.10..18855.81 rows=94114 width=6) (actual time=0.436..0.436 rows=0 loops=1)
   ->  Bitmap Heap Scan on log_poller_blocks  (cost=2417.10..18855.81 rows=94114 width=6) (actual time=0.068..0.093 rows=101 loops=1)
         Recheck Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551))
         Heap Blocks: exact=2
         ->  Bitmap Index Scan on idx_evm_log_poller_blocks_order_by_block  (cost=0.00..2393.57 rows=94114 width=0) (actual time=0.047..0.048 rows=101 loops=1)
               Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551))
 Planning Time: 0.091 ms
 Execution Time: 0.463 ms
(8 rows)

After

=> begin;

explain analyze delete from evm.log_poller_blocks where evm_chain_id = 11155111 and block_number >= 5269551 and block_number <= 5269651;

rollback;
BEGIN
                                                                             QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on log_poller_blocks  (cost=0.43..8.45 rows=1 width=6) (actual time=0.469..0.469 rows=0 loops=1)
   ->  Index Scan using idx_evm_log_poller_blocks_order_by_block on log_poller_blocks  (cost=0.43..8.45 rows=1 width=6) (actual time=0.061..0.095 rows=101 loops=1)
         Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= 5269651))
 Planning Time: 0.450 ms
 Execution Time: 0.499 ms
(5 rows)

After (nested query)

begin;
explain analyze delete from evm.log_poller_blocks where evm_chain_id = 11155111 and block_number >= 5269551 and block_number <= (select max(block_number) from evm.log_poller_blocks where evm_chain_id = 11155111);
rollback;

                                                                                                     QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on log_poller_blocks  (cost=16.01..1764.06 rows=512 width=6) (actual time=0.507..0.508 rows=0 loops=1)
   InitPlan 2 (returns $1)
     ->  Result  (cost=1.04..1.05 rows=1 width=8) (actual time=0.065..0.066 rows=1 loops=1)
           InitPlan 1 (returns $0)
             ->  Limit  (cost=0.43..1.04 rows=1 width=8) (actual time=0.063..0.064 rows=1 loops=1)
                   ->  Index Only Scan using idx_evm_log_poller_blocks_order_by_block on log_poller_blocks log_poller_blocks_1  (cost=0.43..63122.37 rows=102319 width=8) (actual time=0.062..0.062 rows=1 loops=1)
                         Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number IS NOT NULL))
                         Heap Fetches: 1
   ->  Bitmap Heap Scan on log_poller_blocks  (cost=14.96..1763.01 rows=512 width=6) (actual time=0.095..0.121 rows=101 loops=1)
         Recheck Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= $1))
         Heap Blocks: exact=2
         ->  Bitmap Index Scan on idx_evm_log_poller_blocks_order_by_block  (cost=0.00..14.83 rows=512 width=0) (actual time=0.087..0.087 rows=101 loops=1)
               Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= $1))
 Planning Time: 0.159 ms
 Execution Time: 0.546 ms
(15 rows)

[github-actions]

I see that you haven't updated any CHANGELOG files. Would it make sense to do so?

[mateusz-sekara]

Alternative approach would be to get latest block from logs in nested query (without explicit call to o.SelectLatestBlock(pg.WithQueryer(tx)))

DELETE FROM evm.logs 
   WHERE evm_chain_id = :evm_chain_id 
   AND block_number >= :start_block
   AND block_number <= (SELECT MAX(block_number) FROM evm.logs WHERE evm_chain_id = :evm_chain_id)

Seems to have similar performance, the only difference is that it's more defensive because it gets latest block from logs, instead of log_poller_block. This will handle all the cases when the block is not persisted for some reason (not sure how real this scenario is)
Previous implementation takes a block from evm.log_poller_blocks

=> begin;

explain analyze DELETE FROM evm.logs
   WHERE evm_chain_id = 11155111
   AND block_number >= 5269551
   AND block_number <= (SELECT MAX(block_number) FROM evm.logs WHERE evm_chain_id = 11155111);

rollback;
BEGIN
                                                                                QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on logs  (cost=1295.57..75840.88 rows=21790 width=6) (actual time=0.425..0.426 rows=0 loops=1)
   InitPlan 2 (returns $1)
     ->  Result  (cost=1.18..1.19 rows=1 width=8) (actual time=0.031..0.032 rows=1 loops=1)
           InitPlan 1 (returns $0)
             ->  Limit  (cost=0.56..1.18 rows=1 width=8) (actual time=0.030..0.030 rows=1 loops=1)
                   ->  Index Only Scan Backward using evm_logs_idx on logs logs_1  (cost=0.56..2681558.66 rows=4358040 width=8) (actual time=0.029..0.029 rows=1 loops=1)
                         Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number IS NOT NULL))
                         Heap Fetches: 1
   ->  Bitmap Heap Scan on logs  (cost=1294.38..75839.69 rows=21790 width=6) (actual time=0.072..0.106 rows=87 loops=1)
         Recheck Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= $1))
         Heap Blocks: exact=9
         ->  Bitmap Index Scan on evm_logs_idx  (cost=0.00..1288.93 rows=21790 width=0) (actual time=0.056..0.057 rows=87 loops=1)
               Index Cond: ((evm_chain_id = '11155111'::numeric) AND (block_number >= 5269551) AND (block_number <= $1))
 Planning Time: 0.242 ms
 Execution Time: 0.460 ms
(15 rows)

[reductionista]

Yeah, I think this way is safer... and maybe even more efficient since it's only 1 network request instead of 2.

[reductionista]

db.Exec("truncate evm.logs") would be simpler

[reductionista]

I'm really surprised that adding the bounds made a difference in the plan, as the planner is supposed to consult the pg_stats table which includes a histogram of values in each table. In principle, it should know what the range of values is in the table... I can't argue with the EXPLAIN ANALYZE though, it clearly makes a difference somehow.

[cl-sonarqube-production]

Quality Gate passed

Issues
0 New issues
0 Fixed issues
0 Accepted issues

Measures
0 Security Hotspots
100.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarQube