Measuring context switches

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.

1. dbms_trace/event 10938
2. 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.