Re: SQL code runs slower as a stored function - Mailing list pgsql-general
| From | S G |
|---|---|
| Subject | Re: SQL code runs slower as a stored function |
| Date | |
| Msg-id | AANLkTilPjh8gboxtJdFUCrVHeRlr4miscBbY1pAEMzNM@mail.gmail.com Whole thread Raw |
| In response to | Re: SQL code runs slower as a stored function (Raymond O'Donnell <rod@iol.ie>) |
| List | pgsql-general |
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 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!
pgsql-general by date: