Stored procedure slower than sql?

From: "Matthew Peters" <matthew(at)haydrian(dot)com>
To: <pgsql-performance(at)postgresql(dot)org>
Subject: Stored procedure slower than sql?
Date: 2006-10-26 15:49:02
Message-ID: 775F825B46B551499DC75DC4E92F80AB564D00@jupiter.ad.haydrian.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

(Repost - did not appear to make it to the list the first time)

I have written a stored procedure for 8.1 that wraps a single (albeit complex) query, and uses 2 IN parameters (BIGINT, INTEGER) in the FROM JOIN and WHERE clauses.  The procedure is written in SQL (as opposed to plpgsql - although testing in plpgsql produces the same problem).  The results are SETOF a custom type (SMALLINT, NUMERIC(38,2), NUMERIC(38,2)).  The central query, when tested in psql and pgadmin III returns in 500 ms.  As a stored procedure, it returns in 22000 ms!  How can a stored procedure containing a single query not implement the same execution plan (assumption based on the dramatic performance difference) that an identical ad-hoc query generates?  I ran a series of tests, and determined that if I replaced the parameters with hard-coded values, the execution time returned to 500ms.  Can anyone shed some light on this for me - it seems counter-intuitive?

Here are some particulars about the underlying query and tables:

The query selects a month number from a generate_series(1,12) left outer joined on a subquery, which produces three fields.  The subquery is a UNION ALL of 5 tables.  Each of the five tables has 100 inherited partitions.  As you can see from the execution plan, the partitioning constraint is successfully restricting the query to the appropriate partition for each of the five tables.  The constraint for each partition is a CHAR(2) field "partition_key"  = '00' (where '00' is a two-digit CHAR(2) value that is returned from a function call ala table1.partition_key = partition_key($1) )

Execution Plan :

Sort  (cost=10410.15..10410.65 rows=200 width=68) (actual time=273.050..273.071 rows=12 loops=1)
  Sort Key: mm.monthnumber
  ->  HashAggregate  (cost=10398.01..10402.51 rows=200 width=68) (actual time=272.970..273.001 rows=12 loops=1)
        ->  Hash Ltable5 Join  (cost=10370.01..10390.51 rows=1000 width=68) (actual time=272.817..272.902 rows=13 loops=1)
              Hash Cond: (("outer".monthnumber)::double precision = "inner".monthnumber)
              ->  Function Scan on generate_series mm  (cost=0.00..12.50 rows=1000 width=4) (actual time=0.018..0.043 rows=12 loops=1)
              ->  Hash  (cost=10369.99..10369.99 rows=10 width=72) (actual time=272.769..272.769 rows=8 loops=1)
                    ->  Append  (cost=1392.08..10369.89 rows=10 width=47) (actual time=39.581..272.734 rows=8 loops=1)
                          ->  Subquery Scan "*SELECT* 1"  (cost=1392.08..1392.15 rows=2 width=47) (actual time=39.576..39.582 rows=1 loops=1)
                                ->  HashAggregate  (cost=1392.08..1392.13 rows=2 width=47) (actual time=39.571..39.573 rows=1 loops=1)
                                      ->  Result  (cost=0.00..1392.05 rows=2 width=47) (actual time=25.240..39.538 rows=1 loops=1)
                                            ->  Append  (cost=0.00..1392.03 rows=2 width=47) (actual time=25.224..39.518 rows=1 loops=1)
                                                  ->  Seq Scan on table1 table1  (cost=0.00..14.50 rows=1 width=47) (actual time=0.003..0.003 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                                                  ->  Seq Scan on table1_p12 table1  (cost=0.00..1377.53 rows=1 width=28) (actual time=25.214..39.503 rows=1 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                          ->  Subquery Scan "*SELECT* 2"  (cost=2741.47..2741.56 rows=2 width=47) (actual time=78.140..78.140 rows=0 loops=1)
                                ->  HashAggregate  (cost=2741.47..2741.54 rows=2 width=47) (actual time=78.134..78.134 rows=0 loops=1)
                                      ->  Result  (cost=0.00..2741.45 rows=2 width=47) (actual time=78.128..78.128 rows=0 loops=1)
                                            ->  Append  (cost=0.00..2741.43 rows=2 width=47) (actual time=78.122..78.122 rows=0 loops=1)
                                                  ->  Seq Scan on table2 table2  (cost=0.00..12.40 rows=1 width=47) (actual time=0.004..0.004 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                                                  ->  Seq Scan on table2_p12 table2  (cost=0.00..2729.03 rows=1 width=29) (actual time=78.109..78.109 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                          ->  Subquery Scan "*SELECT* 3"  (cost=3173.33..3173.41 rows=2 width=47) (actual time=91.609..91.609 rows=0 loops=1)
                                ->  HashAggregate  (cost=3173.33..3173.39 rows=2 width=47) (actual time=91.603..91.603 rows=0 loops=1)
                                      ->  Result  (cost=0.00..3173.30 rows=2 width=47) (actual time=91.598..91.598 rows=0 loops=1)
                                            ->  Append  (cost=0.00..3173.28 rows=2 width=47) (actual time=91.592..91.592 rows=0 loops=1)
                                                  ->  Seq Scan on table3 table3  (cost=0.00..10.90 rows=1 width=47) (actual time=0.003..0.003 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                                                  ->  Seq Scan on table3_p12 table3  (cost=0.00..3162.38 rows=1 width=29) (actual time=91.581..91.581 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                          ->  Subquery Scan "*SELECT* 4"  (cost=961.72..961.80 rows=2 width=29) (actual time=11.647..11.694 rows=7 loops=1)
                                ->  HashAggregate  (cost=961.72..961.78 rows=2 width=29) (actual time=11.640..11.659 rows=7 loops=1)
                                      ->  Result  (cost=0.00..961.69 rows=2 width=29) (actual time=7.537..11.567 rows=10 loops=1)
                                            ->  Append  (cost=0.00..961.67 rows=2 width=29) (actual time=7.520..11.499 rows=10 loops=1)
                                                  ->  Seq Scan on table4 table4  (cost=0.00..22.30 rows=1 width=29) (actual time=0.003..0.003 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                                                  ->  Index Scan using table4_p12_recency_date_type_xyz_idx on table4_p12 table4  (cost=0.00..939.37 rows=1 width=29) (actual time=7.510..11.452 rows=10 loops=1)
                                                        Index Cond: (table_key = 10265512)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                          ->  Subquery Scan "*SELECT* 5"  (cost=2100.89..2100.98 rows=2 width=47) (actual time=51.658..51.658 rows=0 loops=1)
                                ->  HashAggregate  (cost=2100.89..2100.96 rows=2 width=47) (actual time=51.652..51.652 rows=0 loops=1)
                                      ->  Result  (cost=0.00..2100.87 rows=2 width=47) (actual time=51.646..51.646 rows=0 loops=1)
                                            ->  Append  (cost=0.00..2100.85 rows=2 width=47) (actual time=51.641..51.641 rows=0 loops=1)
                                                  ->  Seq Scan on table5 table5  (cost=0.00..10.90 rows=1 width=47) (actual time=0.004..0.004 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
                                                  ->  Seq Scan on table5_p12 table5  (cost=0.00..2089.95 rows=1 width=29) (actual time=51.627..51.627 rows=0 loops=1)
                                                        Filter: ((partition_key = '12'::bpchar) AND (substr((indexed_field)::text, 2, 1) = '5'::text) AND (table_key = 10265512) AND (date_part('year'::text, (event_date)::timestamp without time zone) = 2005::double precision))
Total runtime: 274.605 ms

I appreciate your thoughts - this is a real mind-bender!

Matthew Peters

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Tom Lane 2006-10-26 16:14:38 Re: Stored procedure slower than sql?
Previous Message Gavin Hamill 2006-10-26 15:06:09 Re: VACUUMs take twice as long across all nodes