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.

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 onsize 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

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

Why0Why1Why2Other Wait

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

10000
ktewh25: kteinicnt

10000
ktewh26: kteinpscan

30000
ktewh27: kteinmap

8,770000
kdswh01: kdstgr

11000
kdswh02: kdsgrp

11000
kdiwh06: kdifbk

11000
kdiwh07: kdifbk

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

8,853000 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 (TablescanGet 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.