SQL trace files, think time, and outliers

Idle wait events and think time

When creating a resource profile for a session or a group of sessions, one usually has to decide how to handle the so-called idle wait events, first and foremost, SQL*Net message from client.

One possibility would be to simply remove (physically or logically) those lines from the trace, thereby avoiding the question of whether some wait should be classified as client (= application) response time, or as think time.
Another would be be to define a threshold and exclude only those lines with wait times above the threshold. In that case, of course, I have to know what makes for a sensible threshold. I could base that threshold on network latencies but then, I might miss information about how the application behaves – what, from the database server’s point of view, is the response time of the application?

So here I want to try another approach, which is applying common outlier detection methods and find out how far that gets me ;-). My test material, this time, will be “real life”, non-artificial trace files, my tools will be the mining infrastructure based on external tables described in the latest three blog posts (starting with Mining SQL Trace Files Using External Tables Part 1: Getting the Timeline and, for ease of use, uploaded on github, and the outlier detection methods used will be four common ones described in http://d-scholarship.pitt.edu/7948/1/Seo.pdf.

Outlier detection methods

The four methods chosen were selected for being both commonly used as well as easily applicable. None of them are based on hypothesis testing as this would require knowledge of the underlying distribution.

Standard deviation method

One commonly used method is classifying as outliers those measurements whose distance from the mean is more than 2 or 3 standard deviations. We may already suspect that a method based on the normality assumption might not be the most effective here, but we’ll have a look anyway, be it only for establishing a baseline for the other methods.

Boxplot

As per Tukey’s boxplot method, values are seen as outliers when either below the first quartile minus 1.5* (3*, respectively) the interquartile range or above the third quartile plus 1.5 * (3*, respectively) the interquartile range (i.e., x < Q1 – 1.5[3]*IQR or x > Q3 + 1.5[3]*IQR).

MADe

Using the MADe method, values are classified as outliers when there distance from the median is more than 2 times (3 times, respectively) the median of absolute differences from the median, scaled by 1.483 (this scaled median of absolute differences is the so-called MADe).
I.e., x < median – 2[3] MADe or x > median – 2[3] MADe.

Median method

Using the median method, values are classified as outliers when they are below/above the median by more than n*IQR, when n is adjustable and chosen as 2.3 in the above mentioned paper.

Outlier detection methods applied

Inspecting the data

First, for all four trace files, let me indicate some summary statistics for the SQL*Net message from client event and present the data graphically.
All trace files have about 50.000 lines for this wait event, with minimum values of ~ 0.35-0.55 milliseconds, a median value of ~ 0.55-0.75 ms, an average of ~1.5-1.8 ms and a maximum ranging from 2.2 to 12 seconds approximately.

SQL> select min(elapsed) min, median(elapsed) median, trunc(avg(elapsed)) avg, trunc(stddev(elapsed)) stddev, max(elapsed) max, count(elapsed) cnt from wait where event='SQL*Net message from client';

-- file 1
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       368	  541	    1606      33961    3005346	    53124

-- file 2
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       523	  683	    1843      33805    2269024	    51485

-- file 3
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       339	  530	    1530      68874   11794066	    47152

-- file 4
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       547	  770	    1482      27795    3306050	    52608

The following diagrams should help visualize how the data is distributed. I’ve chosen a bucket size of 250 microseconds/0.25 milliseconds, which after some experimentation seemed to work best.
(This means that the numbers on the x axis have to be multiplied by 0.25 to give the elapsed time in microseconds).

SQLNET message from client wait elapsed time distribution

SQLNET message from client wait elapsed time distribution

SQLNET message from client wait elapsed time distribution

SQLNET message from client wait elapsed time distributionFor all methods, I’m interested in the upper threshold only. Now let’s see what the different methods yield.

Standard deviation method
with sd_data as
  (select avg(elapsed) avg, stddev(elapsed) stddev from wait where event='SQL*Net message from client'),
  bounds as 
    (select avg + 2*stddev upper_2sd, avg + 3*stddev upper_3sd from sd_data),
    candidates_2sd as
      (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_2sd)),
      candidates_3sd as
        (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_3sd))
        select '   2sd' "method", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates_2sd
        union all 
        select '   3sd', count(elapsed), round(min(elapsed)/1000, 1), round(max(elapsed)/1000, 1) from candidates_3sd;


-- file 1
method num_outliers smallest_outlier_ms  max_value_ms
------ ------------ ------------------- -------------
   2sd		 64		   75.2        3005.3
   3sd		 62		  106.6        3005.3

-- file 2
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
   2sd		 88		   70.5 	2269
   3sd		 84		  116.3 	2269

-- file 3
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
   2sd		 31		  145.9      11794.1
   3sd		 26		  221.7      11794.1

-- file 4
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
   2sd		 64		   62.4       3306.1
   3sd		 55		     93       3306.1

Not surprisingly (given the non-normality of the data), the standard deviation method does not yield useful results. We’ll certainly want to classify as think time values well below 100 ms.

Boxplot
with iqr_data as 
  (select percentile_cont(0.25) within group (order by elapsed) q1, percentile_cont(0.75) within group (order by elapsed) q3, abs(percentile_cont(0.25) within group (order by elapsed) - percentile_cont(0.75) within group (order by elapsed)) iqr from wait where event='SQL*Net message from client'),
  bounds as 
    (select q3 + 1.5 * iqr lower_bound, q3 + 3 * iqr upper_bound from iqr_data),
      candidates_inner as
          (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.lower_bound)),
          candidates_outer as
            (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_bound))
            select 'outside inner bound' "criterion", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates_inner
            union all
            select 'outside outer bound', count(elapsed), round(min(elapsed)/1000, 1), round(max(elapsed)/1000, 1) from candidates_outer
        ;
   

-- file 1
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    5370		  .9	   3005.3
outside outer bound	    3983		 1.1	   3005.3

-- file 2
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    3869		   1	     2269
outside outer bound	    2264		 1.2	     2269

-- file 3
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    2026		  .8	  11794.1
outside outer bound	     809		  .9	  11794.1

-- file 4
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    3836		 1.1	   3306.1
outside outer bound	    1418		 1.3	   3306.1

This looks better! If we choose the outer bound, waits have to exceed 1 ms to be classified as think time. However, looking at the diagrams, I’m not sure if this is not too low. Let’s compare with median-based methods.

MADe
with median as
  (select median(elapsed) median from wait where event='SQL*Net message from client'),
  abs_differences as
    (select abs(elapsed - median) absdiff from wait, median),
    mad_e as 
      (select median(absdiff) mad_e from abs_differences),
        bounds as 
          (select median + 2*mad_e upper_2mad_e, median + 3*mad_e upper_3mad_e from median, mad_e),
          candidates_2mad_e as
            (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_2mad_e)),
            candidates_3mad_e as
              (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_3mad_e))
                select '2mad_e' "method", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates_2mad_e
                union all 
                select '3mad_e', count(elapsed), round(min(elapsed)/1000, 1), round(max(elapsed)/1000, 1) from candidates_3mad_e;


-- file 1
method	num_outliers smallest_outlier_ms max_value_ms
------- ------------ ------------------- ------------
2mad_e   	2740		     1.6       3005.3
3mad_e  	1523		     2.2       3005.3

-- file 2
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
2mad_e		287		      2 	2269
3mad_e		208		    2.7 	2269

-- file 3
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
2mad_e		236		    1.6      11794.1
3mad_e		142		    2.1      11794.1

-- file 4
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
2mad_e		487		    2.3       3306.1
3mad_e		380		    3.1       3306.1

Now this – again choosing the outer bound, so we end up at a threshold of ~ 2-2.5 ms, looks much better to me. Perhaps it is still a little low, from visual inspection?

Median method
with iqr_data as 
  (select median(elapsed) median, percentile_cont(0.25) within group (order by elapsed) q1, percentile_cont(0.75) within group (order by elapsed) q3, abs(percentile_cont(0.25) within group (order by elapsed) - percentile_cont(0.75) within group (order by elapsed)) iqr from wait where event='SQL*Net message from client'),
  bounds as 
    (select median + 2.3 * iqr bound from iqr_data),
      candidates as
          (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.bound))
            select 'outside bound' "criterion", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates;


-- file 1   
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      5065		    .9	     3005.3

-- file 2
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      3575		     1	       2269

-- file 3
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      1729		    .8	    11794.1

-- file 4
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      3316		   1.1	     3306.1

The median method, at least for the trace files given, seems to yield results very similar to boxplot. Same as with boxplot, it might be too strict though.

Conclusion

Of course, four trace files, taken from the same application and under similar conditions, do not make for a representative sample. However, the idea here was to demonstrate the approach, i.e., looking at think time from an outlier detection perspective. For the given sample, the MADe method seems to yield a plausible classification. However, what classification makes sense is, in the end, a question of (at least) two things – the application we’re looking at (a real application? or end users, sitting at their terminals?) and what we want to do with the data (diagnose the database only or the client, too).

I guess it’s the latter case when this approach will be the most useful.

.

Advertisements

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 🙂