Thread: [HACKERS] why subplan is 10x faster then function?
Hi
I have some strange slow queries based on usage "view" functionsCREATE OR REPLACE FUNCTION ides_funcs.najdatsplt_cislo_exekuce(mid_najdatsplt bigint)
RETURNS character varying
LANGUAGE sql
STABLE
AS $function$
select CISLOEXEKUCE
from najzalobpr MT, najvzallok A1,
NAJZALOBST A2, NAJZALOBCE A3 where
MT.ID_NAJVZALLOK= A1.ID_NAJVZALLOK AND
A1.ID_NAJZALOBST=A2.ID_NAJZALOBST AND
A2.ID_NAJZALOBCE= A3.ID_NAJZALOBCE AND
MT.ID_NAJDATSPLT = mID_NAJDATSPLT LIMIT 1;
$function$ cost 20
;
I know so using this kind of functions is not good idea - it is customer old code generated from Oracle. I had idea about possible planner issues. But this is a executor issue.
-> Nested Loop Left Join (cost=0.71..780360.31 rows=589657 width=2700) (actual time=47796.588..47796.588 rows=0 loops=1)
-> Nested Loop (cost=0.29..492947.20 rows=589657 width=2559) (actual time=47796.587..47796.587 rows=0 loops=1)
-> Seq Scan on najdatsplt mt (cost=0.00..124359.24 rows=1106096 width=1013) (actual time=47796.587..47796.587 rows=0 loops=1)
Filter: (najdatsplt_cislo_exekuce(id_najdatsplt) IS NOT NULL)
Rows Removed by Filter: 1111654
-> Nested Loop (cost=0.29..19876820.11 rows=589657 width=2559) (actual time=3404.154..3404.154 rows=0 loops=1)
-> Seq Scan on najdatsplt mt (cost=0.00..19508232.15 rows=1106096 width=1013) (actual time=3404.153..3404.153 rows=0 loops=1)
Filter: ((SubPlan 11) IS NOT NULL)
Rows Removed by Filter: 1111654
SubPlan 11
-> Limit (cost=1.10..17.49 rows=1 width=144) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=1.10..17.49 rows=1 width=144) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=0.83..17.02 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=0.56..16.61 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=1111654)
Is known overhead of function execution?
2017-09-30 23:23 GMT+02:00 Pavel Stehule <pavel.stehule@gmail.com>:
Tested with same result on 9.6, 10.The execution plan is +/- same - the bottleneck is in function executionWhen I use correlated subquery, thenone function looks like this:HiI have some strange slow queries based on usage "view" functions
CREATE OR REPLACE FUNCTION ides_funcs.najdatsplt_cislo_exekuce(mid_najdatsplt bigint)
RETURNS character varying
LANGUAGE sql
STABLE
AS $function$
select CISLOEXEKUCE
from najzalobpr MT, najvzallok A1,
NAJZALOBST A2, NAJZALOBCE A3 where
MT.ID_NAJVZALLOK= A1.ID_NAJVZALLOK AND
A1.ID_NAJZALOBST=A2.ID_NAJZALOBST AND
A2.ID_NAJZALOBCE= A3.ID_NAJZALOBCE AND
MT.ID_NAJDATSPLT = mID_NAJDATSPLT LIMIT 1;
$function$ cost 20
;I know so using this kind of functions is not good idea - it is customer old code generated from Oracle. I had idea about possible planner issues. But this is a executor issue.when this function is evaluated as function, then execution needs about 46 sec
-> Nested Loop Left Join (cost=0.71..780360.31 rows=589657 width=2700) (actual time=47796.588..47796.588 rows=0 loops=1)
-> Nested Loop (cost=0.29..492947.20 rows=589657 width=2559) (actual time=47796.587..47796.587 rows=0 loops=1)
-> Seq Scan on najdatsplt mt (cost=0.00..124359.24 rows=1106096 width=1013) (actual time=47796.587..47796.587 rows=0 loops=1)
Filter: (najdatsplt_cislo_exekuce(id_najdatsplt) IS NOT NULL)
Rows Removed by Filter: 1111654
-> Nested Loop (cost=0.29..19876820.11 rows=589657 width=2559) (actual time=3404.154..3404.154 rows=0 loops=1)
-> Seq Scan on najdatsplt mt (cost=0.00..19508232.15 rows=1106096 width=1013) (actual time=3404.153..3404.153 rows=0 loops=1)
Filter: ((SubPlan 11) IS NOT NULL)
Rows Removed by Filter: 1111654
SubPlan 11
-> Limit (cost=1.10..17.49 rows=1 width=144) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=1.10..17.49 rows=1 width=144) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=0.83..17.02 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=0.56..16.61 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=1111654)Is known overhead of function execution?
profile of slow execution looks like
+ 24,71% 24,40% 48235 postmaster [.] SearchCatCache
+ 14,25% 0,00% 0 postmaster [unknown] [.] 0000000000000000
+ 9,76% 9,65% 19071 postmaster [.] TupleDescInitEntry
+ 3,91% 3,86% 7625 postmaster [.] ExecAssignScanProjectionInfoWithVarno
+ 3,56% 3,52% 6955 postmaster [.] AllocSetAlloc
+ 2,66% 2,63% 5193 postmaster [.] FunctionCall2Coll
+ 2,65% 2,62% 5183 postmaster [.] ResourceArrayRemove
+ 2,42% 2,39% 4719 postmaster [.] ExecTypeFromTLInternal
+ 2,21% 2,19% 4321 postmaster [.] DirectFunctionCall1Coll
+ 2,02% 2,00% 3961 postmaster [.] heap_getsysattr
+ 1,85% 1,82% 3604 postmaster [.] exprTypmod
+ 1,81% 1,79% 3540 postmaster [.] ResourceArrayAdd
+ 1,68% 1,66% 3282 postmaster [.] hash_uint32
+ 1,65% 1,63% 3214 postmaster [.] hash_search_with_hash_value
+ 1,64% 1,62% 3208 postmaster [.] CatalogCacheComputeHashValue
+ 1,28% 1,26% 2498 postmaster [.] MemoryContextAllocZeroAligned
+ 1,25% 1,24% 2446 postmaster [.] palloc0
+ 3,91% 3,86% 7625 postmaster [.] ExecAssignScanProjectionInfoWithVarno
+ 3,56% 3,52% 6955 postmaster [.] AllocSetAlloc
+ 2,66% 2,63% 5193 postmaster [.] FunctionCall2Coll
+ 2,65% 2,62% 5183 postmaster [.] ResourceArrayRemove
+ 2,42% 2,39% 4719 postmaster [.] ExecTypeFromTLInternal
+ 2,21% 2,19% 4321 postmaster [.] DirectFunctionCall1Coll
+ 2,02% 2,00% 3961 postmaster [.] heap_getsysattr
+ 1,85% 1,82% 3604 postmaster [.] exprTypmod
+ 1,81% 1,79% 3540 postmaster [.] ResourceArrayAdd
+ 1,68% 1,66% 3282 postmaster [.] hash_uint32
+ 1,65% 1,63% 3214 postmaster [.] hash_search_with_hash_value
+ 1,64% 1,62% 3208 postmaster [.] CatalogCacheComputeHashValue
+ 1,28% 1,26% 2498 postmaster [.] MemoryContextAllocZeroAligned
+ 1,25% 1,24% 2446 postmaster [.] palloc0
Any ides why SearchCatCache is called too often?
RegardsPavel
1 октября 2017 г. 12:42:14 GMT+03:00, Pavel Stehule <pavel.stehule@gmail.com> пишет: >2017-09-30 23:23 GMT+02:00 Pavel Stehule <pavel.stehule@gmail.com>: > >> Hi >> >> I have some strange slow queries based on usage "view" functions >> >> one function looks like this: >> >> CREATE OR REPLACE FUNCTION >ides_funcs.najdatsplt_cislo_exekuce(mid_najdatsplt >> bigint) >> RETURNS character varying >> LANGUAGE sql >> STABLE >> AS $function$ >> select CISLOEXEKUCE >> from najzalobpr MT, najvzallok A1, >> NAJZALOBST A2, NAJZALOBCE A3 where >> MT.ID_NAJVZALLOK= A1.ID_NAJVZALLOK AND >> A1.ID_NAJZALOBST=A2.ID_NAJZALOBST AND >> A2.ID_NAJZALOBCE= A3.ID_NAJZALOBCE AND >> MT.ID_NAJDATSPLT = mID_NAJDATSPLT LIMIT 1; >> $function$ cost 20 >> ; >> >> I know so using this kind of functions is not good idea - it is >customer >> old code generated from Oracle. I had idea about possible planner >issues. >> But this is a executor issue. >> >> when this function is evaluated as function, then execution needs >about 46 >> sec >> >> -> Nested Loop Left Join (cost=0.71..780360.31 rows=589657 >> width=2700) (actual time=47796.588..47796.588 rows=0 loops=1) >> -> Nested Loop (cost=0.29..492947.20 rows=589657 >width=2559) >> (actual time=47796.587..47796.587 rows=0 loops=1) >> -> Seq Scan on najdatsplt mt (cost=0.00..124359.24 >> rows=1106096 width=1013) (actual time=47796.587..47796.587 rows=0 >loops=1) >> Filter: >(najdatsplt_cislo_exekuce(id_najdatsplt) IS >> NOT NULL) >> Rows Removed by Filter: 1111654 >> >> When I use correlated subquery, then >> >> -> Nested Loop (cost=0.29..19876820.11 rows=589657 width=2559) >(actual >> time=3404.154..3404.154 rows=0 loops=1) >> -> Seq Scan on najdatsplt mt (cost=0.00..19508232.15 rows=1106096 >> width=1013) (actual time=3404.153..3404.153 rows=0 loops=1) >> Filter: ((SubPlan 11) IS NOT NULL) >> Rows Removed by Filter: 1111654 >> SubPlan 11 >> -> Limit (cost=1.10..17.49 rows=1 width=144) (actual >> time=0.002..0.002 rows=0 loops=1111654) >> -> Nested Loop (cost=1.10..17.49 rows=1 width=144) >(actual >> time=0.002..0.002 rows=0 loops=1111654) >> -> Nested Loop (cost=0.83..17.02 rows=1 >width=8) >> (actual time=0.002..0.002 rows=0 loops=1111654) >> -> Nested Loop (cost=0.56..16.61 rows=1 >> width=8) (actual time=0.002..0.002 rows=0 loops=1111654) >> >> The execution plan is +/- same - the bottleneck is in function >execution >> >> Tested with same result on 9.6, 10. >> >> Is known overhead of function execution? >> >> >profile of slow execution looks like > >+ 24,71% 24,40% 48235 postmaster [.] SearchCatCache >+ 14,25% 0,00% 0 postmaster [unknown] [.] >0000000000000000 >+ 9,76% 9,65% 19071 postmaster [.] >TupleDescInitEntry >+ 3,91% 3,86% 7625 postmaster [.] >ExecAssignScanProjectionInfoWithVarno >+ 3,56% 3,52% 6955 postmaster [.] AllocSetAlloc >+ 2,66% 2,63% 5193 postmaster [.] >FunctionCall2Coll >+ 2,65% 2,62% 5183 postmaster [.] >ResourceArrayRemove >+ 2,42% 2,39% 4719 postmaster [.] >ExecTypeFromTLInternal >+ 2,21% 2,19% 4321 postmaster [.] >DirectFunctionCall1Coll >+ 2,02% 2,00% 3961 postmaster [.] >heap_getsysattr >+ 1,85% 1,82% 3604 postmaster [.] >exprTypmod >+ 1,81% 1,79% 3540 postmaster [.] >ResourceArrayAdd >+ 1,68% 1,66% 3282 postmaster [.] >hash_uint32 >+ 1,65% 1,63% 3214 postmaster [.] >hash_search_with_hash_value >+ 1,64% 1,62% 3208 postmaster [.] >CatalogCacheComputeHashValue >+ 1,28% 1,26% 2498 postmaster [.] >MemoryContextAllocZeroAligned >+ 1,25% 1,24% 2446 postmaster [.] palloc0 > >Any ides why SearchCatCache is called too often? > > > >> Regards >> >> Pavel >> Looks like you've already collected profile with call-graph. So you can tell us where it were called from. With regards, -- Sokolov Yura aka funny_falcon -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
2017-10-01 12:45 GMT+02:00 Sokolov Yura <funny.falcon@postgrespro.ru>:
1 октября 2017 г. 12:42:14 GMT+03:00, Pavel Stehule <pavel.stehule@gmail.com> пишет:Looks like you've already collected profile with call-graph. So you can tell us where it were called from.>2017-09-30 23:23 GMT+02:00 Pavel Stehule <pavel.stehule@gmail.com>:
>
>> Hi
>>
>> I have some strange slow queries based on usage "view" functions
>>
>> one function looks like this:
>>
>> CREATE OR REPLACE FUNCTION
>ides_funcs.najdatsplt_cislo_exekuce(mid_najdatsplt
>> bigint)
>> RETURNS character varying
>> LANGUAGE sql
>> STABLE
>> AS $function$
>> select CISLOEXEKUCE
>> from najzalobpr MT, najvzallok A1,
>> NAJZALOBST A2, NAJZALOBCE A3 where
>> MT.ID_NAJVZALLOK= A1.ID_NAJVZALLOK AND
>> A1.ID_NAJZALOBST=A2.ID_NAJZALOBST AND
>> A2.ID_NAJZALOBCE= A3.ID_NAJZALOBCE AND
>> MT.ID_NAJDATSPLT = mID_NAJDATSPLT LIMIT 1;
>> $function$ cost 20
>> ;
>>
>> I know so using this kind of functions is not good idea - it is
>customer
>> old code generated from Oracle. I had idea about possible planner
>issues.
>> But this is a executor issue.
>>
>> when this function is evaluated as function, then execution needs
>about 46
>> sec
>>
>> -> Nested Loop Left Join (cost=0.71..780360.31 rows=589657
>> width=2700) (actual time=47796.588..47796.588 rows=0 loops=1)
>> -> Nested Loop (cost=0.29..492947.20 rows=589657
>width=2559)
>> (actual time=47796.587..47796.587 rows=0 loops=1)
>> -> Seq Scan on najdatsplt mt (cost=0.00..124359.24
>> rows=1106096 width=1013) (actual time=47796.587..47796.587 rows=0
>loops=1)
>> Filter:
>(najdatsplt_cislo_exekuce(id_najdatsplt) IS
>> NOT NULL)
>> Rows Removed by Filter: 1111654
>>
>> When I use correlated subquery, then
>>
>> -> Nested Loop (cost=0.29..19876820.11 rows=589657 width=2559)
>(actual
>> time=3404.154..3404.154 rows=0 loops=1)
>> -> Seq Scan on najdatsplt mt (cost=0.00..19508232.15 rows=1106096
>> width=1013) (actual time=3404.153..3404.153 rows=0 loops=1)
>> Filter: ((SubPlan 11) IS NOT NULL)
>> Rows Removed by Filter: 1111654
>> SubPlan 11
>> -> Limit (cost=1.10..17.49 rows=1 width=144) (actual
>> time=0.002..0.002 rows=0 loops=1111654)
>> -> Nested Loop (cost=1.10..17.49 rows=1 width=144)
>(actual
>> time=0.002..0.002 rows=0 loops=1111654)
>> -> Nested Loop (cost=0.83..17.02 rows=1
>width=8)
>> (actual time=0.002..0.002 rows=0 loops=1111654)
>> -> Nested Loop (cost=0.56..16.61 rows=1
>> width=8) (actual time=0.002..0.002 rows=0 loops=1111654)
>>
>> The execution plan is +/- same - the bottleneck is in function
>execution
>>
>> Tested with same result on 9.6, 10.
>>
>> Is known overhead of function execution?
>>
>>
>profile of slow execution looks like
>
>+ 24,71% 24,40% 48235 postmaster [.] SearchCatCache
>+ 14,25% 0,00% 0 postmaster [unknown] [.]
>0000000000000000
>+ 9,76% 9,65% 19071 postmaster [.]
>TupleDescInitEntry
>+ 3,91% 3,86% 7625 postmaster [.]
>ExecAssignScanProjectionInfoWi thVarno
>+ 3,56% 3,52% 6955 postmaster [.] AllocSetAlloc
>+ 2,66% 2,63% 5193 postmaster [.]
>FunctionCall2Coll
>+ 2,65% 2,62% 5183 postmaster [.]
>ResourceArrayRemove
>+ 2,42% 2,39% 4719 postmaster [.]
>ExecTypeFromTLInternal
>+ 2,21% 2,19% 4321 postmaster [.]
>DirectFunctionCall1Coll
>+ 2,02% 2,00% 3961 postmaster [.]
>heap_getsysattr
>+ 1,85% 1,82% 3604 postmaster [.]
>exprTypmod
>+ 1,81% 1,79% 3540 postmaster [.]
>ResourceArrayAdd
>+ 1,68% 1,66% 3282 postmaster [.]
>hash_uint32
>+ 1,65% 1,63% 3214 postmaster [.]
>hash_search_with_hash_value
>+ 1,64% 1,62% 3208 postmaster [.]
>CatalogCacheComputeHashValue
>+ 1,28% 1,26% 2498 postmaster [.]
>MemoryContextAllocZeroAligned
>+ 1,25% 1,24% 2446 postmaster [.] palloc0
>
>Any ides why SearchCatCache is called too often?
>
>
>
>> Regards
>>
>> Pavel
>>
There was zero info. I'll try to install this database on my notebook, and I'll see
Pavel
With regards,
--
Sokolov Yura aka funny_falcon
2017-09-30 23:23 GMT+02:00 Pavel Stehule <pavel.stehule@gmail.com>:
Tested with same result on 9.6, 10.The execution plan is +/- same - the bottleneck is in function executionWhen I use correlated subquery, thenone function looks like this:HiI have some strange slow queries based on usage "view" functions
CREATE OR REPLACE FUNCTION ides_funcs.najdatsplt_cislo_exekuce(mid_najdatsplt bigint)
RETURNS character varying
LANGUAGE sql
STABLE
AS $function$
select CISLOEXEKUCE
from najzalobpr MT, najvzallok A1,
NAJZALOBST A2, NAJZALOBCE A3 where
MT.ID_NAJVZALLOK= A1.ID_NAJVZALLOK AND
A1.ID_NAJZALOBST=A2.ID_NAJZALOBST AND
A2.ID_NAJZALOBCE= A3.ID_NAJZALOBCE AND
MT.ID_NAJDATSPLT = mID_NAJDATSPLT LIMIT 1;
$function$ cost 20
;I know so using this kind of functions is not good idea - it is customer old code generated from Oracle. I had idea about possible planner issues. But this is a executor issue.when this function is evaluated as function, then execution needs about 46 sec
-> Nested Loop Left Join (cost=0.71..780360.31 rows=589657 width=2700) (actual time=47796.588..47796.588 rows=0 loops=1)
-> Nested Loop (cost=0.29..492947.20 rows=589657 width=2559) (actual time=47796.587..47796.587 rows=0 loops=1)
-> Seq Scan on najdatsplt mt (cost=0.00..124359.24 rows=1106096 width=1013) (actual time=47796.587..47796.587 rows=0 loops=1)
Filter: (najdatsplt_cislo_exekuce(id_najdatsplt) IS NOT NULL)
Rows Removed by Filter: 1111654
-> Nested Loop (cost=0.29..19876820.11 rows=589657 width=2559) (actual time=3404.154..3404.154 rows=0 loops=1)
-> Seq Scan on najdatsplt mt (cost=0.00..19508232.15 rows=1106096 width=1013) (actual time=3404.153..3404.153 rows=0 loops=1)
Filter: ((SubPlan 11) IS NOT NULL)
Rows Removed by Filter: 1111654
SubPlan 11
-> Limit (cost=1.10..17.49 rows=1 width=144) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=1.10..17.49 rows=1 width=144) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=0.83..17.02 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=1111654)
-> Nested Loop (cost=0.56..16.61 rows=1 width=8) (actual time=0.002..0.002 rows=0 loops=1111654)Is known overhead of function execution?
looks like this nested query are expensive - some expensive operatiions are pushed to exec_init_node. When the query are executed from function, then exec_init_note is called too often
RegardsPavel
2017-10-01 12:45 GMT+02:00 Sokolov Yura <funny.falcon@postgrespro.ru>:
1 октября 2017 г. 12:42:14 GMT+03:00, Pavel Stehule <pavel.stehule@gmail.com> пишет:Looks like you've already collected profile with call-graph. So you can tell us where it were called from.>2017-09-30 23:23 GMT+02:00 Pavel Stehule <pavel.stehule@gmail.com>:
>
>> Hi
>>
>> I have some strange slow queries based on usage "view" functions
>>
>> one function looks like this:
>>
>> CREATE OR REPLACE FUNCTION
>ides_funcs.najdatsplt_cislo_exekuce(mid_najdatsplt
>> bigint)
>> RETURNS character varying
>> LANGUAGE sql
>> STABLE
>> AS $function$
>> select CISLOEXEKUCE
>> from najzalobpr MT, najvzallok A1,
>> NAJZALOBST A2, NAJZALOBCE A3 where
>> MT.ID_NAJVZALLOK= A1.ID_NAJVZALLOK AND
>> A1.ID_NAJZALOBST=A2.ID_NAJZALOBST AND
>> A2.ID_NAJZALOBCE= A3.ID_NAJZALOBCE AND
>> MT.ID_NAJDATSPLT = mID_NAJDATSPLT LIMIT 1;
>> $function$ cost 20
>> ;
>>
>> I know so using this kind of functions is not good idea - it is
>customer
>> old code generated from Oracle. I had idea about possible planner
>issues.
>> But this is a executor issue.
>>
>> when this function is evaluated as function, then execution needs
>about 46
>> sec
>>
>> -> Nested Loop Left Join (cost=0.71..780360.31 rows=589657
>> width=2700) (actual time=47796.588..47796.588 rows=0 loops=1)
>> -> Nested Loop (cost=0.29..492947.20 rows=589657
>width=2559)
>> (actual time=47796.587..47796.587 rows=0 loops=1)
>> -> Seq Scan on najdatsplt mt (cost=0.00..124359.24
>> rows=1106096 width=1013) (actual time=47796.587..47796.587 rows=0
>loops=1)
>> Filter:
>(najdatsplt_cislo_exekuce(id_najdatsplt) IS
>> NOT NULL)
>> Rows Removed by Filter: 1111654
>>
>> When I use correlated subquery, then
>>
>> -> Nested Loop (cost=0.29..19876820.11 rows=589657 width=2559)
>(actual
>> time=3404.154..3404.154 rows=0 loops=1)
>> -> Seq Scan on najdatsplt mt (cost=0.00..19508232.15 rows=1106096
>> width=1013) (actual time=3404.153..3404.153 rows=0 loops=1)
>> Filter: ((SubPlan 11) IS NOT NULL)
>> Rows Removed by Filter: 1111654
>> SubPlan 11
>> -> Limit (cost=1.10..17.49 rows=1 width=144) (actual
>> time=0.002..0.002 rows=0 loops=1111654)
>> -> Nested Loop (cost=1.10..17.49 rows=1 width=144)
>(actual
>> time=0.002..0.002 rows=0 loops=1111654)
>> -> Nested Loop (cost=0.83..17.02 rows=1
>width=8)
>> (actual time=0.002..0.002 rows=0 loops=1111654)
>> -> Nested Loop (cost=0.56..16.61 rows=1
>> width=8) (actual time=0.002..0.002 rows=0 loops=1111654)
>>
>> The execution plan is +/- same - the bottleneck is in function
>execution
>>
>> Tested with same result on 9.6, 10.
>>
>> Is known overhead of function execution?
>>
>>
>profile of slow execution looks like
>
>+ 24,71% 24,40% 48235 postmaster [.] SearchCatCache
>+ 14,25% 0,00% 0 postmaster [unknown] [.]
>0000000000000000
>+ 9,76% 9,65% 19071 postmaster [.]
>TupleDescInitEntry
>+ 3,91% 3,86% 7625 postmaster [.]
>ExecAssignScanProjectionInfoWi thVarno
>+ 3,56% 3,52% 6955 postmaster [.] AllocSetAlloc
>+ 2,66% 2,63% 5193 postmaster [.]
>FunctionCall2Coll
>+ 2,65% 2,62% 5183 postmaster [.]
>ResourceArrayRemove
>+ 2,42% 2,39% 4719 postmaster [.]
>ExecTypeFromTLInternal
>+ 2,21% 2,19% 4321 postmaster [.]
>DirectFunctionCall1Coll
>+ 2,02% 2,00% 3961 postmaster [.]
>heap_getsysattr
>+ 1,85% 1,82% 3604 postmaster [.]
>exprTypmod
>+ 1,81% 1,79% 3540 postmaster [.]
>ResourceArrayAdd
>+ 1,68% 1,66% 3282 postmaster [.]
>hash_uint32
>+ 1,65% 1,63% 3214 postmaster [.]
>hash_search_with_hash_value
>+ 1,64% 1,62% 3208 postmaster [.]
>CatalogCacheComputeHashValue
>+ 1,28% 1,26% 2498 postmaster [.]
>MemoryContextAllocZeroAligned
>+ 1,25% 1,24% 2446 postmaster [.] palloc0
>
>Any ides why SearchCatCache is called too often?
>
>
>
>> Regards
>>
>> Pavel
>>
I have more info no. Probably ExecInitIndexScan/ExecAssignResultTypeFromTL is very expensive, when it is called often (in this case for every row of table)
- 20,88% ExecInitIndexScan
- 16,31% ExecAssignResultTypeFromTL
- 16,22% ExecTypeFromTL
- 15,87% ExecTypeFromTLInternal
- 13,39% TupleDescInitEntry
- 9,40% SearchSysCache
- 8,65% SearchCatCache
- 1,87% CatalogCacheComputeHashValue
+ 1,27% DirectFunctionCall1Coll
- 16,31% ExecAssignResultTypeFromTL
- 16,22% ExecTypeFromTL
- 15,87% ExecTypeFromTLInternal
- 13,39% TupleDescInitEntry
- 9,40% SearchSysCache
- 8,65% SearchCatCache
- 1,87% CatalogCacheComputeHashValue
+ 1,27% DirectFunctionCall1Coll
or
- 79,65% exec_stmt_execsql ▒
- 77,50% SPI_execute_plan_with_paramlist ▒
- 77,12% _SPI_execute_plan ▒
- 74,06% _SPI_pquery ▒
- 64,21% ExecutorStart ▒
- 64,11% standard_ExecutorStart ▒
- 63,60% InitPlan ▒
- 61,62% ExecInitNode ▒
- 61,46% ExecInitLimit ▒
- 60,00% ExecInitNode ▒
- 59,89% ExecInitNestLoop ▒
- 58,71% ExecInitNode ▒
- 37,69% ExecInitNestLoop ▒
- 36,80% ExecInitNode ▒
- 21,36% ExecInitNestLoop ▒
- 20,38% ExecInitNode ▒
- 20,25% ExecInitIndexScan ▒
+ 11,58% ExecAssignResultTypeFromTL ▒
+ 2,46% ExecInitQual ▒
+ 1,95% ExecIndexBuildScanKeys ▒
+ 1,10% ExecOpenScanRelation ▒
+ 0,92% ExecAssignExprContext ▒
+ 0,65% ExecAssignScanProjectionInfo ▒
+ 0,63% index_open ▒
- 15,37% ExecInitIndexScan ▒
- 11,39% ExecAssignResultTypeFromTL ▒
- 11,31% ExecTypeFromTL ▒
- 11,06% ExecTypeFromTLInternal ▒
- 9,36% TupleDescInitEntry ▒
+ 6,59% SearchSysCache ▒
+ 0,95% ReleaseSysCache ▒
0,50% exprTypmod ▒
+ 1,05% ExecInitQual ▒
0,81% ExecIndexBuildScanKeys ▒
+ 0,63% ExecAssignScanProjectionInfo ▒
+ 20,88% ExecInitIndexScan ▒
0,54% ExecAssignResultTypeFromTL
- 77,50% SPI_execute_plan_with_paramlist ▒
- 77,12% _SPI_execute_plan ▒
- 74,06% _SPI_pquery ▒
- 64,21% ExecutorStart ▒
- 64,11% standard_ExecutorStart ▒
- 63,60% InitPlan ▒
- 61,62% ExecInitNode ▒
- 61,46% ExecInitLimit ▒
- 60,00% ExecInitNode ▒
- 59,89% ExecInitNestLoop ▒
- 58,71% ExecInitNode ▒
- 37,69% ExecInitNestLoop ▒
- 36,80% ExecInitNode ▒
- 21,36% ExecInitNestLoop ▒
- 20,38% ExecInitNode ▒
- 20,25% ExecInitIndexScan ▒
+ 11,58% ExecAssignResultTypeFromTL ▒
+ 2,46% ExecInitQual ▒
+ 1,95% ExecIndexBuildScanKeys ▒
+ 1,10% ExecOpenScanRelation ▒
+ 0,92% ExecAssignExprContext ▒
+ 0,65% ExecAssignScanProjectionInfo ▒
+ 0,63% index_open ▒
- 15,37% ExecInitIndexScan ▒
- 11,39% ExecAssignResultTypeFromTL ▒
- 11,31% ExecTypeFromTL ▒
- 11,06% ExecTypeFromTLInternal ▒
- 9,36% TupleDescInitEntry ▒
+ 6,59% SearchSysCache ▒
+ 0,95% ReleaseSysCache ▒
0,50% exprTypmod ▒
+ 1,05% ExecInitQual ▒
0,81% ExecIndexBuildScanKeys ▒
+ 0,63% ExecAssignScanProjectionInfo ▒
+ 20,88% ExecInitIndexScan ▒
0,54% ExecAssignResultTypeFromTL
ExecInit time is significantly higher than run time .. 65% / 6%
Regards
Pavel
With regards,
--
Sokolov Yura aka funny_falcon