Oracle Database Tips by Donald Burleson

Analysis of a busy iostat report

The average for blocks read and written per second is significantly higher on this device than it was during the baseline period.  In fact, the highest number of read and writes per second in the baseline (3,184 & 4,096) are close to the average during the performance problem (4,610 & 3,372).   

The question that must now be investigated is whether the I/O bottleneck is causing the performance problems the users are seeing, or if it is only symptomatic of the problem.  To put it another way, the users could be seeing slowness because something in the storage system changed. For example, a change from RAID 1+0 to RAID 5 might speed up reads, but slow down writes.  Or, given the reads and writes are of a similar magnitude in the baseline as well as in the busy measurements, some other operation could be suspected of causing a lot of extra operations on this device. 

To answer that question, it will be necessary to get into the database and investigate who is using most I/O operations, and what type of response time they are seeing.  The start_system_events.sql, finish_system_events.sql and difference_system_events.sql scripts may be useful in identifying what events are waiting most often.   

The output below is from difference_system_events.sql with a twist.  Since the results of the iostat indicate a high volume of activity, the sort order can be changed to show the top number of waits instead of total time or average wait.   

EVENT                        WAITS TIMEOUTS TIME WAITED AVG WAIT

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

db file scattered read         561        0       14283        0

db file sequential read        295        0        1665        0

rdbms ipc message              216      136       28787        0

log file parallel write         74       74           0        0

PL/SQL lock timer               73       73        3735        0

buffer busy waits               60       19        2614        0

SQL*Net message from client     51        0      205862       22

For the interval between the start and finish scripts being run, which was approximately the same time period that iostat was running, the db file scattered read and db file sequential read events were the most common events.  Even though the average wait for these events is reported as 0, it is important to remember that the time in the TIME WAITED column is reported in centiseconds. 

Seeing a measurable average wait above 20 milliseconds would not be expected, even for low performance I/O systems.  Some storage area network vendors predict 3 milliseconds or less(*).  As a representative for one vendor once explained that if they saw I/O response times of 30 milliseconds, it would be considered a major disaster, which would get their 24x7 attention until it was resolved. 

Therefore, even in an I/O problem of 10-20 milliseconds, the average time per wait could still show up as less than 2 centiseconds.  This is not to say that a high number of waits indicates a problem. It just means that based on other information available, namely iostat numbers, the quantity of db file scattered read and db file sequential read events deserve a bit more attention than the 0 centisecond average wait would normally get. 

The next stop then would be to see how the database is performing on all of its I/O operations.  A script called io_report_volume.sql can help here.  Depending on the number of files in the system, it may be helpful to add a condition to the where clause restricting this to the top 10 rows, or something manageable. 

* io_report_volume.sql

-- *************************************************

-- Copyright © 2003 by Rampant TechPress

-- This script is free for non-commercial purposes

-- with no warranties.  Use at your own risk.

--

-- To license this script for a commercial purpose,

-- contact info@rampant.cc

-- ************************************************* 

/* io_report_volume.sql */

column FILE_NAME       format a30

column PHYRDS          format 999,999

column PHYWRTS         format 999,999

column READTIM         format 999,999

column "READ AVG (ms)" format 999.99

column "TOTAL I/O"     format 999,999 

select

   FILE_NAME,

   PHYRDS,

   READTIM,

   PHYWRTS,

   READTIM / (PHYRDS + 1) "READ AVG (ms)",

   PHYRDS + PHYWRTS "TOTAL I/O" 

from

   V$FILESTAT a,

   DBA_DATA_FILES b

where:

See Code Depot

The above book excerpt is from:

Oracle Wait Event Tuning

High Performance with Wait Event Iinterface Analysis 

ISBN 0-9745993-7-9  

Stephen Andert 

http://www.rampant-books.com/book_2004_2_wait_tuning.htm