Re: SQL code runs slower as a stored function

[S G <sgennaria2@xxxxxxxxx>]

It would help if you post the output from EXPLAIN ANALYZE for each case,
as this will hopefully show where the bottleneck is.

I'm glad you asked, and I think I've discussed enough about what *could-be* happening that I'd like to get my hands dirty with what's really going on.  Maybe now I can learn how to read and interpret all this stuff.  I will present 3 EXPLAIN ANALYZE cases:
1) slow with variables: equal query structure as example 2
2) fast with static values: equal query structure as example 1
3) fast with variables: I changed where I put the constraint and it allowed me to keep this as a normal sql stored procedure without relying on the plpgsql RETURN QUERY EXECUTE fix

1) slow with variables: equal query structure as example 2

'CTE Scan on subquery2  (cost=4966.56..4966.59 rows=1 width=88) (actual time=5616.201..5616.202 rows=1 loops=1)'
'  CTE subquery2'
'    ->  HashAggregate  (cost=4966.54..4966.56 rows=1 width=44) (actual time=5616.178..5616.179 rows=1 loops=1)'
'          CTE subquery'
'            ->  Sort  (cost=4966.51..4966.51 rows=1 width=346) (actual time=5612.507..5612.726 rows=1810 loops=1)'
'                  Sort Key: tb_blackhawk_sent.sent_date_time'
'                  Sort Method:  quicksort  Memory: 870kB'
'                  ->  Nested Loop Left Join  (cost=813.78..4966.50 rows=1 width=346) (actual time=10.012..5608.011 rows=1810 loops=1)'
'                        Join Filter: (tb_blackhawk_sent.pcap_sent_date_time = tb_blackhawk.pcap_sent_date_time)'
'                        ->  Nested Loop  (cost=813.78..3367.26 rows=1 width=229) (actual time=4.698..24.509 rows=1810 loops=1)'
'                              Join Filter: ((tb_blackhawk_sent.pcap_sent_date_time >= sf_group_join_times_for_collector_in_test.join_time) AND (tb_blackhawk_sent.pcap_sent_date_time <= sf_group_join_times_for_collector_in_test.stop_time))'
'                              ->  Function Scan on sf_group_join_times_for_collector_in_test  (cost=0.00..265.00 rows=1 width=92) (actual time=2.946..2.957 rows=2 loops=1)'
'                                    Filter: (((group_ip)::text = $3) AND (listen_port = $4))'
'                              ->  Bitmap Heap Scan on tb_blackhawk_sent  (cost=813.78..3102.11 rows=10 width=137) (actual time=1.661..9.843 rows=1862 loops=2)'
'                                    Recheck Cond: (tb_blackhawk_sent.test_id = $1)'
'                                    Filter: ((tb_blackhawk_sent.pcap_sent_date_time >= $5) AND (tb_blackhawk_sent.pcap_sent_date_time <= $6) AND ((tb_blackhawk_sent.destination_ip)::text = $3) AND (tb_blackhawk_sent.destination_port = $4))'
'                                    ->  Bitmap Index Scan on tb_blackhawk_sent_pk2  (cost=0.00..813.77 rows=13526 width=0) (actual time=1.625..1.625 rows=13031 loops=2)'
'                                          Index Cond: (tb_blackhawk_sent.test_id = $1)'
'                        ->  Index Scan using tb_blackhawk_pk2 on tb_blackhawk  (cost=0.00..1599.22 rows=1 width=117) (actual time=0.678..3.083 rows=1 loops=1810)'
'                              Index Cond: ((tb_blackhawk.test_id = $1) AND (tb_blackhawk_sent.sequence_num = tb_blackhawk.sequence_num) AND ((tb_blackhawk.collector_ip)::text = ($2)::text) AND ((tb_blackhawk_sent.collector_ip)::text = (tb_blackhawk.source_ip)::text))'
'                              Filter: (((tb_blackhawk.destination_ip)::text = $3) AND (tb_blackhawk.destination_port = $4))'
'          ->  CTE Scan on subquery  (cost=0.00..0.02 rows=1 width=44) (actual time=5612.513..5615.248 rows=1810 loops=1)'
'Total runtime: 5616.395 ms'


2) fast with static values: equal query structure as example 1

'CTE Scan on subquery2  (cost=14396.95..14403.95 rows=200 width=88) (actual time=46.243..46.244 rows=1 loops=1)'
'  CTE subquery2'
'    ->  HashAggregate  (cost=14393.95..14396.95 rows=200 width=44) (actual time=46.222..46.223 rows=1 loops=1)'
'          CTE subquery'
'            ->  Sort  (cost=14353.35..14356.25 rows=1160 width=346) (actual time=42.338..42.532 rows=1810 loops=1)'
'                  Sort Key: tb_blackhawk_sent.sent_date_time'
'                  Sort Method:  quicksort  Memory: 870kB'
'                  ->  Hash Left Join  (cost=11315.16..14294.31 rows=1160 width=346) (actual time=19.476..38.382 rows=1810 loops=1)'
'                        Hash Cond: (((tb_blackhawk_sent.collector_ip)::text = (tb_blackhawk.source_ip)::text) AND (tb_blackhawk_sent.sequence_num = tb_blackhawk.sequence_num) AND (tb_blackhawk_sent.pcap_sent_date_time = tb_blackhawk.pcap_sent_date_time))'
'                        ->  Nested Loop  (cost=789.32..3490.06 rows=1160 width=229) (actual time=4.954..21.640 rows=1810 loops=1)'
'                              Join Filter: ((tb_blackhawk_sent.pcap_sent_date_time >= sf_group_join_times_for_collector_in_test.join_time) AND (tb_blackhawk_sent.pcap_sent_date_time <= sf_group_join_times_for_collector_in_test.stop_time))'
'                              ->  Function Scan on sf_group_join_times_for_collector_in_test  (cost=0.00..265.00 rows=1 width=92) (actual time=2.992..2.998 rows=2 loops=1)'
'                                    Filter: (((group_ip)::text = '239.0.0.1'::text) AND (listen_port = 5001))'
'                              ->  Bitmap Heap Scan on tb_blackhawk_sent  (cost=789.32..3068.48 rows=10439 width=137) (actual time=1.762..8.630 rows=1862 loops=2)'
'                                    Recheck Cond: (tb_blackhawk_sent.test_id = 219)'
'                                    Filter: ((tb_blackhawk_sent.pcap_sent_date_time >= '-infinity'::timestamp without time zone) AND (tb_blackhawk_sent.pcap_sent_date_time <= 'infinity'::timestamp without time zone) AND ((tb_blackhawk_sent.destination_ip)::text = '239.0.0.1'::text) AND (tb_blackhawk_sent.destination_port = 5001))'
'                                    ->  Bitmap Index Scan on tb_blackhawk_sent_pk2  (cost=0.00..786.71 rows=13118 width=0) (actual time=1.730..1.730 rows=13031 loops=2)'
'                                          Index Cond: (tb_blackhawk_sent.test_id = 219)'
'                        ->  Hash  (cost=10451.04..10451.04 rows=4274 width=117) (actual time=14.508..14.508 rows=1361 loops=1)'
'                              ->  Bitmap Heap Scan on tb_blackhawk  (cost=3179.36..10451.04 rows=4274 width=117) (actual time=9.792..13.853 rows=1361 loops=1)'
'                                    Recheck Cond: ((test_id = 219) AND ((collector_ip)::text = '192.168.145.2'::text))'
'                                    Filter: (((destination_ip)::text = '239.0.0.1'::text) AND (destination_port = 5001))'
'                                    ->  Bitmap Index Scan on tb_blackhawk_pk2  (cost=0.00..3178.29 rows=5725 width=0) (actual time=9.753..9.753 rows=9437 loops=1)'
'                                          Index Cond: ((test_id = 219) AND ((collector_ip)::text = '192.168.145.2'::text))'
'          ->  CTE Scan on subquery  (cost=0.00..23.20 rows=1160 width=44) (actual time=42.343..45.235 rows=1810 loops=1)'
'Total runtime: 46.436 ms'


3) fast with variables: I changed where I put the constraint and it allowed
 me to keep this as a normal sql stored procedure without relying on the
 plpgsql RETURN QUERY EXECUTE fix

'CTE Scan on subquery2  (cost=11879.96..11880.00 rows=1 width=88) (actual time=39.888..39.889 rows=1 loops=1)'
'  CTE subquery2'
'    ->  HashAggregate  (cost=11879.95..11879.96 rows=1 width=44) (actual time=39.867..39.868 rows=1 loops=1)'
'          CTE subquery'
'            ->  Sort  (cost=11874.02..11874.56 rows=215 width=346) (actual time=35.562..35.729 rows=1810 loops=1)'
'                  Sort Key: tb_blackhawk_sent.sent_date_time'
'                  Sort Method:  quicksort  Memory: 870kB'
'                  ->  Hash Left Join  (cost=9309.88..11865.69 rows=215 width=346) (actual time=18.192..31.508 rows=1810 loops=1)'
'                        Hash Cond: (((tb_blackhawk_sent.collector_ip)::text = (tb_blackhawk.source_ip)::text) AND (tb_blackhawk_sent.sequence_num = tb_blackhawk.sequence_num) AND (tb_blackhawk_sent.pcap_sent_date_time = tb_blackhawk.pcap_sent_date_time))'
'                        ->  Nested Loop  (cost=814.26..3328.94 rows=215 width=229) (actual time=4.538..15.664 rows=1810 loops=1)'
'                              Join Filter: ((tb_blackhawk_sent.pcap_sent_date_time >= sf_group_join_times_for_collector_in_test.join_time) AND (tb_blackhawk_sent.pcap_sent_date_time <= sf_group_join_times_for_collector_in_test.stop_time))'
'                              ->  Function Scan on sf_group_join_times_for_collector_in_test  (cost=0.00..265.00 rows=1 width=92) (actual time=2.958..2.963 rows=2 loops=1)'
'                                    Filter: (((group_ip)::text = $3) AND (listen_port = $4))'
'                              ->  Bitmap Heap Scan on tb_blackhawk_sent  (cost=814.26..3034.96 rows=1932 width=137) (actual time=1.573..5.569 rows=1862 loops=2)'
'                                    Recheck Cond: (tb_blackhawk_sent.test_id = $1)'
'                                    Filter: (((tb_blackhawk_sent.destination_ip)::text = $3) AND (tb_blackhawk_sent.destination_port = $4))'
'                                    ->  Bitmap Index Scan on tb_blackhawk_sent_pk2  (cost=0.00..813.77 rows=13526 width=0) (actual time=1.541..1.541 rows=13031 loops=2)'
'                                          Index Cond: (tb_blackhawk_sent.test_id = $1)'
'                        ->  Hash  (cost=8485.14..8485.14 rows=599 width=117) (actual time=13.640..13.640 rows=1361 loops=1)'
'                              ->  Bitmap Heap Scan on tb_blackhawk  (cost=1924.02..8485.14 rows=599 width=117) (actual time=9.240..13.035 rows=1361 loops=1)'
'                                    Recheck Cond: ((test_id = $1) AND ((collector_ip)::text = ($2)::text))'
'                                    Filter: (((destination_ip)::text = $3) AND (destination_port = $4))'
'                                    ->  Bitmap Index Scan on tb_blackhawk_pk2  (cost=0.00..1923.87 rows=4193 width=0) (actual time=9.201..9.201 rows=9437 loops=1)'
'                                          Index Cond: ((test_id = $1) AND ((collector_ip)::text = ($2)::text))'
'          ->  CTE Scan on subquery  (cost=0.00..5.38 rows=1 width=44) (actual time=35.571..38.811 rows=1810 loops=1)'
'                Filter: ((sent_date_time_a >= $5) AND (sent_date_time_a <= $6))'
'Total runtime: 40.092 ms'


Hope you can read that better than I can!

Thanks!