Context switches may not be an issue any longer
Posted by sqlmdx on December 13, 2015
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.
Leave a Reply