CCIP-1053 Replace filtering by created_at with filtering by block_timestamp

[mateusz-sekara]

Context

Sorting by created_at in LogPoller’s queries is invalid because created_at is generated when inserting a block into the database, this might be a problem when:

• node needs to backfill data and will assign now() to all logs from the past - this might end up in processing the wrong records
• nodes will get different values from LogPoller, because they have different clocks. This might cause problems with consensus agreement
• node with a misconfigured clock will get completely wrong values

Although it sounds like an edge case, impact of this might be very high.

Solution

Instead of sorting by created_at, we should sort by the block_timestamp. We can run one small subquery that picks block_number based on the timestamp and use it for filtering. This should save us some latency. Moreover, block_timestamp is initialized on the chain so every node running code should get the same values.

The first implementation was done here, but it lacks detailed testing, so we decided to start from scratch

Tests

Current query performance (match up to 10k records)

We should not make it worse by introducing new query

explain analyze SELECT * FROM evm.logs 
			WHERE evm_chain_id = 1
			AND address = '\xbbbb' 
			AND event_sig = '\xaaaa'
			AND created_at > '1990-10-10'
			AND block_number <= (SELECT COALESCE(block_number, 0) 
													FROM evm.log_poller_blocks 
													WHERE evm_chain_id = 1
												  ORDER BY block_number DESC LIMIT 1) - 10
      ORDER BY created_at;

Sort  (cost=109.77..109.84 rows=27 width=245) (actual time=15.964..19.550 rows=9770 loops=1)
   Sort Key: logs.created_at
   Sort Method: quicksort  Memory: 2928kB
   InitPlan 1 (returns $0)
     ->  Limit  (cost=0.43..0.57 rows=1 width=16) (actual time=0.076..0.078 rows=1 loops=1)
           ->  Index Only Scan Backward using log_poller_blocks_pkey on log_poller_blocks  (cost=0.43..96462.80 rows=663400 width=16) (actual time=0.074..0.074 rows=1 loops=1)
                 Index Cond: (evm_chain_id = '1'::numeric)
                 Heap Fetches: 1
   ->  Index Scan using idx_evm_logs_ordered_by_block_and_created_at on logs  (cost=0.55..108.56 rows=27 width=245) (actual time=0.170..11.445 rows=9770 loops=1)
         Index Cond: ((evm_chain_id = '1'::numeric) AND (address = '\xbbbb'::bytea) AND (event_sig = '\xaaaa'::bytea) AND (block_number <= ($0 - 10)) AND (created_at > '1990-10-10 00:00:00+00'::timestamp with time zone))
 Planning Time: 0.533 ms
 Execution Time: 20.109 ms
(12 rows)

Nested query performance - match everything

explain analyze SELECT min(block_number), max(block_number)
FROM evm.log_poller_blocks 
WHERE evm_chain_id = 1
AND block_timestamp > '1900-10-10';

Result  (cost=1.17..1.18 rows=1 width=16) (actual time=0.078..0.078 rows=1 loops=1)
   InitPlan 1 (returns $0)
     ->  Limit  (cost=0.43..0.58 rows=1 width=8) (actual time=0.040..0.041 rows=1 loops=1)
           ->  Index Scan using log_poller_blocks_pkey on log_poller_blocks  (cost=0.43..103125.49 rows=663534 width=8) (actual time=0.038..0.038 rows=1 loops=1)
                 Index Cond: ((block_number IS NOT NULL) AND (evm_chain_id = '1'::numeric))
                 Filter: (block_timestamp > '1900-10-10 00:00:00+00'::timestamp with time zone)
   InitPlan 2 (returns $1)
     ->  Limit  (cost=0.43..0.58 rows=1 width=8) (actual time=0.028..0.029 rows=1 loops=1)
           ->  Index Scan Backward using log_poller_blocks_pkey on log_poller_blocks log_poller_blocks_1  (cost=0.43..103125.49 rows=663534 width=8) (actual time=0.028..0.028 rows=1 loops=1)
                 Index Cond: ((block_number IS NOT NULL) AND (evm_chain_id = '1'::numeric))
                 Filter: (block_timestamp > '1900-10-10 00:00:00+00'::timestamp with time zone)
 Planning Time: 0.717 ms
 Execution Time: 0.125 ms
(13 rows)

Nested query performance - match nothing

explain analyze SELECT min(block_number), max(block_number)
FROM evm.log_poller_blocks
WHERE evm_chain_id = 1
AND block_timestamp > '2050-10-10';

Aggregate  (cost=254.41..254.42 rows=1 width=16) (actual time=0.033..0.033 rows=1 loops=1)
   ->  Index Scan using idx_block_tm on log_poller_blocks  (cost=0.43..254.08 rows=66 width=8) (actual time=0.029..0.029 rows=0 loops=1)
         Index Cond: ((evm_chain_id = '1'::numeric) AND (block_timestamp > '2050-10-10 00:00:00+00'::timestamp with time zone))
 Planning Time: 0.377 ms
 Execution Time: 0.064 ms

Main query performance - up to 10k records matched

explain analyze SELECT * FROM evm.logs
         WHERE evm_chain_id = 1
         AND address = '\xbbbb'
         AND event_sig = '\xaaaa'
         AND block_number > 0
      AND block_number < 1000000
      ORDER BY (block_number, log_index);

Sort  (cost=27.63..27.64 rows=6 width=277) (actual time=17.116..17.576 rows=10000 loops=1)
   Sort Key: (ROW(block_number, log_index))
   Sort Method: quicksort  Memory: 2989kB
   ->  Index Scan using idx_evm_logs_ordered_by_block_and_created_at on logs  (cost=0.55..27.55 rows=6 width=277) (actual time=0.060..10.289 rows=10000 loops=1)
         Index Cond: ((evm_chain_id = '1'::numeric) AND (address = '\xbbbb'::bytea) AND (event_sig = '\xaaaa'::bytea) AND (block_number > 0) AND (block_number < 1000000))
 Planning Time: 0.286 ms
 Execution Time: 19.174 ms
(7 rows)

Go bench results

New query
BenchmarkSelectAfterQueries
BenchmarkSelectAfterQueries-12    	      79	  14467364 ns/op
BenchmarkSelectAfterQueries-12    	      82	  14312742 ns/op
BenchmarkSelectAfterQueries-12    	      75	  16772204 ns/op
BenchmarkSelectAfterQueries-12    	      82	  14268350 ns/op
BenchmarkSelectAfterQueries-12    	      82	  14590665 ns/op

Old query
BenchmarkSelectAfterQueries
BenchmarkSelectAfterQueries-12    	      63	  18637978 ns/op
BenchmarkSelectAfterQueries-12    	      62	  18487175 ns/op
BenchmarkSelectAfterQueries-12    	      60	  18351498 ns/op
BenchmarkSelectAfterQueries-12    	      64	  18354627 ns/op
BenchmarkSelectAfterQueries-12    	      66	  17899328 ns/op

[github-actions]

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

[samsondav]

I'd want to see benchmarks to ensure we aren't introducing any performance regressions

[samsondav]

Careful! This was set up deliberately for optimization reasons IIRC

[mateusz-sekara]

I was the one who did these optimizations :P For some reason, I missed this query, therefore fixing it right now

[mateusz-sekara]

#9968

[mateusz-sekara]

I'd want to see benchmarks to ensure we aren't introducing any performance regressions

Query plans look good, so I thought perf tests might not be needed. but I can do that. Btw, this query is used only by CCIP, so the impact is very localized.

[mateusz-sekara]

Query plans look good, so I thought perf tests might not be needed. but I can do that. Btw, this query is used only by CCIP, so the impact is very localized.

@samsondav I created a simple Go Benchmark suite with a populated database. Added outcomes to the PR's description, you can also check benchmark in the code

[reductionista]

LGTM!

[cl-sonarqube-production]

SonarQube Quality Gate

0 Bugs
0 Vulnerabilities
0 Security Hotspots
3 Code Smells

91.4% Coverage
0.0% Duplication