Re: [HACKERS] why subplan is 10x faster then function?

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