Monday, November 30, 2020

High Disk file operations I/O Waits When Querying Unified Audit Trail

DB monitoring showed high waits for Disk file operations I/O event.
The select query originated from the EM console.
The database is running pure unified auditing (not mix mode) as such the dba_common_audit_trail part was of no concern. A simple select query on the unified audit trail also showed the same high wait times for Disk file operations I/O.
The issue was happening only on the CDB$root unified audit trail. The PDB audit trail had no issue.
Gathering statistics on audsys didn't help either.
exec dbms_STATS.GATHER_TABLE_STATS(OWNNAME=>'AUDSYS',TABNAME=>'AUD$UNIFIED',degree=>4);
Finally ran a 10046 trace and it showed the following for the Disk file operations I/O wait.
WAIT #140628544496888: nam='Disk file operations I/O' ela= 2352 FileOperation=8 fileno=1 filetype=36 obj#=-1 tim=5526698301528
It was starge objection id is -1 but stranger was there was no filetype 36 listed.
select file_no,filetype_id,FILETYPE_NAME from v$iostat_file where file_no=1 and filetype_id=36;

no rows selected 


At this stage looked at the historical data for the disk file operation I/O wait event on the AWR. It showed the first high waits occured soon after the swtichover to standby (circled in black). Even after switching back to original primary the wait events continued (circled in blue). Prior the switchover there was very low wait events and wait times on the primary.
When unified auditing is enabled on a standby it creates audit files on the local disk in the $ORACLE_BASE/audit/$ORACLE_SID directory. Based on above pattern a hypothesis was devised that unified audit trail could be getting populated from records in the audit files on the local disk that were craeted when it was a standby.
This hypothesis was tested out by archiving and removing the audit records created in the $ORACLE_BASE/audit/$ORACLE_SID. Afterwards querying the unified audit trail did not result in high disk file operation I/O.
Comparing the audit record count before the audit files on the local disks were removed
select count(*) from unified_audit_trail;

COUNT(*)
----------
761793 
and after
select count(*) from unified_audit_trail;

COUNT(*)
----------
516385
shows that some records from audit files on the local disk were used to populat the unified audit trail view.