Oracle I/O latency monitoring
One thing that I have found sorely missing in the performance pages of Enterprise Manager is latency values for various types of I/O. The performance page or top activity may show high I/O waits but it won’t indicated if the latency of I/O is unusually high or not. Thus I put together a shell script that shows latency for the main I/O waits
- db file sequential read
- db file scattered read
- log file parallel write
- direct path reads
- direct path reads temp
Of course it would be nice to add a few others like direct path writes, direct path writes temp and log file sync but there is only so much room in the screen width.
The script is called oramon.sh and is available on github at
https://github.com/khailey/oramon/blob/master/oramon.sh
Example:
$ oramon.sh
Usage: oramon.sh [username] [password] [host] [sid] <port=1521> <runtime=3600>
$ ./oramon.sh system sys 172.16.100.81 vsol
RUN_TIME=-1
COLLECT_LIST=
FAST_SAMPLE=iolatency
TARGET=172.16.100.81:vsol
DEBUG=0
Connected, starting collect at Wed Apr 18 18:41:13 UTC 2012
starting stats collecting
single block logfile write multi block direct read direct read temp
ms IOP/s ms IOP/s ms IOP/s ms IOP/s ms IOP/s
20.76 27.55 32.55 .71 3.50 .00 .00 .01 .00 .00
.00 .20 .00 .00 .00 .00
34.93 369.64 116.79 3.55 .00 .00 .00
31.43 640.33 92.40 8.33 .00 .00 .00
39.39 692.33 111.69 8.00 .00 .00 .00
The first line of output is the average since the database started up.
The subsequent lines are the averages since the last line which is 5 seconds by default.
One should be able to see immediately how much activity there is on the database and the latency for the basic types of database I/O.
Reads
Single block reads are the typical I/O from a database which would happen for example when reading a row in a table with indexes in place.
Multi block reads are common as well is which would happen when for example summing the values over all rows in a table.
Direct reads are less common but quite normal and happen almost exclusively for parallel query though may be used for other activities especially in newer version of Oracle such as 11.2. Direct reads are multiblock reads that by pass the Oracle buffer cache. The size varies from a datablock, such as 8k to 1MB.
Direct read temp happens when a sort has overflowed memory limits and been written to disk. Direct reads temp are multiblock reads that by pass the Oracle buffer cache. The size varies from a datablock, such as 8k to 1MB.
Writes
Logfile writes are the only writes that database users wait for in general. Actually users only wait when the commit, which then is a wait for a signal from the log writer that their particular redo data is on disk which could have already happened. Typically the user wait time is a bit slower than the logwrite time but in general it’s close, ie within a few milliseconds. The farther apart the user wait time is from the log write time the more likely there is a CPU, paging or other concurrency problem on the VDB host slowing down the users signalling and wake up time.
oramon.sql : Oracle Latency Query
If for some reason the shell script isn’t able to connect to the database, then the same data can be collected manually by running the SQL query in SQL*Plus by hand.
The following two SQL queries, oramon_setup.sql and oramon.sql are available on github at
https://github.com/khailey/oramon
If you want to see the latencies over periods shorter than 60s, then you have to collect the values of the cumulative counters at time A, then again at time B and take the difference. The following two queries, oramon.sql and oramon_setup.sql, are available on ftp site
column seq_ms for 9999.99 column seq_ct for 9999.99 column lfpw_ms for 9999.99 column lfpw_ct for 9999.99 column seq_ms for 9999.99 column scat_ct for 9999.99 column dpr_ms for 9999.99 column dpr_ct for 9999.99 column dprt_ms for 9999.99 column dprt_ct for 9999.99 column prevdprt_ct new_value prevdprt_ct_var column prevdprt_tm new_value prevdprt_tm_var column prevdpwt_ct new_value prevdpwt_ct_var column prevdpwt_tm new_value prevdpwt_tm_var column prevdpr_ct new_value prevdpr_ct_var column prevdpr_tm new_value prevdpr_tm_var column prevdpw_ct new_value prevdpw_ct_var column prevdpw_tm new_value prevdpw_tm_var column prevseq_ct new_value prevseq_ct_var column prevseq_tm new_value prevseq_tm_var column prevscat_ct new_value prevscat_ct_var column prevscat_tm new_value prevscat_tm_var column prevlfpw_ct new_value prevlfpw_ct_var column prevlfpw_tm new_value prevlfpw_tm_var column prevsec new_value prevsec_var select 0 prevsec from dual; select 0 prevseq_tm from dual; select 0 prevseq_ct from dual; select 0 prevscat_ct from dual; select 0 prevscat_tm from dual; select 0 prevlfpw_ct from dual; select 0 prevlfpw_tm from dual; select 0 prevdprt_ct from dual; select 0 prevdprt_tm from dual; select 0 prevdpwt_ct from dual; select 0 prevdpwt_tm from dual; select 0 prevdpr_ct from dual; select 0 prevdpr_tm from dual; select 0 prevdpw_ct from dual; select 0 prevdpw_tm from dual; column prevdprt_ct noprint column prevdprt_tm noprint column prevdpwt_ct noprint column prevdpwt_tm noprint column prevdpr_ct noprint column prevdpr_tm noprint column prevdpw_ct noprint column prevdpw_tm noprint column prevseq_ct noprint column prevseq_tm noprint column prevscat_ct noprint column prevscat_tm noprint column prevlfpw_ct noprint column prevlfpw_tm noprint column prevsec noprint
Run following query to see the current latency for
- single block read
- log file parallel write
- multi-block read
oramon.sql
select
round(seqtm/nullif(seqct,0),2) seq_ms,
round(seqct/nullif(delta,0),2) seq_ct,
round(lfpwtm/nullif(lfpwct,0),2) lfpw_ms,
round(lfpwct/nullif(delta,0),2) lfpw_ct,
round(scattm/nullif(scatct,0),2) scat_ms,
round(scatct/nullif(delta,0),0) scat_ct,
round(dprtm/nullif(dprct,0),2) dpr_ms,
round(dprct/nullif(delta,0),2) dpr_ct,
round(dprttm/nullif(dprtct,0),2) dprt_ms,
round(dprtct/nullif(delta,0),2) dprt_ct,
prevseq_ct, prevscat_ct, prevseq_tm, prevscat_tm, prevsec,prevlfpw_tm,prevlfpw_ct
, prevdpr_ct, prevdpr_tm , prevdprt_ct, prevdprt_tm , prevdpw_ct, prevdpw_tm
, prevdpwt_ct, prevdpwt_tm
from
(select
sum(decode(event,'db file sequential read', round(time_waited_micro/1000) - &prevseq_tm_var,0)) seqtm,
sum(decode(event,'db file scattered read', round(time_waited_micro/1000) - &prevscat_tm_var,0)) scattm,
sum(decode(event,'log file parallel write', round(time_waited_micro/1000) - &prevlfpw_tm_var,0)) lfpwtm,
sum(decode(event,'db file sequential read', round(time_waited_micro/1000) ,0)) prevseq_tm,
sum(decode(event,'db file scattered read', round(time_waited_micro/1000) ,0)) prevscat_tm,
sum(decode(event,'log file parallel write', round(time_waited_micro/1000) ,0)) prevlfpw_tm,
sum(decode(event,'db file sequential read', total_waits - &prevseq_ct_var,0)) seqct,
sum(decode(event,'db file scattered read', total_waits - &prevscat_ct_var,0)) scatct,
sum(decode(event,'log file parallel write', total_waits - &prevlfpw_ct_var,0)) lfpwct,
sum(decode(event,'db file sequential read', total_waits ,0)) prevseq_ct,
sum(decode(event,'db file scattered read', total_waits ,0)) prevscat_ct,
sum(decode(event,'log file parallel write', total_waits ,0)) prevlfpw_ct,
sum(decode(event,'direct path read', round(time_waited_micro/1000) - &prevdpr_tm_var,0)) dprtm,
sum(decode(event,'direct path read', round(time_waited_micro/1000) ,0)) prevdpr_tm,
sum(decode(event,'direct path read', total_waits - &prevdpr_ct_var,0)) dprct,
sum(decode(event,'direct path read', total_waits ,0)) prevdpr_ct,
sum(decode(event,'direct path write', round(time_waited_micro/1000) - &prevdpw_tm_var,0)) dpwtm,
sum(decode(event,'direct path write', round(time_waited_micro/1000) ,0)) prevdpw_tm,
sum(decode(event,'direct path write', total_waits - &prevdpw_ct_var,0)) dpwct,
sum(decode(event,'direct path write', total_waits ,0)) prevdpw_ct,
sum(decode(event,'direct path write temp', round(time_waited_micro/1000) - &prevdpwt_tm_var,0)) dpwttm,
sum(decode(event,'direct path write temp', round(time_waited_micro/1000) ,0)) prevdpwt_tm,
sum(decode(event,'direct path write temp', total_waits - &prevdpwt_ct_var,0)) dpwtct,
sum(decode(event,'direct path write temp', total_waits ,0)) prevdpwt_ct,
sum(decode(event,'direct path read temp', round(time_waited_micro/1000) - &prevdprt_tm_var,0)) dprttm,
sum(decode(event,'direct path read temp', round(time_waited_micro/1000) ,0)) prevdprt_tm,
sum(decode(event,'direct path read temp', total_waits - &prevdprt_ct_var,0)) dprtct,
sum(decode(event,'direct path read temp', total_waits ,0)) prevdprt_ct,
to_char(sysdate,'SSSSS')-&prevsec_var delta,
to_char(sysdate,'SSSSS') prevsec
from
v$system_event
where
event in ('db file sequential read',
'db file scattered read',
'direct path read temp',
'direct path write temp',
'direct path read',
'direct path write',
'log file parallel write')
) ;
Output looks like
SEQ_MS SEQ_CT LFPW_MS LFPW_CT SEQ_MS SCAT_CT DPR_MS DPR_CT DPRT_MS DPRT_CT -------- -------- -------- -------- -------- -------- -------- -------- -------- -------- 115.71 422.67 76.17 12.00 .00 .00 .00
The first execution of the query is I/O since database startup, so should most likely be ignored.
Subsequent executions are the I/O since the last execution
The columns are
- SEQ_MS: single block latency
- SEQ_CT: single block reads per second
- LFPW_MS: log file parallel write latency
- LFPW_CT: log file parallel write count per second
- SCAT_MS: multi-block latency
- SCAT_CT: multi-block reads per second
- DPR_MS: direct path read latency
- DPR_CT: direct path read count
- DPRT_MS: direct path read temp latency
- DPRT_CT: direct path read temp count
select
n.name event,
m.wait_count cnt,
10*m.time_waited ms,
nvl(round(10*m.time_waited/nullif(m.wait_count,0),3) ,0) avg_ms
from v$eventmetric m,
v$event_name n
where m.event_id=n.event_id
and (
wait_class_id= 1740759767 -- User I/O
or
wait_class_id= 4108307767 -- System I/O
)
and m.wait_count > 0 ;
.
Oracle L
Trackbacks
Comments
Hi Kyle,
nice script. Thanks a lot.
With minor modifications it also runs fine on MacosX:
HP-UX)
MKNOD=mknod
;;
Darwin) MKNOD=”” ## add for MacosX
;;
*)
if [ -z “${MKNOD}” ]
then
cmd=”mkfifo ${PIPE}”
else
cmd=”$MKNOD $PIPE p”
fi
That is about all. Could you include the changes?
Awesome thanks. Updated oramon.sh on github with your changes. Wonder if something like this works on Windows. I never got the script working on Windows.
– Kyle
Hi Kyle, nice script!
A few comments on direct path reads:
a) normal (not in memory) PQ uses direct path reads
b) starting from version 11, Oracle might choose a direct path read for a full segment scan based on criteria like size (segment shoud be > 5* small table threshold) and number of blocks in the cache (< 50%)
In Oracle 11.2.0.3, Oracle brings the number of IO's in flight kcblsinc() has decided (2 at start), and tries to reap that number 4 times after the io_submit phase. If one of these calls succeeds, there's no wait.
If that doesn't succeed, Oracle registers an 'direct path read' wait, and just tries to reap 1 IO, then redoes the procedure by going through the io_submit phase, kcblsinc to determine if there's a need for a change in # IO's in flight, then tries to reap them all for four times, etc.
So 'direct path read' means IO wait time from the perspective of the foreground process, and has nothing to do with IO latency time.
Oh, if synchronous IO is used for 'direct path read' waits, the reading sequence is: pread64(), begin timing, end timing (so the timing is bogus; I've verified this for 10.2.0.1, 11.2.0.1 and 11.2.0.3)