There’s another interesting thread going on in Oracle-L, about understanding logical IOs and drilling down into their reasons. Of course sometimes (or rather usually) the excessive logical IOs come from a bad execution plan (when a nested loop loops over lots of datablocks again and again or a wrong index is used for driving a query etc), but sometimes the excessive LIOs are caused by some internal issues, like space management etc.
A convenient tool I use for reporting logical IO reasons is (again) my Snapper! It has an option “b” for reporting Buffer get reasons or as I use below – option “a” shows All information Snapper can show.
There are couple of gotchas though which make this approach imperfect:
- The X$ tables Snapper uses for LIO reason reporting contain instance-wide counters, not specific to a single testing session. Thus you either need to be the single user in your database when experimenting and even then the background activity may increment some counters while you are testing too. I have sometimes suspended all other processes (kill -STOP and kill -CONT to resume) or used Flash Freeze (oradebug ffbegin and ffresumeinst) to hang the whole instance that there would be no other activity going on.
- These buffer get reason counters are not maintained properly in Oracle 11g, probably due an optimization effort and some changes for faster pinning of buffer cache buffers (there’s a parameter called _fastpin_enable which is set to 1 in 11g and it enables so called fastpath buffer gets. If you see v$sesstat statistics such “consistent gets from cache (fastpath) or “db block gets from cache (fastpath)” being inremented, then fastpath buffer gets/pins are used. Note that I do have a script which works also on 11g but I’ll write about that one some time in the future :)
Anyway, if you are testing in an environment exclusively used by you, on Oracle 10.2 or lower, then you can run snapper with the gather=a option to report a bunch instance-level statistics in addition to the standard session-level stats:
- BUFG – Buffer get reasons (both consistent and current mode gets)
- LATG – Latch gets (both willing to wait and immediate gets)
- ENQG – Enqueue gets
Here’s an example, prepare for long output:
SQL> @snapper gather=a 5 1 128 -- Session Snapper v2.02 by Tanel Poder ( ) -- ---------------------------------------------------------------------------------------------------------------------- SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH ---------------------------------------------------------------------------------------------------------------------- -1, , BUFG, kcbwh2: kcbchg1 , 1, .2, -1, , BUFG, kttewh00: ktte_get_file_info , 20, 4, -1, , BUFG, ktswh28: ktsgsp , 7, 1.4, -1, , BUFG, ktswh39: ktsrsp , 1, .2, -1, , BUFG, ktswh72: ktsbget , 7, 1.4, -1, , BUFG, ktswh76: ktsxadd , 2, .4, -1, , BUFG, ktswh77: ktsxadd , 1, .2, -1, , BUFG, ktswh201: ktsxbmdelext , 1, .2, -1, , BUFG, ktspfwh10: ktspscan_bmb , 9, 1.8, -1, , BUFG, ktspswh12: ktspffc , 9, 1.8, -1, , BUFG, ktsphwh39: ktspisc , 9, 1.8, -1, , BUFG, ktspbwh1: ktspfsrch , 9, 1.8, -1, , BUFG, ktuwh01: ktugus , 26, 5.2, -1, , BUFG, ktuwh02: ktugus , 20, 4, -1, , BUFG, ktuwh03: ktugnb , 7, 1.4, -1, , BUFG, ktuwh05: ktugct , 5, 1, -1, , BUFG, ktuwh09: ktugfb , 6, 1.2, -1, , BUFG, ktuwh27: kturbk , 7, 1.4, -1, , BUFG, ktewh25: kteinicnt , 30, 6, -1, , BUFG, ktewh26: kteinpscan , 23, 4.6, -1, , BUFG, ktewh27: kteinmap , 14, 2.8, -1, , BUFG, ktewh43: ktelbhw , 2, .4, -1, , BUFG, ktewh51: ktelwbl , 3, .6, -1, , BUFG, ktewh78: kteopdelete , 20, 4, -1, , BUFG, ktewh80: kteopdelete , 20, 4, -1, , BUFG, ktewh88: kteopshrink , 1, .2, -1, , BUFG, ktewh89: kteopshrink , 1, .2, -1, , BUFG, ktfbwh06: ktfbffpre , 21, 4.2, -1, , BUFG, ktfbwh0d: ktfbsearch , 1, .2, -1, , BUFG, ktfbwh36: ktfbbsearch , 1, .2, -1, , BUFG, ktfbwh37: ktfbbset , 22, 4.4, -1, , BUFG, kdswh01: kdstgr , 284, 56.8, -1, , BUFG, kdswh02: kdsgrp , 3237, 647.4, -1, , BUFG, kdswh05: kdsgrp , 1201, 240.2, -1, , BUFG, kdswh06: kdscgr , 42, 8.4, -1, , BUFG, kdtwh01: kdtgrs , 4, .8, -1, , BUFG, kduwh01: kdusru , 13, 2.6, -1, , BUFG, kduwh02: kdusru , 1, .2, -1, , BUFG, kdiwh06: kdifbk , 415, 83, -1, , BUFG, kdiwh07: kdifbk , 924, 184.8, -1, , BUFG, kdiwh08: kdiixs , 82, 16.4, -1, , BUFG, kdiwh09: kdiixs , 3438, 687.6, -1, , BUFG, kdiwh15: kdifxs , 48, 9.6, -1, , BUFG, kdiwh17: kdifind , 187, 37.4, -1, , BUFG, kdiwh22: kdifind , 208, 41.6, -1, , BUFG, kdiwh23: kdiins , 2, .4, -1, , BUFG, kdiwh41: kdifbk , 5, 1, -1, , BUFG, kdiwh42: kdiixs , 3397, 679.4, -1, , BUFG, kdiwh126: kdisparent , 2, .4, -1, , BUFG, kdiwh127: kdislink , 1, .2, -1, , BUFG, kdiwh130: kdisle , 2, .4, -1, , BUFG, kdiwh161: kdifind , 1, .2, -1, , BUFG, kdiwh169: skipscan , 1, .2, -1, , BUFG, kdcwh06: kdccss , 22, 4.4, -1, , BUFG, kdcwh07: kdcifk , 2, .4, -1, , BUFG, kddwh01: kdddel , 31, 6.2, -1, , BUFG, kddwh03: kddlkr , 5, 1, -1, , ENQG, CF - Controlfile Transaction , 2, .4, -1, , ENQG, CI - Cross-Instance Call Invocation , 2, .4, -1, , ENQG, CU - Cursor , 4, .8, -1, , ENQG, HW - Segment High Water Mark , 1, .2, -1, , ENQG, IS - Instance State , 1, .2, -1, , ENQG, JD - Job Queue Date , 1, .2, -1, , ENQG, JS - Job Scheduler , 68, 13.6, -1, , ENQG, MD - Materialized View Log DDL , 1, .2, -1, , ENQG, RO - Multiple Object Reuse , 9, 1.8, -1, , ENQG, TM - DML , 73, 14.6, -1, , ENQG, TS - Temporary Segment , 1, .2, -1, , ENQG, TT - Tablespace , 2, .4, -1, , ENQG, TX - Transaction , 15, 3, -1, , LATG, post/wait queue , 20, 4, -1, , LATG, session allocation , 319, 63.8, -1, , LATG, session idle bit , 744, 148.8, -1, , LATG, client/application info , 136, 27.2, -1, , LATG, object stats modification , 3, .6, -1, , LATG, messages , 114, 22.8, -1, , LATG, enqueues , 243, 48.6, -1, , LATG, enqueue hash chains , 361, 72.2, -1, , LATG, resmgr group change latch , 40, 8, -1, , LATG, channel handle pool latch , 2, .4, -1, , LATG, channel operations parent latch , 73, 14.6, -1, , LATG, message pool operations parent latch , 5, 1, -1, , LATG, active service list , 17, 3.4, -1, , LATG, OS process allocation , 2, .4, -1, , LATG, KMG MMAN ready and startup request latch, 2, .4, -1, , LATG, Memory Management Latch , 2, .4, -1, , LATG, mostly latch-free SCN , 14, 2.8, -1, , LATG, lgwr LWN SCN , 14, 2.8, -1, , LATG, Consistent RBA , 14, 2.8, -1, , LATG, cache buffers lru chain , 1534, 306.8, -1, , LATG, active checkpoint queue latch , 17, 3.4, -1, , LATG, checkpoint queue latch , 266, 53.2, -1, , LATG, cache buffers chains , 28630, 5.73k, -1, , LATG, cache buffer handles , 1, .2, -1, , LATG, multiblock read objects , 24, 4.8, -1, , LATG, cache table scan latch , 16, 3.2, -1, , LATG, simulator lru latch , 613, 122.6, -1, , LATG, simulator hash latch , 617, 123.4, -1, , LATG, object queue header operation , 373, 74.6, -1, , LATG, object queue header heap , 50, 10, -1, , LATG, redo writing , 56, 11.2, -1, , LATG, redo copy , 360, 72, -1, , LATG, redo allocation , 419, 83.8, -1, , LATG, loader state object freelist , 1, .2, -1, , LATG, begin backup scn array , 5, 1, -1, , LATG, dml lock allocation , 146, 29.2, -1, , LATG, commit callback allocation , 4, .8, -1, , LATG, sort extent pool , 1, .2, -1, , LATG, file cache latch , 22, 4.4, -1, , LATG, undo global data , 85, 17, -1, , LATG, ktm global data , 1, .2, -1, , LATG, In memory undo latch , 91, 18.2, -1, , LATG, KTF sga latch , 1225, 245, -1, , LATG, sequence cache , 6, 1.2, -1, , LATG, row cache objects , 9066, 1.81k, -1, , LATG, kks stats , 2, .4, -1, , LATG, shared pool , 2806, 561.2, -1, , LATG, library cache , 17455, 3.49k, -1, , LATG, library cache lock , 1351, 270.2, -1, , LATG, library cache pin , 1733, 346.6, -1, , LATG, library cache pin allocation , 7, 1.4, -1, , LATG, library cache lock allocation , 5, 1, -1, , LATG, library cache load lock , 2, .4, -1, , LATG, shared pool simulator , 725, 145, -1, , LATG, session timer , 2, .4, -1, , LATG, job_queue_processes parameter latch , 1, .2, -1, , LATG, hash table modification latch , 2, .4, -1, , LATG, hash table column usage latch , 4, .8, -1, , LATG, SQL memory manager latch , 2, .4, -1, , LATG, SQL memory manager workarea list latch , 180, 36, -1, , LATG, compile environment latch , 66, 13.2, -1, , LATG, ASM db client latch , 10, 2, -1, , LATG, JS queue state obj latch , 66, 13.2, -1, , LATG, PL/SQL warning settings , 14, 2.8, 128, SYS , STAT, opened cursors cumulative , 565, 113, 128, SYS , STAT, opened cursors current , -4, -.8, 128, SYS , STAT, user commits , 1, .2, 128, SYS , STAT, user calls , 2, .4, 128, SYS , STAT, recursive calls , 2991, 598.2, 128, SYS , STAT, recursive cpu usage , 18, 3.6, 128, SYS , STAT, session logical reads , 17075, 3.42k, 128, SYS , STAT, CPU used when call started , 269, 53.8, 128, SYS , STAT, CPU used by this session , 29, 5.8, 128, SYS , STAT, DB time , 627, 125.4, 128, SYS , STAT, user I/O wait time , 12, 2.4, 128, SYS , STAT, session uga memory , -1315136, -263.03k, 128, SYS , STAT, messages sent , 6, 1.2, 128, SYS , STAT, session pga memory , -7471104, -1.49M, 128, SYS , STAT, enqueue waits , 1, .2, 128, SYS , STAT, enqueue requests , 62, 12.4, 128, SYS , STAT, enqueue conversions , 3, .6, 128, SYS , STAT, enqueue releases , 66, 13.2, 128, SYS , STAT, physical read total IO requests , 44, 8.8, 128, SYS , STAT, physical read total multi block requests, 8, 1.6, 128, SYS , STAT, physical read total bytes , 942080, 188.42k, 128, SYS , STAT, physical write total IO requests , 4, .8, 128, SYS , STAT, physical write total multi block request, 4, .8, 128, SYS , STAT, physical write total bytes , 950272, 190.05k, 128, SYS , STAT, db block gets , 644, 128.8, 128, SYS , STAT, db block gets from cache , 540, 108, 128, SYS , STAT, db block gets direct , 104, 20.8, 128, SYS , STAT, consistent gets , 16409, 3.28k, 128, SYS , STAT, consistent gets from cache , 16409, 3.28k, 128, SYS , STAT, consistent gets - examination , 6316, 1.26k, 128, SYS , STAT, physical reads , 115, 23, 128, SYS , STAT, physical reads cache , 115, 23, 128, SYS , STAT, physical read IO requests , 44, 8.8, 128, SYS , STAT, physical read bytes , 942080, 188.42k, 128, SYS , STAT, db block changes , 618, 123.6, 128, SYS , STAT, consistent changes , 7, 1.4, 128, SYS , STAT, physical writes , 116, 23.2, 128, SYS , STAT, physical writes direct , 116, 23.2, 128, SYS , STAT, physical write IO requests , 4, .8, 128, SYS , STAT, physical write bytes , 950272, 190.05k, 128, SYS , STAT, physical writes non checkpoint , 116, 23.2, 128, SYS , STAT, change write time , 3, .6, 128, SYS , STAT, redo synch writes , 3, .6, 128, SYS , STAT, redo synch time , 3, .6, 128, SYS , STAT, free buffer requested , 132, 26.4, 128, SYS , STAT, dirty buffers inspected , 2, .4, 128, SYS , STAT, hot buffers moved to head of LRU , 420, 84, 128, SYS , STAT, free buffer inspected , 187, 37.4, 128, SYS , STAT, commit cleanout failures: callback failu, 1, .2, 128, SYS , STAT, commit cleanouts , 48, 9.6, 128, SYS , STAT, commit cleanouts successfully completed , 47, 9.4, 128, SYS , STAT, CR blocks created , 7, 1.4, 128, SYS , STAT, switch current to new buffer , 3, .6, 128, SYS , STAT, physical reads cache prefetch , 71, 14.2, 128, SYS , STAT, shared hash latch upgrades - no wait , 29, 5.8, 128, SYS , STAT, calls to kcmgcs , 21, 4.2, 128, SYS , STAT, calls to kcmgas , 29, 5.8, 128, SYS , STAT, calls to get snapshot scn: kcmgss , 4114, 822.8, 128, SYS , STAT, redo entries , 348, 69.6, 128, SYS , STAT, redo size , 105284, 21.06k, 128, SYS , STAT, redo ordering marks , 7, 1.4, 128, SYS , STAT, redo subscn max counts , 13, 2.6, 128, SYS , STAT, undo change vector size , 40376, 8.08k, 128, SYS , STAT, data blocks consistent reads - undo reco, 7, 1.4, 128, SYS , STAT, no work - consistent read gets , 9936, 1.99k, 128, SYS , STAT, cleanouts only - consistent read gets , 1, .2, 128, SYS , STAT, rollbacks only - consistent read gets , 7, 1.4, 128, SYS , STAT, immediate (CURRENT) block cleanout appli, 22, 4.4, 128, SYS , STAT, immediate (CR) block cleanout applicatio, 1, .2, 128, SYS , STAT, deferred (CURRENT) block cleanout applic, 20, 4, 128, SYS , STAT, commit txn count during cleanout , 3, .6, 128, SYS , STAT, active txn count during cleanout , 4, .8, 128, SYS , STAT, cleanout - number of ktugct calls , 5, 1, 128, SYS , STAT, table scans (short tables) , 22, 4.4, 128, SYS , STAT, table scan rows gotten , 16208, 3.24k, 128, SYS , STAT, table scan blocks gotten , 344, 68.8, 128, SYS , STAT, table fetch by rowid , 5476, 1.1k, 128, SYS , STAT, table fetch continued row , 5, 1, 128, SYS , STAT, cluster key scans , 32, 6.4, 128, SYS , STAT, cluster key scan block gets , 45, 9, 128, SYS , STAT, rows fetched via callback , 4083, 816.6, 128, SYS , STAT, index crx upgrade (positioned) , 23, 4.6, 128, SYS , STAT, leaf node splits , 2, .4, 128, SYS , STAT, leaf node 90-10 splits , 1, .2, 128, SYS , STAT, index fetch by key , 1457, 291.4, 128, SYS , STAT, index scans kdiixs1 , 4028, 805.6, 128, SYS , STAT, session cursor cache hits , 430, 86, 128, SYS , STAT, cursor authentications , 45, 9, 128, SYS , STAT, buffer is pinned count , 9217, 1.84k, 128, SYS , STAT, buffer is not pinned count , 14010, 2.8k, 128, SYS , STAT, workarea memory allocated , -1776, -355.2, 128, SYS , STAT, workarea executions - optimal , 2, .4, 128, SYS , STAT, parse time cpu , 1, .2, 128, SYS , STAT, parse count (total) , 432, 86.4, 128, SYS , STAT, parse count (hard) , 5, 1, 128, SYS , STAT, execute count , 824, 164.8, 128, SYS , STAT, bytes sent via SQL*Net to client , 202, 40.4, 128, SYS , STAT, bytes received via SQL*Net from client , 139, 27.8, 128, SYS , STAT, SQL*Net roundtrips to/from client , 2, .4, 128, SYS , STAT, sorts (memory) , 33, 6.6, 128, SYS , TIME, hard parse (bind mismatch) elapsed time , 1951, 390.2us, .0%, | | 128, SYS , TIME, hard parse elapsed time , 2787, 557.4us, .1%, | | 128, SYS , TIME, repeated bind elapsed time , 394, 78.8us, .0%, | | 128, SYS , TIME, parse time elapsed , 8932, 1.79ms, .2%, | | 128, SYS , TIME, PL/SQL execution elapsed time , 57864, 11.57ms, 1.2%, |@ | 128, SYS , TIME, DB CPU , 600031, 120.01ms, 12.0%, |@@ | 128, SYS , TIME, sql execute elapsed time , 1132905, 226.58ms, 22.7%, |@@@ | 128, SYS , TIME, hard parse (sharing criteria) elapsed ti, 1950, 390us, .0%, | | 128, SYS , TIME, DB time , 1169539, 233.91ms, 23.4%, |@@@ | 128, SYS , WAIT, enq: RO - fast object reuse , 924, 184.8us, .0%, | | 128, SYS , WAIT, log file sync , 30373, 6.07ms, .6%, |@ | 128, SYS , WAIT, db file sequential read , 84665, 16.93ms, 1.7%, |@ | 128, SYS , WAIT, db file scattered read , 28306, 5.66ms, .6%, |@ | 128, SYS , WAIT, direct path write , 538, 107.6us, .0%, | | 128, SYS , WAIT, SQL*Net message to client , 6, 1.2us, .0%, | | 128, SYS , WAIT, SQL*Net message from client , 4005179, 801.04ms, 80.1%, |@@@@@@@@ | 128, SYS , WAIT, events in waitclass Other , 1358, 271.6us, .0%, | | -- End of snap 1, end=2009-11-20 00:51:43, seconds=5 PL/SQL procedure successfully completed.
So, the function names (kernel code locations) reported by Snapper do give away how many LIOs were done for accessing user data (kd* functions – which is the Kernel Data layer), space management (ktsI* – which is Kernel Transaction Space management module), kte* – which is the Kernel Transaction Extent management layer etc.
Seeing the function names has allowed me to diagnose some nasty ASSM bugs causing huge amounts of logical IOs in past, like ktspscan_bmb which is an ASSM bitmap block space search function. More details follow some time in the future ;-)
