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         Reading rollback blocks to apply undo records

rem         ktuwh24: ktubko         Reading rollback blocks to apply undo records

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.


Back to Index of Topics