I’ve described how to measure context switches some time ago in this post.
Given that with_clause allows to declare PL/SQL functions in 12c it’s interesting to analyze overhead for context switches in this case.
SQL> set timing on
SQL> create or replace function f(n in number) return number as
2 begin
3 return - n;
4 end;
5 /
Function created.
Elapsed: 00:00:00.10
SQL> with function f0(n number) return number is
2 begin
3 return - n;
4 end;
5 select max(f0(rownum)) m from dual connect by level <= 2e6
6 /
M
----------
-1
Elapsed: 00:00:02.14
SQL> select max(f(rownum)) m from dual connect by level <= 2e6
2 /
M
----------
-1
Elapsed: 00:00:05.35
So execution of function declared in a query completed more than two times faster.
Going further UDF pragma may significantly improve performance for PL/SQL functions called from SQL.
SQL> create or replace function f1(n in number) return number as
2 pragma udf;
3 begin
4 return - n;
5 end;
6 /
Function created.
Elapsed: 00:00:00.18
SQL> select max(f1(rownum)) m from dual connect by level <= 2e6
2 /
M
----------
-1
Elapsed: 00:00:02.03
In this case function executed even a bit faster than the one declared in a query.
Let’s have a look what is going on under the hood by decreasing number of calls from 2e6 to 3.
alter session set events '10938 trace name context forever, level 511'; select max(f(rownum)) m from dual connect by level <= 3;
511 = 1 + 2 + 4 + 8 + 16 + 32 + 64 + 128 + 256, please refer to “DBMS_TRACE Event Constants” in documentation for more details.
And similarly
with function f0(n number) return number is begin return - n; end; select max(f0(rownum)) m from dual connect by level <= 3 /
select max(f1(rownum)) m from dual connect by level <= 3;
According to below output in all cases 3 context switches took place. In case of declaration in a query also “Unknown Trace Event” occurred.
RUNID EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT
---------- ---------- --------------- --------------- ---------- ----------- --------------------------------------------------
12 1 PL/SQL Trace Tool started
12 2 Trace flags changed
12 3 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
12 4 F FUNCTION 3 1 New line executed
12 5 F FUNCTION 4 1 New line executed
12 6 PL/SQL Virtual Machine stopped
12 7 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
12 8 F FUNCTION 3 1 New line executed
12 9 F FUNCTION 4 1 New line executed
12 10 PL/SQL Virtual Machine stopped
12 11 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
12 12 F FUNCTION 3 1 New line executed
12 13 F FUNCTION 4 1 New line executed
12 14 PL/SQL Virtual Machine stopped
14 rows selected.
RUNID EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT
---------- ---------- --------------- --------------- ---------- ----------- --------------------------------------------------
13 1 PL/SQL Trace Tool started
13 2 Trace flags changed
13 3 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
13 4 <anonymous> ANONYMOUS BLOCK 5 1 New line executed
13 5 Unknown Trace Event
13 6 <anonymous> ANONYMOUS BLOCK 5 1 New line executed
13 7 PL/SQL Virtual Machine stopped
13 8 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
13 9 <anonymous> ANONYMOUS BLOCK 5 1 New line executed
13 10 Unknown Trace Event
13 11 <anonymous> ANONYMOUS BLOCK 5 1 New line executed
13 12 PL/SQL Virtual Machine stopped
13 13 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
13 14 <anonymous> ANONYMOUS BLOCK 5 1 New line executed
13 15 Unknown Trace Event
13 16 <anonymous> ANONYMOUS BLOCK 5 1 New line executed
13 17 PL/SQL Virtual Machine stopped
17 rows selected.
RUNID EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT
---------- ---------- --------------- --------------- ---------- ----------- --------------------------------------------------
15 1 PL/SQL Trace Tool started
15 2 Trace flags changed
15 3 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
15 4 F1 FUNCTION 4 1 New line executed
15 5 F1 FUNCTION 5 1 New line executed
15 6 PL/SQL Virtual Machine stopped
15 7 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
15 8 F1 FUNCTION 4 1 New line executed
15 9 F1 FUNCTION 5 1 New line executed
15 10 PL/SQL Virtual Machine stopped
15 11 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started
15 12 F1 FUNCTION 4 1 New line executed
15 13 F1 FUNCTION 5 1 New line executed
15 14 PL/SQL Virtual Machine stopped
14 rows selected.
So PL/SQL tracing is not very useful to see the differences. Let’s check behavior using hierarchical profiler.
exec dbms_hprof.start_profiling('UDUMP', '1.trc');
select max(f(rownum)) from dual connect by level <= 2e6;
exec dbms_hprof.stop_profiling;
select dbms_hprof.analyze('UDUMP', '1.trc') runid from dual;
And similarly for functions f0 and f1 and “select max(rownum) m from dual connect by level <= 2e6".
Results are following
SQL> select pci.runid,
2 level depth,
3 rpad(' ', (level - 1) * 3, ' ') || fi.function as name,
4 fi.subtree_elapsed_time,
5 fi.function_elapsed_time,
6 fi.calls
7 from (select runid, parentsymid, childsymid
8 from dbmshp_parent_child_info
9 union all
10 select runid, null, 2 from dbmshp_runs) pci
11 join dbmshp_function_info fi
12 on pci.runid = fi.runid
13 and pci.childsymid = fi.symbolid
14 where fi.function <> 'STOP_PROFILING'
15 connect by prior childsymid = parentsymid
16 and prior pci.runid = pci.runid
17 start with pci.parentsymid is null
18 and pci.runid in (6, 7, 8, 9);
RUNID DEPTH NAME SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME CALLS
---------- ---------- -------------------- -------------------- --------------------- ----------
6 1 __plsql_vm 1645310 1046294 2000001
6 2 __anonymous_block 162 162 1
6 2 F 598854 598854 2000000
7 1 __plsql_vm 122 38 2
7 2 __anonymous_block 84 84 2
8 1 __plsql_vm 145 51 2
8 2 __anonymous_block 89 89 1
8 2 F1 5 5 1
9 1 __plsql_vm 91 5 1
9 2 __anonymous_block 86 86 1
10 rows selected.
There were 2e6 calls for ordinary PL/SQL function, while function declared in with_clause caused one additional call of "__anonymous_block" as well as function declared with "pragma udf" was logged like executed only once.
This helps better understand difference in timings but on the other hand such results look a bit "inconsistent" with the results of PL/SQL tracing.
So even though PL/SQL tracing logged the same amount of context switches in all cases (PL/SQL Virtual Machine started => PL/SQL Virtual Machine stopped), more detailed results of hierarchical profiler has shown that only one PL/SQL call happens in case of "pragma udf"/"declaration in with_clause".
Declaring functions which are intensively used from SQL with "pragma udf" seems the better way to me since it allows much more flexible maintainability than functions declared in the queries.
