2

Briefly, we have a pl/pgsql function which collects some intermediate data in several temporary tables ("on commit drop") and then returns REFCURSOR which joins those temporary tables with some static tables. We`ve noticed that after several executions and fetches of returned cursor (mostly after 4 executions) subsequent executions(more correctly, fetches of returned cusor) become time consuming. Test case looks like:

begin;
select t.v_resultset from dbo.Get_Object_Fields (v_cObj:='DOCUMENTS_0401002') t;
fetch all from "<unnamed portal 1>";
commit;

First suspicion is inefficiency of execution plan of resulting query.

Output of pg_stat_statement:

1)query with max(total_time) of 4th and subsequent execution

--------------------------------------------------------------------------------
userid              | 376846
dbid                | 892226
query               | select coalesce(so.code, t.obj_code) as obj_code
                |             ,c.code as class_name
                |             ,sp.code as parent_object
                |             ,EDITABLE,ASPTYPE,TITLE,VISIBLE,FIELD_DATA,ATTRIBUTES,FIELD_ALIAS,FIELD_KEY,COPY_METHOD,NASTR_SHOW_DISABLE,LEN_VALUE,ORDERS,FIELD_CALCULATION,INPUT_MASK
                |         from (
                |                select
                |                       object as OBJECT
                |                      ,obj_code as OBJ_CODE
                |                      ,max(parent_object) as PARENT_OBJECT
                |                      ,max(case when p.prop_code='EDITABLE' then substr(v.value,1,4000) end) as EDITABLE
                |                      ,max(case when p.prop_code='ASPTYPE' then substr(v.value,1,4000) end) as ASPTYPE
                |                      ,max(case when p.prop_code='TITLE' then substr(v.value,1,4000) end) as TITLE
                |                      ,max(case when p.prop_code='VISIBLE' then substr(v.value,1,4000) end) as VISIBLE
                |                      ,coalesce(nullif(max(case when p.prop_code='CONTROLSOURCE' then substr(v.value,1,4000) end),''),
                |
calls               | 1
total_time          | 3681.509
rows                | 37
shared_blks_hit     | 2759046
shared_blks_read    | 0
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit      | 19
local_blks_read     | 0
local_blks_dirtied  | 0
local_blks_written  | 0
temp_blks_read      | 62
temp_blks_written   | 60
blk_read_time       | 0
blk_write_time      | 0

2) corresponding query during first fast executions***

--------------------------------------------------------------------------------
userid              | 376846
dbid                | 892226
query               | select coalesce(so.code, t.obj_code) as obj_code
                |             ,c.code as class_name
                |             ,sp.code as parent_object
                |             ,EDITABLE,ASPTYPE,TITLE,VISIBLE,FIELD_DATA,ATTRIBUTES,FIELD_ALIAS,FIELD_KEY,COPY_METHOD,NASTR_SHOW_DISABLE,LEN_VALUE,ORDERS,FIELD_CALCULATION,INPUT_MASK
                |         from (
                |                select
                |                       object as OBJECT
                |                      ,obj_code as OBJ_CODE
                |                      ,max(parent_object) as PARENT_OBJECT
                |                      ,max(case when p.prop_code='EDITABLE' then substr(v.value,1,4000) end) as EDITABLE
                |                      ,max(case when p.prop_code='ASPTYPE' then substr(v.value,1,4000) end) as ASPTYPE
                |                      ,max(case when p.prop_code='TITLE' then substr(v.value,1,4000) end) as TITLE
                |                      ,max(case when p.prop_code='VISIBLE' then substr(v.value,1,4000) end) as VISIBLE
                |                      ,coalesce(nullif(max(case when p.prop_code='CONTROLSOURCE' then substr(v.value,1,4000) end),''),
                |
calls               | 1
total_time          | 23.303
rows                | 37
shared_blks_hit     | 5154
shared_blks_read    | 0
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit      | 19
local_blks_read     | 0
local_blks_dirtied  | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 0
blk_write_time      | 0

But I can`t get why plan has been changing after 4 executions? So the questions are:

  1. why execution of a query becomes slow after 4th execution of stored function?
  2. how to get the real execution plan of queries inside pl/pgsql functions?

Thank you.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.