Posts Tagged ‘“Unified Auditing”’

Unified Auditing – some insights

May 30, 2016 1 comment

Oracle 12c Unified Auditing is a brand new feature in the latest Oracle version which consolidates database level auditing records into a single location. DBAs can access the audit information from the view UNIFIED_AUDIT_TRAIL for all kind audit records, and they are

SQL> select distinct COMPONENT from all_unified_audit_actions;

Direct path API
Database Vault
Label Security

8 rows selected.

UNIFIED_AUDIT_TRAIL is a view owned by SYS and a public synonym pointing to this view.

SQL>  select owner,object_type from dba_objects where object_name='UNIFIED_AUDIT_TRAIL';

---------- ------------------------------
SYS        VIEW

Any database user who got ADUIT_ADMIN and AUDIT_VIEWER roles can administer and view the audit records respectively. Oracle separated the AUDITOR role from the traditional DBA/ SYSDBA roles so that and independent database auditor can operate outside the DBA group. To harden the security, no DBA or SYSDBA users can UPDATE or DELETE the audit records outside DBMS_AUDIT_MGMT.

Audit records are physically stored in AUDSYS schema along with other supporting indexes and BLOBS.

SSQL> select  owner,object_type,object_name  from dba_objects where owner='AUDSYS';

OWNER      OBJECT_TYPE                    OBJECT_NAME
---------- ------------------------------ ------------------------------
AUDSYS     INDEX                          CLI_LOB$7e10621c$1$1
AUDSYS     INDEX PARTITION                CLI_LOB$7e10621c$1$1
AUDSYS     INDEX                          CLI_TIME$7e10621c$1$1
AUDSYS     INDEX PARTITION                CLI_TIME$7e10621c$1$1
AUDSYS     LOB                            SYS_LOB0000091761C00014$$
AUDSYS     LOB PARTITION                  SYS_LOB0000091761C00014$$
AUDSYS     INDEX                          SYS_IL0000091761C00014$$
AUDSYS     INDEX PARTITION                SYS_IL0000091761C00014$$
AUDSYS     INDEX                          CLI_SCN$7e10621c$1$1
AUDSYS     INDEX PARTITION                CLI_SCN$7e10621c$1$1
AUDSYS     TABLE PARTITION                CLI_SWP$7e10621c$1$1
AUDSYS     TABLE                          CLI_SWP$7e10621c$1$1

12 rows selected.

You can see a table CLI_SWP$7e10621c$1$1 and the audit records are writing to this table and UNIFIED_AUDIT_TRAIL must be a view built on this table – just an assumption as the view is getting the records from the audit base table. Let us confirm that assumption by checking the execution plan for UNIFIED_AUDIT_TRAIL.

| Id  | Operation               | Name                    | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
|   0 | SELECT STATEMENT        |                         | 11738 |  1123K|     6  (34)| 00:00:01 |        |      |            |
|*  1 |  HASH JOIN RIGHT OUTER  |                         | 11738 |  1123K|     6  (34)| 00:00:01 |        |      |            |
|   2 |   INDEX FAST FULL SCAN  | I_STMT_AUDIT_OPTION_MAP |   308 |  1232 |     2   (0)| 00:00:01 |        |      |            |
|   3 |   NESTED LOOPS          |                         | 11738 |  1077K|     4  (50)| 00:00:01 |        |      |            |
|*  4 |    HASH JOIN RIGHT OUTER|                         | 11738 |   997K|     4  (50)| 00:00:01 |        |      |            |
|   5 |     INDEX FAST FULL SCAN| I_SYSTEM_PRIVILEGE_MAP  |   237 |  1185 |     2   (0)| 00:00:01 |        |      |            |
|   6 |     PX COORDINATOR      |                         |       |       |            |          |        |      |            |
|   7 |      PX SEND QC (RANDOM)| :TQ10000                | 11738 |   229K|     2 (100)| 00:00:01 |  Q1,00 | P->S | QC (RAND)  |
|*  8 |       VIEW              | GV$UNIFIED_AUDIT_TRAIL  |       |       |            |          |  Q1,00 | PCWP |            |
|*  9 |        FIXED TABLE FULL | X$UNIFIED_AUDIT_TRAIL   | 11738 |   229K|     2 (100)| 00:00:01 |  Q1,00 | PCWP |            |
|* 10 |    INDEX UNIQUE SCAN    | I_UNIFIED_AUDIT_ACTIONS |     1 |     7 |     0   (0)| 00:00:01 |        |      |            |

Predicate Information (identified by operation id):

   1 - access("AUDIT_OPTION"="AOM"."OPTION#"(+))
   4 - access("SPX"."PRIVILEGE"(+)=(-"SYSTEM_PRIVILEGE"))
   8 - filter("CON_ID"=0 OR "CON_ID"=1)
   9 - filter("CON_ID"=0 OR "CON_ID"=1)
  10 - access("AUDIT_TYPE"="ACT"."TYPE" AND "ACTION"="ACT"."ACTION")

   - statement not queuable: gv$ statement

     134589  recursive calls
          0  db block gets
     300896  consistent gets
          0  physical reads
          0  redo size
    2057935  bytes sent via SQL*Net to client
      85625  bytes received via SQL*Net from client
       7736  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
     116016  rows processed

That is bit interesting – the base table for UNIFIED_AUDIT_TRAIL is not the actual audit table in the SYSAUD schema, rather the records are coming from an X$ table known as X$UNIFIED_AUDIT_TRAIL and that is confusing. Moreover, the x$ fixed table is owned by SYS user, not in SYSAUD schema! You can see the fixed table X$UNIFIED_AUDIT_TRAIL existing in the V$FIXED_TABLE view.

SQL> select * from v$fixed_table where name='X$UNIFIED_AUDIT_TRAIL';

NAME                            OBJECT_ID TYPE   TABLE_NUM     CON_ID
------------------------------ ---------- ----- ---------- ----------
X$UNIFIED_AUDIT_TRAIL          4294953277 TABLE        641          0

So, there is some relation existing between the fixed table X$UNIFIED_AUDIT_TRAIL and CLI_SWP$7e10621c$1$1, the physical table where the actual data is existing. Moreover, every X$ table is a non-physical volatile table interfacing a memory structure and not really suitable to store the audit records. Trace 10046 should tell us more inside stories and relation between X$UNIFIED_AUDIT_TRAIL and CLI_SWP$7e10621c$1$1.

From the 10046 tracing came to a conclusion – the reading the audit records happening in two phases.

Phase 1: Oracle read the complete base audit table and populates the X$UNIFIED_AUDIT_TRAIL table for that container.

FETCH #140085662005752:c=0,e=28,p=0,cr=4,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120329
FETCH #140085662005752:c=0,e=113,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120480
FETCH #140085662005752:c=0,e=25,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120548
FETCH #140085662005752:c=0,e=19,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120601
FETCH #140085662005752:c=0,e=18,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120651
FETCH #140085662005752:c=999,e=55,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120736
FETCH #140085662005752:c=0,e=24,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120806
FETCH #140085662005752:c=0,e=21,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120860
FETCH #140085662005752:c=0,e=24,p=0,cr=4,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120916
FETCH #140085662005752:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850120966
FETCH #140085662005752:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850121014
FETCH #140085662005752:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850121059
FETCH #140085662005752:c=0,e=16,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850121104
FETCH #140085662005752:c=0,e=21,p=0,cr=4,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850121157
FETCH #140085662005752:c=0,e=23,p=0,cr=4,cu=0,mis=0,r=1,dep=2,og=1,plh=1405023807,tim=10748850121212
STAT #140085662005752 id=1 cnt=102 pid=0 pos=1 obj=0 op='PARTITION RANGE SINGLE PARTITION: KEY 1 (cr=286 pr=1 pw=0 time=66 us cost=496 size=70729009 card=32579)'
STAT #140085662005752 id=2 cnt=102 pid=1 pos=1 obj=91761 op='TABLE ACCESS BY LOCAL INDEX ROWID CLI_SWP$7e10621c$1$1 PARTITION: KEY 1 (cr=286 pr=1 pw=0 time=55 us cost=496 size=70729009 card=32579)'
STAT #140085662005752 id=3 cnt=169 pid=2 pos=1 obj=91771 op='INDEX RANGE SCAN CLI_LOB$7e10621c$1$1 PARTITION: KEY 1 (cr=103 pr=1 pw=0 time=462 us cost=496 size=0 card=50122)'
CLOSE #140085662005752:c=0,e=80,dep=2,type=1,tim=10748850121429

Phase : 2 – User get the audit records from the X$UNIFIED_AUDIT_TRAIL base table, need not worry about the rest of the containers audit data as it is filtered at the first place.

EXEC #140085626601992:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=1999586355,tim=10748918362622
FETCH #140085626601992:c=0,e=18,p=0,cr=1,cu=0,mis=0,r=1,dep=2,og=1,plh=1999586355,tim=10748918362650
WAIT #140085668747360: nam='PX Deq: reap credit' ela= 25 p1=0 p2=0 p3=0 obj#=91764 tim=10748918362746
WAIT #140085668747360: nam='PX Deq: reap credit' ela= 7 p1=0 p2=0 p3=0 obj#=91764 tim=10748918363179
WAIT #140085668747360: nam='PX Deq Credit: send blkd' ela= 435 sleeptime/senderid=268632063 passes=1 qref=7974696744 obj#=91764 tim=10748918363179
WAIT #140085668747360: nam='Disk file operations I/O' ela= 246 FileOperation=2 fileno=0 filetype=36 obj#=91764 tim=10748918364034
WAIT #140085668747360: nam='Disk file operations I/O' ela= 1115 FileOperation=8 fileno=1 filetype=36 obj#=91764 tim=10748918365176
WAIT #140085668747360: nam='Disk file operations I/O' ela= 1346 FileOperation=5 fileno=0 filetype=36 obj#=91764 tim=10748918366577
WAIT #140085668747360: nam='PX Deq: reap credit' ela= 31 p1=0 p2=0 p3=0 obj#=91764 tim=10748918366739
WAIT #140085668747360: nam='PX Deq: reap credit' ela= 56 p1=0 p2=0 p3=0 obj#=91764 tim=10748918371873
WAIT #140085668747360: nam='PX Deq: reap credit' ela= 9 p1=0 p2=0 p3=0 obj#=91764 tim=10748918371951
WAIT #140085668747360: nam='PX Deq Credit: send blkd' ela= 5155 sleeptime/senderid=268632063 passes=1 qref=7974696744 obj#=91764 tim=10748918371951
EXEC #140085668747360:c=22873523,e=158435095,p=32962,cr=231162,cu=889,mis=0,r=0,dep=1,og=1,plh=4119967587,tim=10748918372017
WAIT #140085668747360: nam='PX Deq: reap credit' ela= 9 p1=0 p2=0 p3=0 obj#=91764 tim=10748918372133
WAIT #140085668747360: nam='PX Deq: reap credit' ela= 15 p1=0 p2=0 p3=0 obj#=91764 tim=10748918380111
WAIT #140085668747360: nam='PX Deq: Execution Msg' ela= 8930 sleeptime/senderid=268632063 passes=2 p3=7974696744 obj#=91764 tim=10748918381073
STAT #140085668747360 id=1 cnt=0 pid=0 pos=1 obj=0 op='HASH JOIN RIGHT OUTER (cr=0 pr=0 pw=0 time=0 us cost=8 size=448192054 card=11738)'
STAT #140085668747360 id=2 cnt=0 pid=1 pos=1 obj=464 op='INDEX FAST FULL SCAN I_STMT_AUDIT_OPTION_MAP (cr=0 pr=0 pw=0 time=0 us cost=2 size=7084 card=308)'
STAT #140085668747360 id=3 cnt=0 pid=1 pos=2 obj=0 op='HASH JOIN RIGHT OUTER (cr=0 pr=0 pw=0 time=0 us cost=6 size=447922080 card=11738)'
STAT #140085668747360 id=4 cnt=0 pid=3 pos=1 obj=455 op='INDEX FAST FULL SCAN I_SYSTEM_PRIVILEGE_MAP (cr=0 pr=0 pw=0 time=0 us cost=2 size=5925 card=237)'
STAT #140085668747360 id=5 cnt=0 pid=3 pos=2 obj=0 op='HASH JOIN  (cr=0 pr=0 pw=0 time=0 us cost=4 size=447628630 card=11738)'
STAT #140085668747360 id=6 cnt=0 pid=5 pos=1 obj=4598 op='TABLE ACCESS FULL ALL_UNIFIED_AUDIT_ACTIONS (cr=0 pr=0 pw=0 time=0 us cost=2 size=8711 card=281)'
STAT #140085668747360 id=7 cnt=0 pid=5 pos=2 obj=0 op='PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)'
STAT #140085668747360 id=8 cnt=0 pid=7 pos=1 obj=0 op='PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us cost=2 size=27995130 card=11738)'
STAT #140085668747360 id=9 cnt=99506 pid=8 pos=1 obj=4294953278 op='VIEW  GV$UNIFIED_AUDIT_TRAIL (cr=231043 pr=32962 pw=0 time=108383889 us)'
STAT #140085668747360 id=10 cnt=99506 pid=9 pos=1 obj=0 op='FIXED TABLE FULL X$UNIFIED_AUDIT_TRAIL (cr=231043 pr=32962 pw=0 time=108237708 us cost=2 size=27995130 card=11738)'

So, that is where the fixed table X$UNIFIED_AUDIT_TRAIL come into play and this is not really going to be easy. Look at the below SELECT –

SQL> select * from unified_audit_trail;

158836 rows selected.

Elapsed: 00:01:16.35

I just got 158836 audit records and it took 76.35 seconds! Where the time is spent? Look at the recursive calls. I believe, these are DB calls for populating the fixed table, X$UNIFIED_AUDIT_TRAIL from the SYSAUD physical table where the consolidated audit records are located. Compared to traditional tables, your audit table access will be much slow.

     194858  recursive calls
       2285  db block gets
     398738  consistent gets
      46457  physical reads
        140  redo size
   84053638  bytes sent via SQL*Net to client
   35188183  bytes received via SQL*Net from client
     292940  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
     158836  rows processed

Currently, I have only few days of STANDARD audit records for a single PDB. It will be interesting to see, what will be response time and memory usage if I am hosting few years of audit records for security compliance and for a number of PDBs. One needs to do test the real impact before enabling the unified auditing and retaining the records for a longer period.

Note: These are my own opinions and research and can be wrong. Do your research before implementing and I will not accept any liabilities or damages.