SQLMDX

Eventually it's all about data

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

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
%d bloggers like this: