JL Computer Consultancy
Investigating Logical I/O
|
Apr 2007 |
Here’s a little procedure I
wrote a few years ago to investigate “logical I/O”. It’s not
something I use often, but it can offer some interesting insights into where your logical I/O is coming from, and where your CPU time is
being spent.
If you connect as sys,
you can find a couple of x$ objects which relate to logical
I/O: x$kcbwh
seems to be a list of the different functions that may be used to perform
different types of logical I/O (my copy of 10.2.0.3 has 806 of them, compared
to the 458 I used to see in 8.1.7.4), and x$kcbsw
captures some statistics about the way these functions have been used.
There really isn’t much
point in getting excited about these arrays, but a few years ago I wrote a
little snapshot package to capture statistics about how often each function was
used; then I started writing a little catalogue of which function represented
what activity. Here’s the code that runs on 9i and 10g (but needs a small
change for 8i). You need to connect as sys to install the
package, but the script creates a public synonym and grants
execute to public, so anyone can execute it.
rem
rem Script: snap_9_kcbsw.sql
rem Author: Jonathan
Lewis
rem Dated: March 2001
rem Purpose: Package to
get snapshot start and delta of cache usage
rem
rem Notes
rem 8i has column 'OTHER WAIT' which needs double quotes.
rem 9i has column 'OTHER_WAIT'
rem
rem 8.1.7.4 has 458 routines listed in x$kcbwh
rem 9.2.0.3 has 675
rem 9.2.0.6 has 677
rem 9.2.0.8 has 694
rem 10.1.0.1 has 773
rem 10.1.0.4 has 782
rem 10.2.0.1 has 802
rem 10.2.0.3 has 806
rem
rem Some actions seem to change their choice of call as
rem you go through different versions of Oracle - so
rem perhaps many of the calls are there for historical
rem reasons and 'just in case'.
rem
rem Has to be run by SYS to create the package
rem According to a note I found in Metalink
on RAC:
rem WHY2 is 'waits'
rem OTHER_WAITS is 'caused waits'
rem I take this to mean that both columns should sum
rem to the same value, but one shows when a function
rem had to wait, the other shows when a function was
rem responsible for making another function wait.
rem
rem Usage:
rem set serveroutput on size 1000000
format wrapped
rem set linesize 120
rem set trimspool on
rem execute snap_kcbsw.start_snap
rem -- do something
rem execute snap_kcbsw.end_snap
rem
rem Calls seem to follow a naming convention based on the first
rem two or three letters, for example:
rem ktu undo segments
rem kd data
layer
rem kdi data layer - indexes
rem kts Space management
rem kte Extent management
rem
rem A few guesses of details:
rem ktuwh01: ktugus Undo segment header to start
transaction Get Undo Segment ??
rem ktuwh03: ktugnb Undo segment header to Get Next undo
Block
rem ktuwh02: ktugus Get Undo Segment header for commit
rem ktuwh20: ktuabt Updating undo segment headers on
rollback (ABorT)
rem ktuwh23: ktubko
rem ktuwh24: ktubko
rem
rem kdowh00: kdoiur Applying
rollback records to data blocks ??
rem kduwh01: kdusru Single
row-piece update
rem kddwh01: kdddel Delete
row
rem
create
or replace package snap_kcbsw as
procedure start_snap;
procedure end_snap(i_limit in number default 0);
end;
/
create
or replace package body snap_kcbsw as
cursor c1 is
select
indx,
why0,
why1,
why2,
-- "OTHER WAIT" other_wait -- v8
other_wait -- v9
from
x$kcbsw
;
type w_type1 is table of c1%rowtype index
by binary_integer;
w_list1 w_type1;
empty_list w_type1;
w_sum1 c1%rowtype;
w_count number(6);
cursor c2(i_task
number) is
select
kcbwhdes
from x$kcbwh
where
indx
= i_task
;
r2 c2%rowtype;
m_start_time date;
m_start_flag char(1);
m_end_time date;
procedure
start_snap is
begin
m_start_time := sysdate;
m_start_flag :=
'U';
w_list1 := empty_list;
for r in c1 loop
w_list1(r.indx).why0
:= r.why0;
w_list1(r.indx).why1
:= r.why1;
w_list1(r.indx).why2
:= r.why2;
w_list1(r.indx).other_wait := r.other_wait;
end loop;
end
start_snap;
procedure
end_snap(i_limit in number
default 0) is
begin
m_end_time := sysdate;
dbms_output.put_line('---------------------------------');
dbms_output.put_line('Buffer
Cache - ' ||
to_char(m_end_time,'dd-Mon hh24:mi:ss')
);
if m_start_flag
= 'U' then
dbms_output.put_line('Interval:- ' ||
trunc(86400
* (m_end_time - m_start_time))
||
' seconds'
);
else
dbms_output.put_line('Since
Startup:- ' ||
to_char(m_start_time,'dd-Mon hh24:mi:ss')
);
end if;
if (i_limit !=
0) then
dbms_output.put_line('Lower
limit:- ' || i_limit);
end if;
dbms_output.put_line('---------------------------------');
dbms_output.put_line(
lpad('Why0',14)
||
lpad('Why1',14)
||
lpad('Why2',14)
||
lpad('Other
Wait',14)
);
dbms_output.put_line(
lpad('----',14)
||
lpad('----',14)
||
lpad('----',14)
||
lpad('----------',14)
);
w_sum1.why0 := 0;
w_sum1.why1 := 0;
w_sum1.why2 := 0;
w_sum1.other_wait := 0;
w_count := 0;
for r in c1 loop
if (not w_list1.exists(r.indx)) then
w_list1(r.indx).why0
:= 0;
w_list1(r.indx).why1
:= 0;
w_list1(r.indx).why2
:= 0;
w_list1(r.indx).other_wait := 0;
end if;
if (
r.why0 > w_list1(r.indx).why0
+ i_limit
or r.why1 > w_list1(r.indx).why1 + i_limit
or r.why2 > w_list1(r.indx).why2 + i_limit
or r.other_wait
> w_list1(r.indx).other_wait
+ i_limit
) then
dbms_output.put(to_char(
r.why0 - w_list1(r.indx).why0,
'9,999,999,990')
);
dbms_output.put(to_char(
r.why1 - w_list1(r.indx).why1,
'9,999,999,990')
);
dbms_output.put(to_char(
r.why2 - w_list1(r.indx).why2,
'9,999,999,990')
);
dbms_output.put(to_char(
r.other_wait
- w_list1(r.indx).other_wait,
'9,999,999,990')
);
open c2 (r.indx);
fetch c2 into r2;
close c2;
dbms_output.put('
'|| r2.kcbwhdes);
dbms_output.new_line;
w_sum1.why0 := w_sum1.why0 +
r.why0 - w_list1(r.indx).why0;
w_sum1.why1 := w_sum1.why1 +
r.why1 - w_list1(r.indx).why1;
w_sum1.why2 := w_sum1.why2 +
r.why2 - w_list1(r.indx).why2;
w_sum1.other_wait := w_sum1.other_wait
+ r.other_wait - w_list1(r.indx).other_wait;
w_count
:= w_count + 1;
end if;
end loop;
dbms_output.put_line(
lpad('----',14)
||
lpad('----',14)
||
lpad('----',14)
||
lpad('----------',14)
);
dbms_output.put(to_char(w_sum1.why0,'9,999,999,990'));
dbms_output.put(to_char(w_sum1.why1,'9,999,999,990'));
dbms_output.put(to_char(w_sum1.why2,'9,999,999,990'));
dbms_output.put(to_char(w_sum1.other_wait,'9,999,999,990'));
dbms_output.put('
Total: ' || w_count || ' rows');
dbms_output.new_line;
end
end_snap;
begin
select
startup_time,
'S'
into
m_start_time,
m_start_flag
from
v$instance
;
end
snap_kcbsw;
/
drop
public synonym snap_kcbsw;
create
public synonym snap_kcbsw for snap_kcbsw;
grant
execute on snap_kcbsw to public;
You may find the package useful
from time to time to help you figure out what’s going on with a
particular statement or batch job. If you want to make use of it though,
it’s a good example of a tool where it helps if you know the answers
before asking the questions. In other words, don’t wait until you have a
problem, do some tests up front so that you know what the results are telling
you when you use the tool in anger. For example:
set
serveroutput on
size 1000000 format wrapped
set
trimspool on
set
linesize 120
set
termout off
execute
snap_kcbsw.start_snap
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
select
/*+ full(t) */ count(*) from tab$;
spool
temp1
execute
snap_kcbsw.end_snap
spool
off
---------------------------------
Buffer
Cache - 05-Apr 08:49:41
Interval:- 0 seconds
---------------------------------
Why0 Why1 Why2 Other Wait
---- ---- ---- ----------
10 0 0 0
ktewh25: kteinicnt
10 0 0 0
ktewh26: kteinpscan
30 0 0 0
ktewh27: kteinmap
8,770 0 0 0
kdswh01: kdstgr
11 0 0 0
kdswh02: kdsgrp
11 0 0 0
kdiwh06: kdifbk
11 0 0 0
kdiwh07: kdifbk
---- ---- ---- ----------
8,853 0 0 0 Total:
7 rows
PL/SQL
procedure successfully completed.
After 10 full tablescans
there are some interesting results. You would be fairly safe in betting that
the 10/10/30 counts related to the 10 tablescans
(they are the two checks of the segment header block for the extent map (kteinicnt perhaps) and high water mark (kteinpscan perhaps), followed by a couple of
extra checks of the extent map (kteinmap)
as we work through the multiple extents in the segment. The 8,770 calls to kdstgr are getting rows from blocks read by tablescan (Tablescan
Get Row, perhaps).
The 11 calls to the other three
functions are a little puzzling – but a little experimentation with
enabling serveroutput highlights the fact that they
seem to be associated with calls to dbms_output.get_lines.
Normally I would assume that kdifbk was
related to walking through indexes (kdi)
and kdsgrp is about visiting a table to
Get a Row Piece – but
that’s not exactly what’s happening here.
Bear in mind that tab$
is part of the cluster c_obj#,
so these results might not be identical to the results you get from a tablescan of a simple table, of course. So don’t take
my word for the interpretations of any these calls. If you feel the need to
investigate, you will be able to waste endless amounts of time trying to
discover and catalogue the reasons for all 806 calls that 10.2.0.3 offers.
Apr 2009 Update: Unfortunately the two x$
structures are not updated in the same way in 11g. This may relate to the new block access
methods recorded as “db block gets from cache (fastpath)”
and “consistent gets from cache (fastpath)”,
but may simply be code changes designed to minimise
any “redundant” work – as some point I will be checking to
see if there is an event or debug flag that can be set to re-enable the stats.
