Thread: SQL Function Performance

If you have only recently analyzed the tables in the query, close your psql session (if that's what you were using) and
thenrestart it. I've gotten burned by asking a query using the function, which I believe is when PG creates the plan
forthe function, and then making significant changes to the tables behind it (new index, bulk insert, etc.). By
startinga new session, the function will be re-planned according to up to date statistics or using newly created
indices.

On Sun, Feb 12, 2006 at 10:25:28PM +0200, Adnan DURSUN wrote:
> My database has an SQL function. The result comes in 30-40 seconds
> when i use the SQL function. On the other hand; The result comes
> 300-400 milliseconds when i run the SQL statement. Any idea ??

Have you analyzed the tables?  If that's not the problem then could
you post the EXPLAIN ANALYZE output for the direct query and for a
prepared query?  For the prepared query do this:

PREPARE stmt (varchar, date, int4, varchar, varchar) AS SELECT ... ;

where "..." is the same SQL as in the function body, including the
numbered parameters ($1, $2, etc.).  To execute the query do this:

EXPLAIN ANALYZE EXECUTE stmt (...);

Where "..." is the same parameter list you'd pass to the function
(the same values you used in the direct query).

If you need to re-prepare the query then run "DEALLOCATE stmt"
before doing so.

--
Michael Fuhr

From: Michael Fuhr

Date: 02/13/06 07:46:05

To: Adnan DURSUN

Cc: pgsql-performance@postgresql.org

Subject: Re: [PERFORM] SQL Function Performance

 

On Sun, Feb 12, 2006 at 10:25:28PM +0200, Adnan DURSUN wrote:

>> My database has an SQL function. The result comes in 30-40 seconds

>> when i use the SQL function. On the other hand; The result comes

>> 300-400 milliseconds when i run the SQL statement. Any idea ??

 

>Have you analyzed the tables?  If that's not the problem then could

>you post the EXPLAIN ANALYZE output for the direct query and for a

>prepared query?  For the prepared query do this:

 

EXPLAIN ANALYZE for direct query :

 

QUERY PLAN
"HashAggregate  (cost=29.37..29.40 rows=1 width=58) (actual time=12.114..12.114 rows=0 loops=1)"
"  ->  Nested Loop  (cost=9.55..29.36 rows=1 width=58) (actual time=12.107..12.107 rows=0 loops=1)"
"        Join Filter: (((""inner"".hat_no)::text = (""outer"".hat_no)::text) AND (""inner"".sefer_kod = ""outer"".sefer_kod) AND (""inner"".plan_tarihi = ""outer"".plan_tarihi) AND (""inner"".bin_yer_kod = ""outer"".bin_yer_kod) AND (""inner"".koltuk_no = ""outer"".koltuk_no))"
"        ->  Nested Loop  (cost=9.55..26.15 rows=1 width=93) (actual time=12.102..12.102 rows=0 loops=1)"
"              ->  Nested Loop  (cost=9.55..20.60 rows=1 width=65) (actual time=8.984..12.012 rows=1 loops=1)"
"                    ->  Nested Loop  (cost=9.55..14.62 rows=1 width=48) (actual time=6.155..7.919 rows=41 loops=1)"
"                          Join Filter: (""outer"".sefer_tip_kod = ""inner"".kod)"
"                          ->  Hash Join  (cost=9.55..13.58 rows=1 width=52) (actual time=6.129..6.846 rows=41 loops=1)"
"                                Hash Cond: (""outer"".kod = ""inner"".varis_yer_kod)"
"                                ->  Seq Scan on t_yer y2  (cost=0.00..3.44 rows=115 width=14) (actual time=0.018..0.374 rows=115 loops=1)"
"                                      Filter: ((iptal)::text = 'H'::text)"
"                                ->  Hash  (cost=9.55..9.55 rows=1 width=46) (actual time=6.058..6.058 rows=41 loops=1)"
"                                      ->  Merge Join  (cost=9.45..9.55 rows=1 width=46) (actual time=4.734..5.894 rows=41 loops=1)"
"                                            Merge Cond: (""outer"".kod = ""inner"".kalkis_yer_kod)"
"                                            ->  Index Scan using t_yer_pkey on t_yer y1  (cost=0.00..9.62 rows=115 width=14) (actual time=0.021..0.183 rows=40 loops=1)"
"                                                  Filter: ((iptal)::text = 'H'::text)"
"                                            ->  Sort  (cost=9.45..9.45 rows=1 width=40) (actual time=4.699..4.768 rows=41 loops=1)"
"                                                  Sort Key: h.kalkis_yer_kod"
"                                                  ->  Nested Loop  (cost=4.51..9.44 rows=1 width=40) (actual time=0.410..4.427 rows=41 loops=1)"
"                                                        Join Filter: ((""inner"".""no"")::text = (""outer"".hat_no)::text)"
"                                                        ->  Hash Join  (cost=4.51..8.09 rows=1 width=27) (actual time=0.384..1.036 rows=41 loops=1)"
"                                                              Hash Cond: ((""outer"".durumu)::text = (""inner"".kod)::text)"
"                                                              ->  Hash Join  (cost=2.25..5.80 rows=3 width=32) (actual time=0.193..0.652 rows=41 loops=1)"
"                                                                    Hash Cond: ((""outer"".ek_dev)::text = (""inner"".kod)::text)"
"                                                                    ->  Seq Scan on t_seferler s  (cost=0.00..3.21 rows=41 width=37) (actual time=0.009..0.256 rows=41 loops=1)"
"                                                                          Filter: (((iptal)::text = 'H'::text) AND ((iptal)::text = 'H'::text) AND ((firma_no)::text = '1'::text))"
"                                                                    ->  Hash  (cost=2.25..2.25 rows=2 width=5) (actual time=0.156..0.156 rows=2 loops=1)"
"                                                                          ->  Seq Scan on t_domains d1  (cost=0.00..2.25 rows=2 width=5) (actual time=0.055..0.138 rows=2 loops=1)"
"                                                                                Filter: ((name)::text = 'EKDEV'::text)"
"                                                              ->  Hash  (cost=2.25..2.25 rows=2 width=5) (actual time=0.164..0.164 rows=2 loops=1)"
"                                                                    ->  Seq Scan on t_domains d2  (cost=0.00..2.25 rows=2 width=5) (actual time=0.057..0.142 rows=2 loops=1)"
"                                                                          Filter: ((name)::text = 'SFR_DURUMU'::text)"
"                                                        ->  Seq Scan on t_hatlar h  (cost=0.00..1.23 rows=10 width=18) (actual time=0.004..0.042 rows=10 loops=41)"
"                                                              Filter: ('1'::text = (firma_no)::text)"
"                          ->  Seq Scan on t_sefer_tip t  (cost=0.00..1.03 rows=1 width=9) (actual time=0.005..0.009 rows=1 loops=41)"
"                                Filter: (((iptal)::text = 'H'::text) AND ('1'::text = (firma_no)::text))"
"                    ->  Index Scan using t_lokal_plan_sefer_liste_idx on t_lokal_plan lp  (cost=0.00..5.97 rows=1 width=22) (actual time=0.091..0.092 rows=0 loops=41)"
"                          Index Cond: (((lp.firma_no)::text = '1'::text) AND ((""outer"".hat_no)::text = (lp.hat_no)::text) AND (""outer"".kod = lp.sefer_kod) AND (lp.kalkis_tarihi = '2006-02-13'::date))"
"                          Filter: (lokal_kod = 62)"
"              ->  Index Scan using t_koltuk_son_durum_pkey on t_koltuk_son_durum sd  (cost=0.00..5.53 rows=1 width=28) (actual time=0.079..0.079 rows=0 loops=1)"
"                    Index Cond: (('1'::text = (sd.firma_no)::text) AND ((""outer"".hat_no)::text = (sd.hat_no)::text) AND (""outer"".kod = sd.sefer_kod) AND (""outer"".plan_tarihi = sd.plan_tarihi) AND (""outer"".yer_kod = sd.bin_yer_kod))"
"                    Filter: ((islem)::text = 'S'::text)"
"        ->  Index Scan using t_koltuk_islem_kod_ukey on t_koltuk_islem i  (cost=0.00..3.18 rows=1 width=57) (never executed)"
"              Index Cond: (i.kod = ""outer"".islem_kod)"
"              Filter: ((firma_no)::text = '1'::text)"
"Total runtime: 13.984 ms"

 

Adnan DURSUN

ASRIN Bilişim Ltd.Şti

Ankara / TURKEY

 

From: Michael Fuhr

Date: 02/13/06 07:46:05

To: Adnan DURSUN

Cc: pgsql-performance@postgresql.org

Subject: Re: [PERFORM] SQL Function Performance

 

On Sun, Feb 12, 2006 at 10:25:28PM +0200, Adnan DURSUN wrote:

>> My database has an SQL function. The result comes in 30-40 seconds

>> when i use the SQL function. On the other hand; The result comes

>> 300-400 milliseconds when i run the SQL statement. Any idea ??

 

>Have you analyzed the tables?  If that's not the problem then could

>you post the EXPLAIN ANALYZE output for the direct query and for a

>prepared query?  For the prepared query do this:

 

>EXPLAIN ANALYZE EXECUTE stmt (...);

 

 Here is the EXPLAIN ANALYZE output for prepared statement :

 

QUERY PLAN
"HashAggregate  (cost=29.37..29.40 rows=1 width=58) (actual time=10.600..10.600 rows=0 loops=1)"
"  ->  Nested Loop  (cost=9.55..29.36 rows=1 width=58) (actual time=10.594..10.594 rows=0 loops=1)"
"        Join Filter: (((""inner"".hat_no)::text = (""outer"".hat_no)::text) AND (""inner"".sefer_kod = ""outer"".sefer_kod) AND (""inner"".plan_tarihi = ""outer"".plan_tarihi) AND (""inner"".bin_yer_kod = ""outer"".bin_yer_kod) AND (""inner"".koltuk_no = ""outer"".koltuk_no))"
"        ->  Nested Loop  (cost=9.55..26.15 rows=1 width=93) (actual time=10.588..10.588 rows=0 loops=1)"
"              ->  Nested Loop  (cost=9.55..20.60 rows=1 width=65) (actual time=7.422..10.499 rows=1 loops=1)"
"                    ->  Nested Loop  (cost=9.55..14.62 rows=1 width=48) (actual time=5.455..7.247 rows=41 loops=1)"
"                          Join Filter: (""outer"".sefer_tip_kod = ""inner"".kod)"
"                          ->  Hash Join  (cost=9.55..13.58 rows=1 width=52) (actual time=5.432..6.131 rows=41 loops=1)"
"                                Hash Cond: (""outer"".kod = ""inner"".varis_yer_kod)"
"                                ->  Seq Scan on t_yer y2  (cost=0.00..3.44 rows=115 width=14) (actual time=0.018..0.375 rows=115 loops=1)"
"                                      Filter: ((iptal)::text = 'H'::text)"
"                                ->  Hash  (cost=9.55..9.55 rows=1 width=46) (actual time=5.352..5.352 rows=41 loops=1)"
"                                      ->  Merge Join  (cost=9.45..9.55 rows=1 width=46) (actual time=4.713..5.182 rows=41 loops=1)"
"                                            Merge Cond: (""outer"".kod = ""inner"".kalkis_yer_kod)"
"                                            ->  Index Scan using t_yer_pkey on t_yer y1  (cost=0.00..9.62 rows=115 width=14) (actual time=0.021..0.176 rows=40 loops=1)"
"                                                  Filter: ((iptal)::text = 'H'::text)"
"                                            ->  Sort  (cost=9.45..9.45 rows=1 width=40) (actual time=4.678..4.747 rows=41 loops=1)"
"                                                  Sort Key: h.kalkis_yer_kod"
"                                                  ->  Nested Loop  (cost=4.51..9.44 rows=1 width=40) (actual time=0.412..4.389 rows=41 loops=1)"
"                                                        Join Filter: ((""inner"".""no"")::text = (""outer"".hat_no)::text)"
"                                                        ->  Hash Join  (cost=4.51..8.09 rows=1 width=27) (actual time=0.386..1.137 rows=41 loops=1)"
"                                                              Hash Cond: ((""outer"".durumu)::text = (""inner"".kod)::text)"
"                                                              ->  Hash Join  (cost=2.25..5.80 rows=3 width=32) (actual time=0.193..0.751 rows=41 loops=1)"
"                                                                    Hash Cond: ((""outer"".ek_dev)::text = (""inner"".kod)::text)"
"                                                                    ->  Seq Scan on t_seferler s  (cost=0.00..3.21 rows=41 width=37) (actual time=0.009..0.258 rows=41 loops=1)"
"                                                                          Filter: (((iptal)::text = 'H'::text) AND ((iptal)::text = 'H'::text) AND ((firma_no)::text = '1'::text))"
"                                                                    ->  Hash  (cost=2.25..2.25 rows=2 width=5) (actual time=0.141..0.141 rows=2 loops=1)"
"                                                                          ->  Seq Scan on t_domains d1  (cost=0.00..2.25 rows=2 width=5) (actual time=0.048..0.131 rows=2 loops=1)"
"                                                                                Filter: ((name)::text = 'EKDEV'::text)"
"                                                              ->  Hash  (cost=2.25..2.25 rows=2 width=5) (actual time=0.160..0.160 rows=2 loops=1)"
"                                                                    ->  Seq Scan on t_domains d2  (cost=0.00..2.25 rows=2 width=5) (actual time=0.056..0.139 rows=2 loops=1)"
"                                                                          Filter: ((name)::text = 'SFR_DURUMU'::text)"
"                                                        ->  Seq Scan on t_hatlar h  (cost=0.00..1.23 rows=10 width=18) (actual time=0.004..0.045 rows=10 loops=41)"
"                                                              Filter: ('1'::text = (firma_no)::text)"
"                          ->  Seq Scan on t_sefer_tip t  (cost=0.00..1.03 rows=1 width=9) (actual time=0.004..0.009 rows=1 loops=41)"
"                                Filter: (((iptal)::text = 'H'::text) AND ('1'::text = (firma_no)::text))"
"                    ->  Index Scan using t_lokal_plan_sefer_liste_idx on t_lokal_plan lp  (cost=0.00..5.97 rows=1 width=22) (actual time=0.071..0.072 rows=0 loops=41)"
"                          Index Cond: (((lp.firma_no)::text = '1'::text) AND ((""outer"".hat_no)::text = (lp.hat_no)::text) AND (""outer"".kod = lp.sefer_kod) AND (lp.kalkis_tarihi = '2006-02-13'::date))"
"                          Filter: (lokal_kod = 62)"
"              ->  Index Scan using t_koltuk_son_durum_pkey on t_koltuk_son_durum sd  (cost=0.00..5.53 rows=1 width=28) (actual time=0.078..0.078 rows=0 loops=1)"
"                    Index Cond: (('1'::text = (sd.firma_no)::text) AND ((""outer"".hat_no)::text = (sd.hat_no)::text) AND (""outer"".kod = sd.sefer_kod) AND (""outer"".plan_tarihi = sd.plan_tarihi) AND (""outer"".yer_kod = sd.bin_yer_kod))"
"                    Filter: ((islem)::text = 'S'::text)"
"        ->  Index Scan using t_koltuk_islem_kod_ukey on t_koltuk_islem i  (cost=0.00..3.18 rows=1 width=57) (never executed)"
"              Index Cond: (i.kod = ""outer"".islem_kod)"
"              Filter: ((firma_no)::text = '1'::text)"
"Total runtime: 11.856 ms"

 

Adnan DURSUN

ASRIN Bilişim Ltd.Şti

Ankara / TURKEY

 

"Adnan DURSUN" <a_dursun@hotmail.com> writes:
>>>> EXPLAIN ANALYZE EXECUTE stmt (...);

>    Here is the EXPLAIN ANALYZE output for prepared statement :

This is exactly the same as the other plan --- you did not parameterize
the query.  To see what's going on, you need to insert PREPARE
parameters in the places where the function uses plpgsql variables.

            regards, tom lane

On Mon, Feb 13, 2006 at 07:57:07PM -0500, Tom Lane wrote:
> "Adnan DURSUN" <a_dursun@hotmail.com> writes:
> >>>> EXPLAIN ANALYZE EXECUTE stmt (...);
>
> >    Here is the EXPLAIN ANALYZE output for prepared statement :
>
> This is exactly the same as the other plan --- you did not parameterize
> the query.  To see what's going on, you need to insert PREPARE
> parameters in the places where the function uses plpgsql variables.

Actually it was an SQL function, but that also does PREPARE/EXECUTE,
right?

Adnan, what Tom is saying is that I requested this (simplified):

PREPARE stmt (integer) AS SELECT * FROM foo WHERE id = $1;
EXPLAIN ANALYZE EXECUTE stmt (12345);

but instead you appear to have done this:

PREPARE stmt AS SELECT * FROM foo WHERE id = 12345;
EXPLAIN ANALYZE EXECUTE stmt;

We can tell because if you had done it the first way (parameterized)
then the EXPLAIN ANALYZE output would have shown the parameters as
$1, $2, $3, etc., which it didn't.

--
Michael Fuhr

On Tue, Feb 14, 2006 at 11:33:57AM +0200, Adnan DURSUN wrote:
>         ->  Nested Loop  (cost=5.90..267.19 rows=3 width=101) (actual time=76.240..30974.777 rows=63193 loops=1)
>               ->  Nested Loop  (cost=5.90..123.48 rows=26 width=73) (actual time=32.082..4357.786 rows=14296 loops=1)

A prepared query is planned before the parameters' values are known,
so the planner can't take full advantage of column statistics to
estimate row counts.  The planner must therefore decide on a plan
that should be reasonable in most cases; apparently this isn't one
of those cases, as the disparity between estimated and actual rows
shows.  Maybe Tom (one of the core developers) can comment on whether
anything can be done to improve the plan in this case.

Absent a better solution, you could write a PL/pgSQL function and
build the query as a text string, then EXECUTE it.  That would give
you a new plan each time, one that can take better advantage of
statistics, at the cost of having to plan the query each time you
call the function (but you probably don't care about that cost
as long as the overall results are better).  Here's an example:

CREATE FUNCTION fooquery(qval text) RETURNS SETOF foo AS $$
DECLARE
    row    foo%ROWTYPE;
    query  text;
BEGIN
    query := 'SELECT * FROM foo WHERE val = ' || quote_literal(qval);

    FOR row IN EXECUTE query LOOP
        RETURN NEXT row;
    END LOOP;

    RETURN;
END;
$$ LANGUAGE plpgsql STABLE STRICT;

--
Michael Fuhr

I've run into this issue. It basically comes down to the plan that is being used inside the function is not the same as the plan used when you issue the query manually outside of the function.  Although I'm no expert on when plans are prepared and re-evaluated for functions, I know that they are not re-evaluated each time to execute the function.

So, what I did in such cases was to build up the sql query in a text variable inside my function, and then use the EXECUTE command inside the function.  When you use the EXECUTE command, the plan is prepared each time.  I know there is some minimal overhead of preparing the plan each time, but it seems like it's minor compared to the saving's you'll get.

- Mark

> in my case; both direct query and sql function gererate same execution plan. Also, execution plan belongs to the sql function better than direct sql > query plan. But, direct sql result comes less than 1 second. sql function result comes about in 50 seconds.

How are you getting at the plan inside your function?  If you just do an EXPLAIN on the function call you get a FUNCTION SCAN line in your plan, which tells you nothing.  I remember I had to work through some process for catching the output of the Explain plan in a cursor and returning that to actually see the plan.  I saw in a previous response he suggested using a PREPARE and EXECUTE against that.  I'm not sure that's the same as what's going on in the function (although I could be wrong).

Just humor me and try creating the sql query in the fuction in a text variable and then Executing it. 

Prior to that, however, you might try just recreating the function.  The plan may be re-evaluated at that point.

- Mark