Thread: Function Scan costs
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
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
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
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
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
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
>
>
> 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
>
>