Skip to content

Fix slowdown in live sync

Michal Zander requested to merge mzander/fix-slowdown into develop

due to changes in btree indexes in postgresql 17 multiple IN statements must be moved to CTE

plan for miss behaving query,

pg16:

"Nested Loop  (cost=51979.78..3427335.04 rows=2977692 width=48) (actual time=1.281..1.594 rows=7 loops=1)"
"  Buffers: shared hit=106 read=8"
"  I/O Timings: shared read=1.055"
"  ->  Limit  (cost=6.32..7.35 rows=1 width=21) (actual time=0.023..0.023 rows=1 loops=1)"
"        Buffers: shared hit=4"
"        ->  Bitmap Heap Scan on contexts hc  (cost=6.32..7.35 rows=1 width=21) (actual time=0.022..0.023 rows=1 loops=1)"
"              Recheck Cond: ((name)::text = 'hafbe_bal'::text)"
"              Heap Blocks: exact=2"
"              Buffers: shared hit=4"
"              ->  Bitmap Index Scan on uq_hive_context_name  (cost=0.00..6.32 rows=1 width=0) (actual time=0.008..0.008 rows=2 loops=1)"
"                    Index Cond: ((name)::text = 'hafbe_bal'::text)"
"                    Buffers: shared hit=2"
"  ->  Append  (cost=51973.46..3375218.07 rows=2977692 width=151) (actual time=1.238..1.527 rows=7 loops=1)"
"        Buffers: shared hit=102 read=8"
"        I/O Timings: shared read=1.055"
"        ->  Subquery Scan on ""*SELECT* 1""  (cost=51973.46..3360298.32 rows=2977691 width=151) (actual time=1.237..1.251 rows=7 loops=1)"
"              Buffers: shared hit=73 read=8"
"              I/O Timings: shared read=1.055"
"              ->  Bitmap Heap Scan on operations ho  (cost=51973.46..3330521.41 rows=2977691 width=157) (actual time=1.237..1.249 rows=7 loops=1)"
"                    Recheck Cond: (((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279)) OR ((hive.operation_id_to_type_id(id) = 55) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279)) OR ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279)))"
"                    Filter: ((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) OR ((hive.operation_id_to_type_id(id) = 55) AND (NOT ((((body_binary)::jsonb -> 'value'::text) ->> 'is_saved_into_hbd_balance'::text))::boolean)) OR ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND ((((body_binary)::jsonb -> 'value'::text) ->> 'payout_must_be_claimed'::text))::boolean))"
"                    Heap Blocks: exact=1"
"                    Buffers: shared hit=73 read=8"
"                    I/O Timings: shared read=1.055"
"                    ->  BitmapOr  (cost=51973.42..51973.42 rows=3080033 width=0) (actual time=1.214..1.215 rows=0 loops=1)"
"                          Buffers: shared hit=73 read=7"
"                          I/O Timings: shared read=1.043"
"                          ->  Bitmap Index Scan on hive_operations_op_type_id_block_num  (cost=0.00..46738.48 rows=2894313 width=0) (actual time=1.010..1.010 rows=5 loops=1)"
"                                Index Cond: ((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279))"
"                                Buffers: shared hit=63 read=5"
"                                I/O Timings: shared read=0.864"
"                          ->  Bitmap Index Scan on hive_operations_op_type_id_block_num  (cost=0.00..18.62 rows=1068 width=0) (actual time=0.005..0.005 rows=0 loops=1)"
"                                Index Cond: ((hive.operation_id_to_type_id(id) = 55) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279))"
"                                Buffers: shared hit=4"
"                          ->  Bitmap Index Scan on hive_operations_op_type_id_block_num  (cost=0.00..2983.04 rows=184652 width=0) (actual time=0.195..0.195 rows=2 loops=1)"
"                                Index Cond: ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279))"
"                                Buffers: shared hit=6 read=2"
"                                I/O Timings: shared read=0.179"
"        ->  Subquery Scan on ""*SELECT* 2""  (cost=1.06..31.29 rows=1 width=247) (actual time=0.274..0.274 rows=0 loops=1)"
"              Buffers: shared hit=29"
"              ->  Nested Loop  (cost=1.06..31.28 rows=1 width=253) (actual time=0.274..0.274 rows=0 loops=1)"
"                    Join Filter: ((o.fork_id = (max(hbr.fork_id))) AND (hive.operation_id_to_block_num(o.id) = hbr.num))"
"                    Buffers: shared hit=29"
"                    ->  Seq Scan on operations_reversible o  (cost=0.04..30.23 rows=1 width=255) (actual time=0.274..0.274 rows=0 loops=1)"
"                          Filter: ((hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279) AND ((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) OR ((hive.operation_id_to_type_id(id) = 55) AND (NOT ((((body_binary)::jsonb -> 'value'::text) ->> 'is_saved_into_hbd_balance'::text))::boolean)) OR ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND ((((body_binary)::jsonb -> 'value'::text) ->> 'payout_must_be_claimed'::text))::boolean)))"
"                          Rows Removed by Filter: 27"
"                          Buffers: shared hit=29"
"                    ->  HashAggregate  (cost=1.02..1.03 rows=1 width=12) (never executed)"
"                          Group Key: hbr.num"
"                          ->  Result  (cost=0.00..1.02 rows=1 width=12) (never executed)"
"                                One-Time Filter: (((hc.current_block_num > hc.irreversible_block) AND hc.is_forking))"
"                                ->  Seq Scan on blocks_reversible hbr  (cost=0.00..1.02 rows=1 width=12) (never executed)"
"                                      Filter: ((num > hc.irreversible_block) AND (fork_id <= hc.fork_id) AND (num <= hc.current_block_num))"
"Planning:"
"  Buffers: shared hit=126"
"Planning Time: 1.371 ms"
"Execution Time: 1.653 ms"

pg17:

"Nested Loop  (cost=52513.25..3462742.24 rows=3012823 width=48) (actual time=854.119..854.202 rows=7 loops=1)"
"  Buffers: shared hit=153188"
"  ->  Limit  (cost=6.32..7.35 rows=1 width=21) (actual time=0.016..0.018 rows=1 loops=1)"
"        Buffers: shared hit=3"
"        ->  Bitmap Heap Scan on contexts hc  (cost=6.32..7.35 rows=1 width=21) (actual time=0.015..0.017 rows=1 loops=1)"
"              Recheck Cond: ((name)::text = 'hafbe_bal'::text)"
"              Heap Blocks: exact=1"
"              Buffers: shared hit=3"
"              ->  Bitmap Index Scan on uq_hive_context_name  (cost=0.00..6.32 rows=1 width=0) (actual time=0.006..0.007 rows=1 loops=1)"
"                    Index Cond: ((name)::text = 'hafbe_bal'::text)"
"                    Buffers: shared hit=2"
"  ->  Append  (cost=52506.92..3410010.48 rows=3012823 width=151) (actual time=854.066..854.115 rows=7 loops=1)"
"        Buffers: shared hit=153185"
"        ->  Subquery Scan on ""*SELECT* 1""  (cost=52506.92..3394923.70 rows=3012822 width=151) (actual time=854.065..854.087 rows=7 loops=1)"
"              Buffers: shared hit=153183"
"              ->  Bitmap Heap Scan on operations ho  (cost=52506.92..3364795.48 rows=3012822 width=157) (actual time=854.064..854.084 rows=7 loops=1)"
"                    Recheck Cond: (((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279)) OR ((hive.operation_id_to_type_id(id) = 55) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279)) OR ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279)))"
"                    Filter: ((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) OR ((hive.operation_id_to_type_id(id) = 55) AND (NOT ((((body_binary)::jsonb -> 'value'::text) ->> 'is_saved_into_hbd_balance'::text))::boolean)) OR ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND ((((body_binary)::jsonb -> 'value'::text) ->> 'payout_must_be_claimed'::text))::boolean))"
"                    Heap Blocks: exact=1"
"                    Buffers: shared hit=153183"
"                    ->  BitmapOr  (cost=52506.88..52506.88 rows=3112096 width=0) (actual time=854.044..854.044 rows=0 loops=1)"
"                          Buffers: shared hit=153182"
"                          ->  Bitmap Index Scan on hive_operations_op_type_id_block_num  (cost=0.00..47340.71 rows=2932178 width=0) (actual time=853.981..853.981 rows=5 loops=1)"
"                                Index Cond: ((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279))"
"                                Buffers: shared hit=153170"
"                          ->  Bitmap Index Scan on hive_operations_op_type_id_block_num  (cost=0.00..19.16 rows=1104 width=0) (actual time=0.005..0.005 rows=0 loops=1)"
"                                Index Cond: ((hive.operation_id_to_type_id(id) = 55) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279))"
"                                Buffers: shared hit=4"
"                          ->  Bitmap Index Scan on hive_operations_op_type_id_block_num  (cost=0.00..2887.39 rows=178815 width=0) (actual time=0.053..0.053 rows=2 loops=1)"
"                                Index Cond: ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND (hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279))"
"                                Buffers: shared hit=8"
"        ->  Subquery Scan on ""*SELECT* 2""  (cost=2.35..22.66 rows=1 width=137) (actual time=0.024..0.025 rows=0 loops=1)"
"              Buffers: shared hit=2"
"              ->  Nested Loop  (cost=2.35..22.65 rows=1 width=143) (actual time=0.023..0.024 rows=0 loops=1)"
"                    Join Filter: ((o.fork_id = (max(hbr.fork_id))) AND (hive.operation_id_to_block_num(o.id) = hbr.num))"
"                    Buffers: shared hit=2"
"                    ->  Index Scan using hive_operations_reversible_block_num_type_id_trx_in_block_fork_ on operations_reversible o  (cost=0.31..20.57 rows=1 width=145) (actual time=0.023..0.023 rows=0 loops=1)"
"                          Index Cond: ((hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279))"
"                          Filter: ((hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) OR ((hive.operation_id_to_type_id(id) = 55) AND (NOT ((((body_binary)::jsonb -> 'value'::text) ->> 'is_saved_into_hbd_balance'::text))::boolean)) OR ((hive.operation_id_to_type_id(id) = ANY ('{51,63}'::integer[])) AND ((((body_binary)::jsonb -> 'value'::text) ->> 'payout_must_be_claimed'::text))::boolean))"
"                          Buffers: shared hit=2"
"                    ->  GroupAggregate  (cost=2.04..2.06 rows=1 width=12) (never executed)"
"                          Group Key: hbr.num"
"                          ->  Sort  (cost=2.04..2.05 rows=1 width=12) (never executed)"
"                                Sort Key: hbr.num"
"                                ->  Result  (cost=0.00..2.04 rows=1 width=12) (never executed)"
"                                      One-Time Filter: (((hc.current_block_num > hc.irreversible_block) AND hc.is_forking))"
"                                      ->  Seq Scan on blocks_reversible hbr  (cost=0.00..2.04 rows=1 width=12) (never executed)"
"                                            Filter: ((num > hc.irreversible_block) AND (fork_id <= hc.fork_id) AND (num <= hc.current_block_num))"
"Planning:"
"  Buffers: shared hit=117"
"Planning Time: 1.254 ms"
"Execution Time: 854.275 ms"

query plan after changes on pg17:

"CTE Scan on process_block_range_data_b ov  (cost=2067730.46..2223335.31 rows=285849 width=48) (actual time=0.095..0.139 rows=7 loops=1)"
"  Filter: ((op_type_id = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68}'::integer[])) OR ((op_type_id = 55) AND (NOT (((body -> 'value'::text) ->> 'is_saved_into_hbd_balance'::text))::boolean)) OR ((op_type_id = ANY ('{51,63}'::integer[])) AND (((body -> 'value'::text) ->> 'payout_must_be_claimed'::text))::boolean))"
"  Buffers: shared hit=11"
"  CTE process_block_range_data_b"
"    ->  Nested Loop  (cost=7.03..2067730.42 rows=3112097 width=48) (actual time=0.089..0.129 rows=7 loops=1)"
"          Buffers: shared hit=11"
"          ->  Limit  (cost=6.32..7.35 rows=1 width=21) (actual time=0.028..0.029 rows=1 loops=1)"
"                Buffers: shared hit=3"
"                ->  Bitmap Heap Scan on contexts hc  (cost=6.32..7.35 rows=1 width=21) (actual time=0.028..0.028 rows=1 loops=1)"
"                      Recheck Cond: ((name)::text = 'hafbe_bal'::text)"
"                      Heap Blocks: exact=1"
"                      Buffers: shared hit=3"
"                      ->  Bitmap Index Scan on uq_hive_context_name  (cost=0.00..6.32 rows=1 width=0) (actual time=0.006..0.006 rows=1 loops=1)"
"                            Index Cond: ((name)::text = 'hafbe_bal'::text)"
"                            Buffers: shared hit=2"
"          ->  Append  (cost=0.71..2013261.36 rows=3112097 width=151) (actual time=0.021..0.033 rows=7 loops=1)"
"                Buffers: shared hit=8"
"                ->  Subquery Scan on ""*SELECT* 1""  (cost=0.71..1997681.32 rows=3112096 width=151) (actual time=0.020..0.023 rows=7 loops=1)"
"                      Buffers: shared hit=6"
"                      ->  Index Scan using hive_operations_block_num_trx_in_block_idx on operations ho  (cost=0.71..1966560.36 rows=3112096 width=157) (actual time=0.019..0.021 rows=7 loops=1)"
"                            Index Cond: ((hive.operation_id_to_block_num(id) <= (LEAST(hc.irreversible_block, hc.current_block_num))) AND (hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279) AND (hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68,51,63,55}'::integer[])))"
"                            Buffers: shared hit=6"
"                ->  Subquery Scan on ""*SELECT* 2""  (cost=2.31..19.55 rows=1 width=188) (actual time=0.008..0.008 rows=0 loops=1)"
"                      Buffers: shared hit=2"
"                      ->  Nested Loop  (cost=2.31..19.54 rows=1 width=194) (actual time=0.008..0.008 rows=0 loops=1)"
"                            Join Filter: ((o.fork_id = (max(hbr.fork_id))) AND (hive.operation_id_to_block_num(o.id) = hbr.num))"
"                            Buffers: shared hit=2"
"                            ->  Index Scan using hive_operations_reversible_block_num_type_id_trx_in_block_fork_ on operations_reversible o  (cost=0.27..17.46 rows=1 width=196) (actual time=0.008..0.008 rows=0 loops=1)"
"                                  Index Cond: ((hive.operation_id_to_block_num(id) >= 90833279) AND (hive.operation_id_to_block_num(id) <= 90833279) AND (hive.operation_id_to_type_id(id) = ANY ('{40,41,62,32,33,34,59,39,4,20,56,60,52,53,77,70,68,51,63,55}'::integer[])))"
"                                  Buffers: shared hit=2"
"                            ->  GroupAggregate  (cost=2.04..2.06 rows=1 width=12) (never executed)"
"                                  Group Key: hbr.num"
"                                  ->  Sort  (cost=2.04..2.05 rows=1 width=12) (never executed)"
"                                        Sort Key: hbr.num"
"                                        ->  Result  (cost=0.00..2.04 rows=1 width=12) (never executed)"
"                                              One-Time Filter: (((hc.current_block_num > hc.irreversible_block) AND hc.is_forking))"
"                                              ->  Seq Scan on blocks_reversible hbr  (cost=0.00..2.04 rows=1 width=12) (never executed)"
"                                                    Filter: ((num > hc.irreversible_block) AND (fork_id <= hc.fork_id) AND (num <= hc.current_block_num))"
"Planning:"
"  Buffers: shared hit=102"
"Planning Time: 0.755 ms"
"Execution Time: 0.187 ms"
Edited by Michal Zander

Merge request reports

Loading