Almost everyone who has some experience with Oracle knows about notorious notion called “context switches” between SQL and PL/SQL engines.
You can find a great explanation of context switches by Tom Kyte here.
Even though it’s quite simple to measure the overhead introduced by context switches, not so many developers know how to calculate exact number of context switches and moreover how to check whether they occurred or not in some cases.
So let’s start with synthetic example to show how context switches impact the performance and then walk though harness to measure them.
Functions mod1 and mod2 are supposed to check whether number is even or not.
create or replace function mod1(n in number) return number as begin return mod(n, 2); end mod1; / create or replace function mod2(n in number) return number as result number; begin select mod(n, 2) into result from dual; return result; end mod2; /
First query executes without any context switches, second one causes SQL -> PL/SQL -> SQL switches for each row and third one generates following sequence of calls for each row: SQL -> PL/SQL -> SQL -> PL/SQL -> SQL.
SQL> set timing on SQL> SQL> select sum(mod(rownum, 2)) s 2 from dual 3 connect by level <= 1e6; S ---------- 500000 Elapsed: 00:00:01.01 SQL> SQL> SQL> select sum(mod1(rownum)) s 2 from dual 3 connect by level <= 1e6; S ---------- 500000 Elapsed: 00:00:03.02 SQL> SQL> SQL> select sum(mod2(rownum)) s 2 from dual 3 connect by level <= 1e6; S ---------- 500000 Elapsed: 00:00:38.07
There are at least a couple of ways to check what exactly happens under the hood during execution of a statement.
- dbms_trace/event 10938
- dbms_hprof
1. dbms_trace/event 10938 (To create the trace tables, use the script rdbms/admin/tracetab.sql)
select event_seq, event_unit, event_unit_kind, event_line, stack_depth, event_comment, sum(decode(event_comment, 'PL/SQL Virtual Machine started', 1)) over(order by event_seq) context_switch from sys.plsql_trace_events where runid = (select max(runid) from sys.plsql_trace_events);
exec dbms_trace.set_plsql_trace(1); select sum(mod1(rownum)) s from dual;
SQL> @cswitch1 EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT CONTEXT_SWITCH ---------- --------------- --------------- ---------- ----------- -------------------------------------------------- -------------- 1 PL/SQL Trace Tool started 2 Trace flags changed 3 DBMS_TRACE PACKAGE BODY 21 3 Return from procedure call 4 DBMS_TRACE PACKAGE BODY 76 2 Return from procedure call 5 DBMS_TRACE PACKAGE BODY 81 1 Return from procedure call 6 PL/SQL Virtual Machine stopped 7 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started 1 8 MOD1 FUNCTION 3 1 PL/SQL Internal Call 1 9 PL/SQL Virtual Machine stopped 1
dbms_trace.set_plsql_trace is a PL/SQL routine and it remains a few lines (EVENT_SEQ 3-6) in output after itself. In order to avoid those waste lines it’s better to set event 10938 directly.
alter session set events '10938 trace name context forever, level 1'; select sum(mod1(rownum)) s from dual;
SQL> @cswitch1 EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT CONTEXT_SWITCH ---------- --------------- --------------- ---------- ----------- -------------------------------------------------- -------------- 1 PL/SQL Trace Tool started 2 Trace flags changed 3 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started 1 4 MOD1 FUNCTION 3 1 PL/SQL Internal Call 1 5 PL/SQL Virtual Machine stopped 1
To capture SQL calls from PL/SQL trace level should be increased to 33.
All possible trace levels are described here.
set lines 150 pages 150 column event_unit format a15 column event_unit_kind format a15 column event_comment format a40 select event_seq, event_unit, event_unit_kind, event_line, stack_depth, event_comment, sum(decode(event_comment, 'PL/SQL Virtual Machine started', 1)) over(order by event_seq) context_switch, decode(event_kind, 54, sum(decode(event_kind, 54, 1)) over(order by event_seq)) sql_invoke from sys.plsql_trace_events where runid = (select max(runid) from sys.plsql_trace_events);
alter session set events '10938 trace name context forever, level 33'; select sum(mod2(rownum)) s from dual;
SQL> @cswitch2 EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT CONTEXT_SWITCH SQL_INVOKE ---------- --------------- --------------- ---------- ----------- ---------------------------------------- -------------- ---------- 1 PL/SQL Trace Tool started 2 Trace flags changed 3 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started 1 4 MOD2 FUNCTION 4 1 SELECT MOD(:B1 , 2) FROM DUAL 1 1 5 PL/SQL Virtual Machine stopped 1
2. dbms_hprof
dbms_hprof provides services for fine grained tracking of elapsed time for each call and ability to view calls in a hierarchical form.
set lines 150 pages 150 column name format a30 column namespace format a10 select level depth, rpad(' ', (level - 1) * 3, ' ') || t.function name, t.namespace, t.subtree_elapsed_time, t.function_elapsed_time, t.calls from (select pci.parentsymid, pci.childsymid, fi.*, sign(fi_start.runid) is_root from dbmshp_parent_child_info pci join dbmshp_function_info fi on pci.runid = fi.runid and pci.childsymid = fi.symbolid left join dbmshp_function_info fi_start on pci.runid = fi_start.runid and pci.parentsymid = fi_start.symbolid and fi_start.function = '__plsql_vm') t connect by prior t.childsymid = t.parentsymid and prior t.runid = t.runid start with t.is_root = 1 and t.runid = (select max(runid) from dbmshp_function_info);
Let’s collect and analyze profiler’s data for “mod” functions in a following manner (approach for mod1 & mod2 is the same):
exec dbms_hprof.start_profiling('UDUMP', '1.trc'); select sum(mod(rownum, 2)) s from dual connect by level <= 1e6; exec dbms_hprof.stop_profiling; select dbms_hprof.analyze('UDUMP', '1.trc') runid from dual;
Results are fillowing:
DEPTH NAME NAMESPACE SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME CALLS ---------- ------------------------------ ---------- -------------------- --------------------- ---------- 1 __anonymous_block PLSQL 46 46 1 2 STOP_PROFILING PLSQL 0 0 1
DEPTH NAME NAMESPACE SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME CALLS ---------- ------------------------------ ---------- -------------------- --------------------- ---------- 1 __anonymous_block PLSQL 52 52 1 2 STOP_PROFILING PLSQL 0 0 1 1 MOD1 PLSQL 814236 814236 1000000
DEPTH NAME NAMESPACE SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME CALLS ---------- ------------------------------ ---------- -------------------- --------------------- ---------- 1 __anonymous_block PLSQL 54 54 1 2 STOP_PROFILING PLSQL 0 0 1 1 MOD2 PLSQL 33524106 3742238 1000000 2 __static_sql_exec_line4 SQL 29781868 29781868 1000000
Function “STOP_PROFILING” appears in all cases because profiler tracks the call which stops it.
In second case you also can see call of function MOD1 and in third one there are call of function MOD2 and call to SQL engine from PL/SQL.
Calls to SQL engine from PL/SQL are also being tracked under stat name “recursive calls”.
So autotrace for mod1 will show zero recursive calls while for mod2 this statistics increments by one.
Event 10938 may be very useful to check whether context switch take place in cases when function may not be executed.
1. Result cache function
create or replace function mod3(n in number) return number result_cache as begin dbms_application_info.set_client_info('***'); return mod(n, 2); end mod3;
column client_info format a10 exec dbms_result_cache.flush; exec dbms_application_info.set_client_info(null); select sum(mod3(rownum)) s from dual; select client_info from v$session where sid = userenv('sid'); exec dbms_application_info.set_client_info(null); alter session set events '10938 trace name context forever, level 1'; select sum(mod3(rownum)) s from dual; alter session set events '10938 trace name context off'; select client_info from v$session where sid = userenv('sid');
Output shows that after second call client_info is null which means instead of execution the function Oracle takes result from cache.
But event 10938 shows that context switch occurred even in this case:
SQL> @cswitch1 EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT CONTEXT_SWITCH ---------- --------------- --------------- ---------- ----------- -------------------------------------------------- -------------- 1 PL/SQL Trace Tool started 2 Trace flags changed 3 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started 1 4 PL/SQL Virtual Machine stopped 1
So PL/SQL engine checks that result in the cache and doesn’t execute code of the function.
2. Deterministic function
create or replace function mod4(n in number) return number deterministic as l_client_info varchar2(30); begin dbms_application_info.read_client_info(l_client_info); dbms_application_info.set_client_info(l_client_info || '*'); return mod(n, 2); end mod4;
column client_info format a10 exec dbms_application_info.set_client_info(null); alter session set events '10938 trace name context forever, level 1'; select sum(mod4(1)) s from dual connect by level <= 10; alter session set events '10938 trace name context off'; select client_info from v$session where sid = userenv('sid');
Output shows that client_info is ‘*’ which means that code of the function was executed only once.
And event 10938 shows that there was only one context switch.
SQL> @cswitch1 EVENT_SEQ EVENT_UNIT EVENT_UNIT_KIND EVENT_LINE STACK_DEPTH EVENT_COMMENT CONTEXT_SWITCH ---------- ------------------------- --------------- ---------- ----------- ---------------------------------------- -------------- 1 PL/SQL Trace Tool started 2 Trace flags changed 3 <anonymous> ANONYMOUS BLOCK 0 0 PL/SQL Virtual Machine started 1 4 MOD4 FUNCTION 4 1 Procedure Call 1 5 DBMS_APPLICATION_INFO PACKAGE BODY 55 2 PL/SQL Internal Call 1 6 DBMS_APPLICATION_INFO PACKAGE BODY 55 1 Return from procedure call 1 7 MOD4 FUNCTION 5 1 Procedure Call 1 8 DBMS_APPLICATION_INFO PACKAGE BODY 52 2 PL/SQL Internal Call 1 9 DBMS_APPLICATION_INFO PACKAGE BODY 52 1 Return from procedure call 1 10 MOD4 FUNCTION 6 1 PL/SQL Internal Call 1 11 PL/SQL Virtual Machine stopped 1
But in other circumstances output may be different and also this behavior is version dependent.
So please read advise by Tom Kyte here
When calling functions from SQL, you had better not rely on how often the functions get called, in what order, or whatever. In short, assume nothing.
One thought on “Measuring context switches”