Disk file operation I/O

We have just upgraded Siebel from version 7.x to 8.x. At the same time we upgraded the database from version 11.1.0.7 to 11.2.0.4. We had several sqls on top performance list, but what I noticed was that this sql took 20 minutes for each execution and it wasn’t doing many buffer gets.

SELECT To_char(current_timestamp AT TIME zone 'GMT', 
              'YYYY-MM-DD HH24:MI:SS TZD') AS curr_timestamp 
       , 
       Count(db_user)                      AS 
       failed_count 
FROM   sys.dba_common_audit_trail 
WHERE  action BETWEEN 100 AND 102 
       AND returncode != 0 
       AND extended_timestamp >= current_timestamp - 
                                 To_dsinterval('0 0:30:00') 

 

and we had 100% waits on Disk file operation I/O, this is a picture during the day
picture1
 
when analyzing my other performance problems I noticed this event as well in the ADDM report.
Finding 4: Unusual "User I/O" Wait Event
Impact is .74 active sessions, 9.22% of total activity.
-------------------------------------------------------
Wait event "Disk file operations I/O" in wait class "User I/O" was consuming significant database time.
Even ADDM calls it unusual..so what information can we get from this event ? (Oracle 11gR2 Reference Guide)
Disk file operations I/O
This event is used to wait for disk file operations (for example, open, close, seek, and resize). It is also used for miscellaneous I/O operations such as block dumps and password file accesses.
Wait Time: The wait time is the actual time it takes to do the I/O
Parameter Description
FileOperation Type of file operation
fileno File identification number
filetype Type of file (for example, log file, data file, and so on)
 
I searched and came across information from Kyle Hailey about the event. He also presented a sql to list more information.(see the refrence)
 
 FILE_TYPE                 FILE_OPERATION                                                    FILE#   COUNT(*)
------------------------- ------------------------------------------------------------ ---------- ----------

Data File                 file resize                                                          -1       4
Data Pump Dump File       file resize                                                           0       1
unknown 8                 wait for miscellaneous io (ftp, block dump, passwd file)              0      44608
Archive Log               file resize                                                           0       1
So we can see that the wait is not on data file, but on unknown 8. Also notice file# = 0.
I traced the sql and got the following:
call     count      cpu    elapsed       disk      query    current       rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse        1     0.01      0.02           4        155          0          0
Execute      1     0.00      0.00           0          0          0          0
Fetch        1   587.98   1262.70           1          1          0          0 
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total       3   587.99    1262.72           5        156          0          0

Elapsed times include waiting on following events:
 Event waited on                           Times  Max. Wait Total Waited
 ---------------------------------------- Waited ---------- ------------
 SQL*Net message to client                     1      0.00          0.00
 db file sequential read                       1      0.00          0.00
 Disk file operations I/O                 644080    504.62       1258.05
I discussed it with my colleague Peter and he remanded me that we had an issue with long running sqls against audit table some year ago. Then we noticed that we spent a lot of  time on cpu and had very little IO.
So we checked the parameters for auditing: 
NAME                                 TYPE        VALUE

------------------------------------ ----------- --------------------------------

audit_file_dest                      string      /oracle/misc/other/garg8p01
audit_sys_operations                 boolean     TRUE
audit_syslog_level                   string
audit_trail                          string      XML, EXTENDED
We looked how many files we had in audit_file_dest and found again plenty of  xml files. We don’t know exactly but we had at least 700.000 files (yes 700.000) if not more. Deleting the files solved the issue, we also noticed that we were auditing create session and believe it was the big contributor to the many files.
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