Audit Excess

So you’ve decided you want to audit a particular table in your database, and think that Oracle’s built in audit command will do what you want. You discover two options that seem to be relevant:

audit all on t1 by access;
audit all on t1 by session;

To check the audit state of anything in your schema you can then run a simple query – with a few SQL*Plus formatting commands – to see something like the following:

select
	*
from
	user_obj_audit_opts
;

OBJECT_NAME          OBJECT_TYPE       ALT AUD COM DEL GRA IND INS LOC REN SEL UPD REF EXE CRE REA WRI FBK
-------------------- ----------------- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
T1                   TABLE             S/S S/S S/S S/S S/S S/S S/S S/S S/S S/S S/S -/- -/- -/- -/- -/- S/S

The appearance of all the ‘S’ markers in my output is because I actually ran the two earlier commands in the order shown, so the ‘by session’ command after the ‘by access’ command. If I’d run the commands the other way round then you would have seen ‘A’s everywhere.

Each of the columns (‘ALT’,’SEL’, etc.) represents an action that can be audited, and the column content shows when and why it will be audited. The significance of the “X/X” is that the default audit is “always” but could be limited to “whenever successful” (the first ‘X’) or “whenever not successful” (the second  ‘X’).

The question is this: is auditing by session cheaper than auditing by action ? Your initial thought is that it probably ought to be because you only need one row per audited object per session when auditing by session, not one row per session per access – but how much do you really save ? When in doubt, one of the first tests is to run a little code with sql_trace enabled.

Here, from 10.2.0.3, is the interesting bit from tkprof after running “select * from t1” eleven times – enabling sql_trace after the first select so that I can see the work done by auditing for the last ten selects:

Audit by access
===============
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,
  userhost,terminal,action#,returncode, obj$creator,obj$name,auth$privileges,
  auth$grantee, new$owner,new$name,ses$actions,ses$tid,logoff$pread,
  logoff$lwrite,logoff$dead,comment$text,spare1,spare2,  priv$used,clientid,
  sessioncpu,proxy$sid,user$guid, instance#,process#,xid,scn,auditid,sqlbind,
  sqltext)
values
(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP),     :4,:5,:6,:7,:8,     :9,:10,:11,
  :12,     :13,:14,:15,:16,:17,     :18,:19,:20,:21,:22,     :23,:24,:25,:26,
  :27,     :28,:29,:30,:31,:32,:33,:34)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0          0         41          10
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       10      0.00       0.00          0          0         41          10

Audit by session
================
update sys.aud$ set ses$actions=merge$actions(ses$actions,:3), spare2=
  nvl(spare2,:4)
where
 sessionid=:1 and ses$tid=:2 and action#=103 and (priv$used=:5 or priv$used
  is null and :5 is null)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0         40         30          10
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       10      0.00       0.00          0         40         30          10

If you thought that auditing by session was a light-weight operation, think again. Interestingly, the auditing anomaly that I reported recently re-appears in the “audit by session” option. You will recall that when auditing is enabled, Oracle turns “update row” into “lock row, update row” – this happens to the audit table (aud$) as well, so every update to an aud$ row generates two redo entries. Here’s a comparison of the redo generated (by 10.2.0.3) for the two tests:

Audit by access
===============
redo entries                                                                30
redo size                                                               10,360
undo change vector size                                                  2,280

Audit by session
================
redo entries                                                                30
redo size                                                                8,112
undo change vector size                                                  2,320

The results are startlingly similar. For “audit by access” we see one redo entry for the table insert, one for the index insert, one for the commit; for “audit by session” we see one redo entry for the “lock row”, one for the “update row”, one for the commit. You may recall, by the way, that one of the comments on my blog about the lock/update anomaly pointed out that this bug was limited to 10.2.0.1 – 10.2.0.3; that may be true most of the time, but when you get to the aud$table the same lock/update pattern reappears.

And here’s a final kicker when you think about auditing: sometimes it seems like a good idea to write a pl/sql function with an embedded query that you can use in a select list rather than doing an outer join to a table in the from clause. If you enable auditing on the embedded table, every call to the pl/sql function results in an insert (or update) of a row in the audit table.

Footnote: If you want to see what the three-letter column names in the user_obj_audit_opts view mean, you can run a query like this:

column column_name format a6 heading "Option"
column comments format a70 heading "Description"

select
	column_name, comments
from
	all_col_comments
where
	owner = 'SYS'
and	table_name = 'USER_DEF_AUDIT_OPTS'
;

Option Description
------ ----------------------------------------------------------------------
ALT    Auditing ALTER WHENEVER SUCCESSFUL / UNSUCCESSFUL
AUD    Auditing AUDIT WHENEVER SUCCESSFUL / UNSUCCESSFUL
COM    Auditing COMMENT WHENEVER SUCCESSFUL / UNSUCCESSFUL
DEL    Auditing DELETE WHENEVER SUCCESSFUL / UNSUCCESSFUL
GRA    Auditing GRANT WHENEVER SUCCESSFUL / UNSUCCESSFUL
IND    Auditing INDEX WHENEVER SUCCESSFUL / UNSUCCESSFUL
INS    Auditing INSERT WHENEVER SUCCESSFUL / UNSUCCESSFUL
LOC    Auditing LOCK WHENEVER SUCCESSFUL / UNSUCCESSFUL
REN    Auditing RENAME WHENEVER SUCCESSFUL / UNSUCCESSFUL
SEL    Auditing SELECT WHENEVER SUCCESSFUL / UNSUCCESSFUL
UPD    Auditing UPDATE WHENEVER SUCCESSFUL / UNSUCCESSFUL
REF    Dummy REF column. Maintained for backward compatibility of the view
EXE    Auditing EXECUTE WHENEVER SUCCESSFUL / UNSUCCESSFUL
FBK    Auditing FLASHBACK WHENEVER SUCCESSFUL / UNSUCCESSFUL
REA    Auditing READ WHENEVER SUCCESSFUL / UNSUCCESSFUL

Update 26th Nov:

For news of a threat on upgrading from 10g to 11g (post 11.1.0.6) – see this thread on OTN. The table aud$ loses its index in 11.1.0.7, and any updates are (probably) replaced by an insert – so audit all on t1 by session turns into an insert for every access to t1; the impact on undo and redo doesn’t change all that much, but some people may see the size of the aud$ table increase dramatically.