Re: SQL code runs slower as a stored function

>
> 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!