Mining SQL Trace Files Using External Tables Part 3: Recursive Overhead

Recursive statements overhead

After first, introducing the idea of profiling SQL trace files using the external table preprocessor (see Mining SQL Trace Files Using External Tables Part 1: Getting the Timeline), and then, showing how this approach could yield the usual output of resource profiles etc. (in Mining SQL Trace Files Using External Tables Part 2: Resource Profiling), I’d finally like to come to one of the main features I created this for – an expressive and convenient way to view the SQL statements internally executed by Oracle, and to analyze the performance overhead caused by using different optional features.

I won’t try to draw any statistical conclusions here, as I’m restricting myself to a specific test setup and just one tracefile here (plus, one Oracle version, OS version, etc. etc. etc.), – the intent is just to demonstrate the usefulness of the method and the kinds of insight it yields.

The question

In my test setup, I’ll be using the three features standard auditing, fine grained auditing, and virtual private database. Although I’m on 12.1.0.2, I’m using traditional auditing here. As it’s an artificial setup, designed to demonstrate what’s possible with the approach, I’ll be using a PL/SQL procedure to iterate through statements against one and the same object; of course if you want to answer questions about the real impact of implementing auditing, FGA or VPD in a real application, real trace files from this application would have to be used.

So, this is the test setup we’ll be using to have a look at auditing, FGA and VPD effects:

/* drop all objects, for repeated execution */
begin
  dbms_fga.drop_policy('USR', 'MYOBJECTS', 'MYOBJECTS_FGA_POLICY');
end;
/
begin
  dbms_rls.drop_policy ( 
    object_schema   	 => 'USR', 
    object_name     	 => 'MYOBJECTS', 
    policy_name     	 => 'MYOBJECTS_POLICY');
end;
/
drop table myobjects;

/* sample table */
create table myobjects as select * from dba_objects;

/* test procedure issues select and DML for every 100th row, every second of which will be prohibited by VPD */
create or replace procedure generate_stuff_to_trace
is
  type t_numtab is table of number;
  l_numtab t_numtab;
  l_name varchar2(30);
begin
  select object_id bulk collect into l_numtab from myobjects;
  for i in 1..l_numtab.count loop
    if mod(i, 100) = 0 then
      dbms_session.set_identifier('client_' || to_char(i)); 
      begin
        select object_name into l_name from myobjects where object_id = l_numtab(i);
      exception
        when no_data_found then null;
      end;
      update myobjects set owner = null where object_id = l_numtab(i);
      delete from myobjects where object_id = l_numtab(i);
    end if;
  end loop;
  dbms_session.set_identifier(null);
end;
/

/* just audit every statement type on this table */
audit all on myobjects;

/* unconditional FGA, again for all types of select/DML */
begin
  dbms_fga.add_policy (
    object_schema      => 'USR', 
    object_name        => 'MYOBJECTS', 
    policy_name        => 'MYOBJECTS_FGA_POLICY',
    audit_condition    =>  null, 
    statement_types    => 'SELECT, INSERT, UPDATE, DELETE',
    audit_trail        =>  DBMS_FGA.DB_EXTENDED,
    audit_column_opts  =>  DBMS_FGA.ANY_COLUMNS);
end;
/

/* VPD policy, to be evaluated on context change */
begin
  dbms_rls.add_policy ( 
    object_schema   	 => 'USR', 
    object_name     	 => 'MYOBJECTS', 
    policy_name     	 => 'MYOBJECTS_POLICY',
    function_schema  	 => 'USR',
    policy_function  	 => 'MYOBJECTS_POLICY',
    statement_types  	 => 'SELECT, INSERT, UPDATE, DELETE',
    update_check     	 => TRUE,
    static_policy    	 => FALSE,
    policy_type      	 => DBMS_RLS.CONTEXT_SENSITIVE,
    sec_relevant_cols	 => 'OBJECT_ID, OWNER, OBJECT_TYPE, OBJECT_NAME'); 
end;
/

/* every second client will be blocked by this */
CREATE OR REPLACE FUNCTION MYOBJECTS_POLICY( 
  schema_var IN VARCHAR2,
  table_var  IN VARCHAR2
 )
 RETURN VARCHAR2
 IS
  retval VARCHAR2 (400);
 BEGIN
  retval := 'mod(to_number(substr(nvl(sys_context(''userenv'', ''client_identifier''), ''client_7777777777''), 8)), 200)  0' ;
  RETURN retval;
 END MYOBJECTS_POLICY;
/

/* first execution just to have blocks in cache */
exec generate_stuff_to_trace;
rollback;

/* performed with and without this */
alter system flush shared_pool;

/* execute test */
alter session set tracefile_identifier='audit_fga_vpd'; 
exec dbms_monitor.session_trace_enable(binds=>true);
exec generate_stuff_to_trace;
exec dbms_monitor.session_trace_disable; 

So what’s going on?

If I just execute the above without flushing the shared pool – surprisingly little!
This is the flow of statements, showing what is happening in chronological order and how long every call takes:

col tim for 999999999999
create or replace view timeline_diffs as
select
  t.call_type,
  t.sqlid,
  substr(cs.sql_text,1,30) sql_text,
  t.close_type,
  t.tim,
  t.tim - lag(t.tim) over (order by t.tim) timediff
from timeline_extended t
left join call c on (t.lineno=c.lineno)
join (select distinct sqlid, sql_text from cursor) cs on (t.sqlid=cs.sqlid)
where T.call_type in ('PARSE', 'EXEC', 'FETCH', 'CLOSE')
order by t.tim;

select * from timeline_diffs fetch next 50 rows only;

CALL_ SQLID	    SUBSTR(CS.SQL_TEXT,1,30)	   CLOSE_TYPE		TIM   TIMEDIFF

EXEC  31wf1v9f4ags6 BEGIN dbms_monitor.session_tra		 5061658516
CLOSE 31wf1v9f4ags6 BEGIN dbms_monitor.session_tra	    0	 5061659991	  1475
PARSE 6agkhk8bx8ra0 BEGIN generate_stuff_to_trace;		 5061660241	   250
PARSE fk584xkqxdatw insert into sys.fga_log$ (sess		 5061660810	   569
EXEC  fk584xkqxdatw insert into sys.fga_log$ (sess		 5061662883	  2073
CLOSE fk584xkqxdatw insert into sys.fga_log$ (sess	    0	 5061718106	 55223
EXEC  9vr8phz4kn5hg SELECT OBJECT_ID FROM MYOBJECT		 5061718456	   350
EXEC  4vs91dcv7u1p6 insert into sys.aud$( sessioni		 5061719824	  1368
FETCH 9vr8phz4kn5hg SELECT OBJECT_ID FROM MYOBJECT		 5061752683	 32859
CLOSE 9vr8phz4kn5hg SELECT OBJECT_ID FROM MYOBJECT	    3	 5061752859	   176
PARSE fk584xkqxdatw insert into sys.fga_log$ (sess		 5061754105	  1246
EXEC  fk584xkqxdatw insert into sys.fga_log$ (sess		 5061754899	   794
CLOSE fk584xkqxdatw insert into sys.fga_log$ (sess	    0	 5061754968	    69
EXEC  6r8xukyd3acaf SELECT OBJECT_NAME FROM MYOBJE		 5061755097	   129
EXEC  4vs91dcv7u1p6 insert into sys.aud$( sessioni		 5061756412	  1315
FETCH 6r8xukyd3acaf SELECT OBJECT_NAME FROM MYOBJE		 5061761298	  4886
CLOSE 6r8xukyd3acaf SELECT OBJECT_NAME FROM MYOBJE	    3	 5061761423	   125
PARSE fk584xkqxdatw insert into sys.fga_log$ (sess		 5061762180	   757
EXEC  fk584xkqxdatw insert into sys.fga_log$ (sess		 5061762914	   734
CLOSE fk584xkqxdatw insert into sys.fga_log$ (sess	    1	 5061762976	    62
EXEC  4tv1husqy68fm UPDATE MYOBJECTS SET OWNER = N		 5061768013	  5037
EXEC  4vs91dcv7u1p6 insert into sys.aud$( sessioni		 5061770303	  2290
CLOSE 4tv1husqy68fm UPDATE MYOBJECTS SET OWNER = N	    3	 5061770499	   196
PARSE fk584xkqxdatw insert into sys.fga_log$ (sess		 5061771597	  1098
EXEC  fk584xkqxdatw insert into sys.fga_log$ (sess		 5061772367	   770
CLOSE fk584xkqxdatw insert into sys.fga_log$ (sess	    3	 5061772412	    45
EXEC  dj5wz2dxcta77 DELETE FROM MYOBJECTS WHERE OB		 5061776760	  4348
EXEC  4vs91dcv7u1p6 insert into sys.aud$( sessioni		 5061778510	  1750
CLOSE dj5wz2dxcta77 DELETE FROM MYOBJECTS WHERE OB	    3	 5061778721	   211
PARSE fk584xkqxdatw insert into sys.fga_log$ (sess		 5061779091	   370
EXEC  fk584xkqxdatw insert into sys.fga_log$ (sess		 5061779790	   699
CLOSE fk584xkqxdatw insert into sys.fga_log$ (sess	    3	 5061779839	    49
EXEC  6r8xukyd3acaf SELECT OBJECT_NAME FROM MYOBJE		 5061779937	    98
EXEC  4vs91dcv7u1p6 insert into sys.aud$( sessioni		 5061781042	  1105
FETCH 6r8xukyd3acaf SELECT OBJECT_NAME FROM MYOBJE		 5061781168	   126
CLOSE 6r8xukyd3acaf SELECT OBJECT_NAME FROM MYOBJE	    3	 5061781230	    62
PARSE fk584xkqxdatw insert into sys.fga_log$ (sess		 5061781713	   483
EXEC  fk584xkqxdatw insert into sys.fga_log$ (sess		 5061782423	   710
CLOSE fk584xkqxdatw insert into sys.fga_log$ (sess	    3	 5061782464	    41
EXEC  4tv1husqy68fm UPDATE MYOBJECTS SET OWNER = N		 5061782541	    77
EXEC  4vs91dcv7u1p6 insert into sys.aud$( sessioni		 5061783692	  1151
CLOSE 4tv1husqy68fm UPDATE MYOBJECTS SET OWNER = N	    3	 5061783814	   122
PARSE fk584xkqxdatw insert into sys.fga_log$ (sess		 5061784107	   293
EXEC  fk584xkqxdatw insert into sys.fga_log$ (sess		 5061784725	   618
...
...

There are nearly no recursive statements at all in the tracefile, apart from the inserts into sys.aud$ and sys.fga$. And no sign of VPD at all.

What’s interesting to see is how cursor management works differently with standard auditing as compared to FGA.
The standard auditing’s insert into sys.aud$ cursor is never closed, not once during the tracing session; the FGA’s insert into sys.fga_log$ is re-parsed again on every use, this being a “softer soft parse” starting from after the third close.

select
  'standard auditing', round(avg(timediff)) avg_microsecs, round(stddev(timediff)) stddev_microsecs, round(stddev(timediff)/avg(timediff), 2) COV
  from timeline_diffs
  where sql_text like 'insert into sys.aud$%'
union all
select 
  'fga - parse', round(avg(timediff)) avg_microsecs, round(stddev(timediff)) stddev_microsecs, round(stddev(timediff)/avg(timediff), 2) COV
  from timeline_diffs
  where sql_text like 'insert into sys.fga_log$%' and call_type='PARSE'
union all
select 
  'fga - exec', round(avg(timediff)) avg_microsecs, round(stddev(timediff)) stddev_microsecs, round(stddev(timediff)/avg(timediff), 2) COV
  from timeline_diffs
  where sql_text like 'insert into sys.fga_log$%' and call_type='EXEC'
union all
select 
  'fga - close', round(avg(timediff)) avg_microsecs, round(stddev(timediff)) stddev_microsecs, round(stddev(timediff)/avg(timediff), 2) COV
  from timeline_diffs
  where sql_text like 'insert into sys.fga_log$%' and call_type='CLOSE'
;


'STANDARDAUDITING AVG_MICROSECS STDDEV_MICROSECS	COV
----------------- ------------- ---------------- ----------
standard auditing	   1472 	     672	.46
fga - parse		   1531 	    2089       1.36
fga - exec		    880 	     465	.53
fga - close		     83 	    1062      12.75

So – again, not extrapolating here, just taking the sample data for what they are – the overhead of standard auditing, in my case, was 1.5 milliseconds per insert on average, and very predictible, with a – comparatively – low coefficient of variation.
FGA, on average, took ~ 2.5 milliseconds per insert, where again the time taken by operations subsumed under ‘EXEC’ was rather predictible, while parse (and close) time tended to vary much more.

So what about VPD? Evidently, here, to investigate performance overhead we need a different approach – probably the usual two-factor setup based on representative experiments.

The rules

Personally, I was impressed, when looking at the recursive statements executed, that there were no occurrences visible of Oracle having to remind itself of the rules of the game – what to audit and under which conditions 😉 . Perhaps that’s not too astonishing either, as my procedure made use of just one object to audit and a small set of statements, so all policy stuff could be kept in memory.

Just to have a look at what happens when Oracle does not have the rules in memory, I ran the test again flushing the shared pool immediately before the traced run. In this case we see, at the beginning of the tracefile, the expected queries against rls$ (e.g., select pname,pname,stmt_type,check_opt,enable_flag,pfschma,ppname,pfname from rls$ where obj#=:1), fga$ (select pname, enable_flag, ptxt, pcol, pfschma, ppname, pfname, stmt_type, powner# from fga$ where obj# = :1) and aud_object_opt$ (select policy#, action# from aud_object_opt$ where object# = :1 and type = 2).

But as the timediff column shows, overhead for these calls is minimal.

CALL_ SQLID	    SQL_TEXT			   CLOSE_TYPE	     TIM   TIMEDIFF
----- ------------- ------------------------------ ---------- ---------- ----------
EXEC  31wf1v9f4ags6 BEGIN dbms_monitor.session_tra	      7759969665
CLOSE 31wf1v9f4ags6 BEGIN dbms_monitor.session_tra	    0 7759971054       1389
PARSE gngtvs38t0060 SELECT /*+ CONNECT_BY_FILTERIN	      7759973184       2130
EXEC  87gaftwrm2h68 select o.owner#,o.name,o.names	      7759978350       5166
FETCH 87gaftwrm2h68 select o.owner#,o.name,o.names	      7759978385	 35
CLOSE 87gaftwrm2h68 select o.owner#,o.name,o.names	    3 7759978418	 33
EXEC  87gaftwrm2h68 select o.owner#,o.name,o.names	      7759978509	 91
FETCH 87gaftwrm2h68 select o.owner#,o.name,o.names	      7759978526	 17
CLOSE 87gaftwrm2h68 select o.owner#,o.name,o.names	    3 7759978546	 20
EXEC  87gaftwrm2h68 select o.owner#,o.name,o.names	      7759978626	 80
FETCH 87gaftwrm2h68 select o.owner#,o.name,o.names	      7759978642	 16
CLOSE 87gaftwrm2h68 select o.owner#,o.name,o.names	    3 7759978673	 31
EXEC  gngtvs38t0060 SELECT /*+ CONNECT_BY_FILTERIN	      7759978915	242
FETCH gngtvs38t0060 SELECT /*+ CONNECT_BY_FILTERIN	      7759978961	 46
PARSE b1wc53ddd6h3p select audit$,options from pro	      7759979646	685
EXEC  7fwum1yuknrsh select t.ts#,t.file#,t.block#,	      7759979922	276
FETCH 7fwum1yuknrsh select t.ts#,t.file#,t.block#,	      7759980044	122
CLOSE 7fwum1yuknrsh select t.ts#,t.file#,t.block#,	    3 7759980073	 29
EXEC  gd28w82ct6rva select audit$ from tab$ where	      7759980223	150
FETCH gd28w82ct6rva select audit$ from tab$ where	      7759980254	 31
CLOSE gd28w82ct6rva select audit$ from tab$ where	    3 7759980272	 18
PARSE 04kug40zbu4dm select policy#, action# from a	      7759980341	 69
EXEC  04kug40zbu4dm select policy#, action# from a	      7759980513	172
FETCH 04kug40zbu4dm select policy#, action# from a	      7759980577	 64
CLOSE 04kug40zbu4dm select policy#, action# from a	    1 7759980634	 57
PARSE 04kug40zbu4dm select policy#, action# from a	      7759980966	332
EXEC  04kug40zbu4dm select policy#, action# from a	      7759981848	882
FETCH 04kug40zbu4dm select policy#, action# from a	      7759981930	 82
CLOSE 04kug40zbu4dm select policy#, action# from a	    1 7759981991	 61
EXEC  616m6uhpa2usu select i.obj#,i.ts#,i.file#,i.	      7759982186	195
FETCH 616m6uhpa2usu select i.obj#,i.ts#,i.file#,i.	      7759982565	379
EXEC  5n1fs4m2n2y0r select pos#,intcol#,col#,spare	      7759982676	111
FETCH 5n1fs4m2n2y0r select pos#,intcol#,col#,spare	      7759982754	 78
...

So, leaving this example and getting back to the beginning of the post, – what’s the point? It all depends on the questions you have – the method allows for all kinds of straightforward and less straightforward investigations 🙂

Advertisements

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