Thread: Function Scan costs

Function Scan costs

From
Andy Halsall
Date:
I'm calling functions via libpq. I've noticed that in the EXPLAIN analysis the time for the Function Scan is high relative to that of the actual query. In the example below (if I'm reading it correctly), the query seems to take just 0.022 ms whereas the time allocated to "Function Scan is 0.483ms. Is this to do with parsing original query and substituting params? Could somebody please explain? Thanks.
 
CONTEXT:  SQL statement "SELECT        n.node_type, r.rel_type, n.c_state, n.sort_key, n.d_state, n.node_id,
                              r.s_t_n, r.t_s_n, n.permissions, n.audit,
                              r.state, r.permissions, r.control,
                              r.prime_key, r.prime_key_len, r.sec_key, r.sec_key_len,
                              r.up_prime_key, r.up_prime_key_len, r.up_sec_key, r.up_sec_key_len
                FROM relationship r, node n
                WHERE r.rel_id = in_rel_id
                AND n.node_id = in_node_id
                AND n.d_state = 1"
        PL/pgSQL function "sp_select_by_node_rel" line 6 at SQL statement
LOG:  duration: 0.497 ms  plan:
        Query Text: select * from sp_select_by_node_rel($1,$2)
        Function Scan on public.sp_select_by_node_rel  (cost=0.25..0.26 rows=1 width=296) (actual time=0.482..0.483 rows=1 loo
ps=1)
          Output: tn_type, rel_type, tn_c_state, tn_sort, tn_d_state, tn_create_order, stn_guid, tsn_guid, tn_gen_perms, tn_au
dit, rel_state, sp_perms, rel_control, prime_key, prime_key_len, sec_key, sec_key_len, u_prime_key, u_prime_key_len, u_sec_key
, u_sec_key_len

          Function Call: sp_select_by_node_rel(82677::bigint, 71346::bigint)
          Buffers: shared hit=6
LOG:  duration: 0.030 ms  plan:
        Query Text: SELECT        n.node_type, r.rel_type, n.c_state, n.sort_key, n.d_state, n.node_id,
                              r.s_t_n, r.t_s_n, n.permissions, n.audit,
                              r.state, r.permissions, r.control,
                              r.prime_key, r.prime_key_len, r.sec_key, r.sec_key_len,
                              r.up_prime_key, r.up_prime_key_len, r.up_sec_key, r.up_sec_key_len
                FROM relationship r, node n
                WHERE r.rel_id = in_rel_id
                AND n.node_id = in_node_id
                AND n.d_state = 1
        Nested Loop  (cost=0.00..12.55 rows=1 width=130) (actual time=0.022..0.022 rows=1 loops=1)
          Output: n.node_type, r.rel_type, n.c_state, n.sort_key, n.d_state, n.node_id, r.s_t_n, r.t_s_n, n.permissions, n.aud
it, r.state, r.permissions, r.control, r.prime_key, r.prime_key_len, r.sec_key, r.sec_key_len, r.up_prime_key, r.up_prime_key_
len, r.up_sec_key, r.up_sec_key_len
          Buffers: shared hit=6
          ->  Index Scan using pk_relationship on public.relationship r  (cost=0.00..6.27 rows=1 width=81) (actual time=0.011.
.0.011 rows=1 loops=1)
                Output: r.rel_id, r.rel_type, r.s_t_n, r.t_s_n, r.state, r.control, r.sort_key, r.prime_key, r.prime_key_len,
r.sec_key, r.sec_key_len, r.up_sort_key, r.up_prime_key, r.up_prime_key_len, r.up_sec_key, r.up_sec_key_len, r.permissions, r.
created, r.t_s_n_type
                Index Cond: (r.rel_id = $1)
                Buffers: shared hit=3
          ->  Index Scan using pk_node on public.node n  (cost=0.00..6.27 rows=1 width=49) (actual time=0.008..0.008 rows=1 lo
ops=1)
                Output: n.node_id, n.node_type, n.c_state, n.d_state, n.sort_key, n.permissions, n.audit, n.pkg_id, n.created
                Index Cond: (n.node_id = $2)
                Filter: (n.d_state = 1)
                Buffers: shared hit=3

Re: Function Scan costs

From
Simon Riggs
Date:
On 27 June 2012 16:56, Andy Halsall <halsall_andy@hotmail.com> wrote:

> LOG:  duration: 0.497 ms  plan:
>         Query Text: select * from sp_select_by_node_rel($1,$2)
>         Function Scan on public.sp_select_by_node_rel  (cost=0.25..0.26
> rows=1 width=296) (actual time=0.482..0.483 rows=1 loo
> ps=1)
>           Output: tn_type, rel_type, tn_c_state, tn_sort, tn_d_state,
> tn_create_order, stn_guid, tsn_guid, tn_gen_perms, tn_au
> dit, rel_state, sp_perms, rel_control, prime_key, prime_key_len, sec_key,
> sec_key_len, u_prime_key, u_prime_key_len, u_sec_key
> , u_sec_key_len
>
>           Function Call: sp_select_by_node_rel(82677::bigint, 71346::bigint)
>           Buffers: shared hit=6

Seems OK to me.

--
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

Re: Function Scan costs

From
Jeff Davis
Date:
On Wed, 2012-06-27 at 15:56 +0000, Andy Halsall wrote:
> I'm calling functions via libpq. I've noticed that in the EXPLAIN
> analysis the time for the Function Scan is high relative to that of
> the actual query. In the example below (if I'm reading it correctly),
> the query seems to take just 0.022 ms whereas the time allocated to
> "Function Scan is 0.483ms. Is this to do with parsing original query
> and substituting params? Could somebody please explain? Thanks.

The times involved are quite small so it's hard to speculate on exactly
what's causing the difference (if there is a real difference).

If I had to guess, I would say that it's because a set-returning
function (SRF) always materializes the entire result. That's a
limitation of SRFs, and you might consider a foreign table instead if it
suits your needs.

Regards,
    Jeff Davis



Re: Function Scan costs

From
Andy Halsall
Date:
Thanks Jeff. From what I can see I'm not sure foreign tables will help us. The query is pretty efficient - two index scans and a single,  minimal result to materialize. I would've expected the time to find the result to be high in comparison to the overall time of the call and so I was interested in where the overheads were.
 
Looking at this a different way, I've written an immutable function that returns a fixed value. If I call this from libpq I can establish the cost in time of the overhead of the call from client and back. If I compare this with the time it takes to execute my real stored procedure (from original post), the overhead is ~40%. Seems high.
 
Andy
 
> Subject: Re: [NOVICE] Function Scan costs
> From: pgsql@j-davis.com
> To: halsall_andy@hotmail.com
> CC: pgsql-novice@postgresql.org
> Date: Wed, 27 Jun 2012 16:33:51 -0700
>
> On Wed, 2012-06-27 at 15:56 +0000, Andy Halsall wrote:
> > I'm calling functions via libpq. I've noticed that in the EXPLAIN
> > analysis the time for the Function Scan is high relative to that of
> > the actual query. In the example below (if I'm reading it correctly),
> > the query seems to take just 0.022 ms whereas the time allocated to
> > "Function Scan is 0.483ms. Is this to do with parsing original query
> > and substituting params? Could somebody please explain? Thanks.
>
> The times involved are quite small so it's hard to speculate on exactly
> what's causing the difference (if there is a real difference).
>
> If I had to guess, I would say that it's because a set-returning
> function (SRF) always materializes the entire result. That's a
> limitation of SRFs, and you might consider a foreign table instead if it
> suits your needs.
>
> Regards,
> Jeff Davis
>
>