Following the discussions of Blog: Oracle Physical Read Access Path and Cost, and Oracle Logical Read: Consistent Gets Access Path and Cost, now is the time to look into second part of Logical Reads: Current Mode Gets.
We will use SQL Trace Event 10046 to display the statistics, and dtrace script: dtracelio.d published in Blog: Dynamic tracing of Oracle logical I/O to show block read details and sequence. Ideally Oracle could provide one Event to trace Current Mode Get, which is similar to Event 10200 ("consistent read buffer status") for Consistent Mode Get.
Blog: Dynamic tracing of Oracle logical I/O: part 2. Dtrace LIO v2 is released includes a detail description of Oracle internal functions:
Consistent gets:
kcbgtcr – Kernel Cache Buffer Get Consistent Read. This is general entry point for consistent read.
kcbldrget – Kernel Cache Buffer Load Direct-Read Get. The function performing direct-path read.
Interesting detail: 10.2 the function kcbldrget is called just after kcbgtcr,
in 11.2 by (from) kcbgtcr.
Current gets (db block gets):
kcbgcur – Kernel Cache Buffer Get Current Read
kcbget – Kernel Cache Buffer Get Buffer. This is analogue of kcbgcur function,
as I observed this function is called for index branch and leaf blocks
kcbnew – Kernel Cache Buffer New Buffer
kcblnb (kcblnb_dscn in 11.2) – Kernel Cache Buffer Load New Buffer.
The function performing direct-path load.
Decoding of block coordinates is not supported for this function
in the current version of DTraceLIO.
The parameters such as object_id, data_object_id will be shown as 0 (zero)
Note: All tests are done in Oracle 12.1.0.2 on Solaris with 6 physical processors.
1. Test Setup
drop tablespace ksun_tts including contents and datafiles;
drop tablespace ksun_its1 including contents and datafiles;
drop tablespace ksun_its2 including contents and datafiles;
create tablespace ksun_tts datafile '/oratestdb/oradata/testdb/ksun_tts.dbf' size 200m online;
create tablespace ksun_its1 datafile '/oratestdb/oradata/testdb/ksun_its1.dbf' size 200m online;
create tablespace ksun_its2 datafile '/oratestdb/oradata/testdb/ksun_its2.dbf' size 200m online;
drop table ksun_tab;
create table ksun_tab tablespace ksun_tts
as select trunc(level/1000) type_id, mod(level, 100) id1, trunc(mod(level, 1000)/100) id2, -1234 dummy
from dual connect by level <= 4099;
create unique index ksun_tab#u#1 on ksun_tab (type_id, id1, id2, dummy) tablespace ksun_its1;
create unique index ksun_tab#u#2 on ksun_tab (type_id, id2, id1) tablespace ksun_its2;
exec dbms_stats.gather_table_stats(null, 'KSUN_TAB', cascade=>true);
select name, ts# from v$tablespace where name like '%KSUN%' or ts# in (2, 1999);
--UNDO 2
--U1 1999
--KSUN_TTS 2231
--KSUN_ITS1 2232
--KSUN_ITS2 2233
select rfile#, name, v.* from v$datafile v where name like '%ksun%';
--917 /oratestdb/oradata/testdb/ksun_tts.dbf
--931 /oratestdb/oradata/testdb/ksun_its1.dbf
--101 /oratestdb/oradata/testdb/ksun_its2.dbf
select object_name, object_id from dba_objects where object_name like 'KSUN_TAB%' or object_id in (1577349);
--RMTAB$ 1577349
--KSUN_TAB 2286270
--KSUN_TAB#U#1 2286271
--KSUN_TAB#U#2 2286272
select segment_name, blocks, v.* from dba_segments v where segment_name like 'KSUN_TAB%';
--KSUN_TAB 16
--KSUN_TAB#U#1 24
--KSUN_TAB#U#2 16
select 'KSUN_TAB', count(distinct dbms_rowid.rowid_relative_fno (rowid)||'-'||dbms_rowid.rowid_block_number (rowid)) used_blocks from KSUN_TAB;
--KSUN_TAB 11
select 'KSUN_TAB#U#1', count(distinct dbms_rowid.rowid_block_number(sys_op_lbid (2286271, 'L', t.rowid))) used_blocks from KSUN_TAB t;
--KSUN_TAB#U#1 14
select 'KSUN_TAB#U#2', count(distinct dbms_rowid.rowid_block_number(sys_op_lbid (2286272, 'L', t.rowid))) used_blocks from KSUN_TAB t;
-- KSUN_TAB#U#2 11
-- list different functions used to perform different types of logical I/O
select indx, kcbwhdes from x$kcbwh where indx in (799, 1060, 1062, 1066, 1153, 1199);
--799 ktewh26: kteinpscan
--1060 kdiwh15: kdifxs
--1062 kdiwh17: kdifind
--1066 kdiwh22: kdifind
--1153 kdiwh169: skipscan
--1199 kddwh01: kdddel
2. Tests
We will perform 3 Tests, the first one uses 2 different indexes, the second uses only one index, and the last one uses the same index twice.
2.1 Test_1
--******************************* SQL Trace *******************************--
delete /*+ test_1 use_concat index_ss(@DEL$1 T@DEL$1 ksun_tab#u#2)
index_ss(@DEL$1_2 T@DEL$1_2 ksun_tab#u#1) */ ksun_tab t where 99 in (id2, id1)
-- rollback; -- make test repeatable
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 12 211 41
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 12 211 41
Rows (avg) Row Source Operation
---------- ---------------------------------------------------
0 DELETE KSUN_TAB (cr=12 pr=0 pw=0 time=1569 us)
41 CONCATENATION (cr=12 pr=0 pw=0 time=356 us)
0 INDEX SKIP SCAN KSUN_TAB#U#2 (cr=6 pr=0 pw=0 time=82 us cost=3 size=14 card=1)(object id 2286272)
41 INDEX SKIP SCAN KSUN_TAB#U#1 (cr=6 pr=0 pw=0 time=228 us cost=8 size=574 card=41)(object id 2286271)
--******************************* dtrace *******************************--
SQL> delete /*+ test_1 use_concat index_ss(@DEL$1 T@DEL$1 ksun_tab#u#2)
index_ss(@DEL$1_2 T@DEL$1_2 ksun_tab#u#1) */ ksun_tab t where 99 in (id2, id1);
41 rows deleted.
-- rollback; -- make test repeatable
$ > dtracelio.d 23585
Dynamic tracing of Oracle logical I/O v2.1 by Alexander Anokhin ( http://alexanderanokhin.wordpress.com )
108075: 108075 kcbgtcr(0xFFFFFD7FFAE17D58,0,1153,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1153 exam: 0
124990: 4336 kcbgtcr(0xFFFFFD7FFAE17D58,0,1153,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1153 exam: 0
--Repeated lines removed--
424351: 4783 kcbgtcr(0xFFFFFD7FFA0EF830,0,1153,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1153 exam: 0
428303: 2234 kcbgtcr(0xFFFFFD7FFA0EF830,0,1153,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1153 exam: 0
--Repeated lines removed--
511748: 21448 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
524191: 3355 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
658937: 5220 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
663567: 2134 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
695708: 18720 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
707668: 2415 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
745953: 5864 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
750657: 2105 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
759713: 4981 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
764240: 1989 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
784175: 3267 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
789056: 2245 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
806713: 2546 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
811388: 2215 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
818717: 3387 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
823620: 2283 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
833734: 2543 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
838017: 1949 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
843481: 2253 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
847875: 1988 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
--Repeated lines removed (40 Repeats)--
Pick one line:
524191: 3355 kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
You can see here:
timestamp - 524191,
delta time - 3355 (from last timestamp to current timestamp),
kcbgcur(0xFFFFFD7FFAED0EB0,2,1199,0) – it is function call with 3 arguments,
tsn: 2231 – a tablespace number, ts# from v$tablespace for KSUN_TTS,
rdba: 0xe5400083 – a relative dba (data block address)
(917/131) – file 917 (ksun_tts.dbf) block 131
obj: 2286270 – dictionary object number, object_id from dba_objects for KSUN_TAB,
dobj: 2286270 – data object number, data_object_id from dba_objects for KSUN_TAB,
where: 1199 – location from function (kcbgcur in this case) was executed. This is INDX from x$kcbwf for "kddwh01: kdddel".
===================== Logical I/O Summary (grouped by object/function) ==============
function stat object_id data_object_id mode_held where bufs calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
kcbgcur cu 0 -1 2 53 2 2
kcbgcur cu 0 -1 2 88 2 2
kcbgcur cu 0 -1 2 86 4 4
kcbnew cu 0 -1 47 4 4
kcbgtcr cr 2286271 2286271 1153 12 12
kcbgtcr cr 2286272 2286272 1153 12 12
kcbgcur cu 2286270 2286270 2 1199 82 82
kcbgcur cu 2286271 2286271 1 1062 82 82
kcbgcur cu 2286272 2286272 1 1062 82 82
kcbget cu 2286271 2286271 2 1066 82 82
kcbget cu 2286272 2286272 2 1066 82 82
=====================================================================================
================================= Logical I/O Summary (grouped by object) ==========================================
object_id data_object_id lio cr cr (e) cr (d) cu cu (d) ispnd (Y) ispnd (N) pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
0 -1 12 0 0 0 12 0 0 0 4
2286270 2286270 82 0 0 0 82 0 0 0 82
2286271 2286271 176 12 0 0 164 0 0 0 12
2286272 2286272 176 12 0 0 164 0 0 0 12
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
total 446 24 0 0 422 0 0 0 110
====================================================================================================================
Legend
lio : logical gets (cr + cu)
cr : consistent gets
cr (e) : consistent gets - examination
cr (d) : consistent gets direct
cu : db block gets
cu (d) : db block gets direct
ispnd (Y): buffer is pinned count
ispnd (N): buffer is not pinned count
pin rls : pin releases
2.2 Test_2
--******************************* SQL Trace *******************************--
delete /*+ test_2 index(t ksun_tab#U#2) */ ksun_tab t where 99 in (id2, id1)
-- rollback; -- make test repeatable
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 12 75 41
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 12 75 41
Rows (avg) Row Source Operation
---------- ---------------------------------------------------
0 DELETE KSUN_TAB (cr=12 pr=0 pw=0 time=1025 us)
41 INDEX FULL SCAN KSUN_TAB#U#2 (cr=12 pr=0 pw=0 time=405 us cost=6 size=574 card=41)(object id 2286272)
--******************************* dtrace *******************************--
SQL > delete /*+ test_2 index(t ksun_tab#U#2) */ ksun_tab t where 99 in (id2, id1);
41 rows deleted.
-- rollback; -- make test repeatable
$ > dtracelio.d 23585
Dynamic tracing of Oracle logical I/O v2.1 by Alexander Anokhin ( http://alexanderanokhin.wordpress.com )
233462: 22641 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
245054: 2829 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
365187: 2913 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
369681: 1947 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
404103: 2826 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
408598: 2029 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
429972: 2233 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
434528: 2212 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
453201: 6922 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
458011: 2301 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
479314: 2777 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
484221: 2266 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
506878: 2334 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
511463: 2202 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
532201: 2334 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
536500: 1965 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
556552: 2244 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
560690: 1834 kcbgcur(0xFFFFFD7FFAED9270,2,1199,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
577493: 3208 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
581798: 2276 kcbgtcr(0xFFFFFD7FFAED1730,0,1060,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
--Repeated lines removed--
1786824: 5448 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
1791226: 2020 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
1830860: 17280 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
1841407: 2737 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
1885701: 3609 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
1890635: 1952 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
1904651: 3127 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
1909925: 2340 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
--Repeated lines removed--
2202041: 5066 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
2206643: 2018 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
2220344: 5196 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
2224948: 2136 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
2242122: 2441 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
2246527: 2011 kcbgcur(0xFFFFFD7FFFDF3200,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
2255942: 2484 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c0008a (931/138) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
2260392: 1987 kcbget(0xFFFFFD7FFFDF3200,2,1066,0) [tsn: 2232 rdba: 0xe8c0008a (931/138) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
--Repeated lines removed--
===================== Logical I/O Summary (grouped by object/function) ==============
function stat object_id data_object_id mode_held where bufs calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
kcbgcur cu 0 -1 2 53 2 2
kcbgcur cu 0 -1 2 86 2 2
kcbgcur cu 0 -1 2 88 2 2
kcbgtcr cr 2286272 2286272 1298 2 2
kcbgtcr cr 2286272 2286272 1299 2 2
kcbnew cu 0 -1 47 2 2
kcbgcur cu 2286271 2286271 1 1062 8 8
kcbget cu 2286271 2286271 2 1066 8 8
kcbgtcr cr 2286272 2286272 1060 20 20
kcbgcur cu 2286272 2286272 1 1062 22 22
kcbget cu 2286272 2286272 2 1066 22 22
kcbgcur cu 2286270 2286270 2 1199 82 82
=====================================================================================
================================= Logical I/O Summary (grouped by object) ==========================================
object_id data_object_id lio cr cr (e) cr (d) cu cu (d) ispnd (Y) ispnd (N) pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
0 -1 8 0 0 0 8 0 0 0 2
2286270 2286270 82 0 0 0 82 0 0 0 82
2286271 2286271 16 0 0 0 16 0 0 0 0
2286272 2286272 68 24 2 0 44 0 0 2 18
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
total 174 24 2 0 150 0 0 2 102
====================================================================================================================
2.3 Test_3
--******************************* SQL Trace *******************************--
delete /*+ test_3 use_concat index_ss(@DEL$1_1 T@DEL$1 ksun_tab#u#2)
index_ffs(@DEL$1_2 T@DEL$1_2 ksun_tab#u#2) */ ksun_tab t where 99 in (id2, id1)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 23 211 41
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 23 211 41
ows (avg) Row Source Operation
--------- ---------------------------------------------------
0 DELETE KSUN_TAB (cr=23 pr=0 pw=0 time=1180 us)
41 CONCATENATION (cr=23 pr=0 pw=0 time=398 us)
0 INDEX SKIP SCAN KSUN_TAB#U#2 (cr=6 pr=0 pw=0 time=72 us cost=3 size=14 card=1)(object id 2286272)
41 INDEX FAST FULL SCAN KSUN_TAB#U#2 (cr=17 pr=0 pw=0 time=242 us cost=5 size=574 card=41)(object id 2286272)
--******************************* dtrace *******************************--
131208: 3788 kcbgtcr(0xFFFFFD7FFFDE5230,0,798,0) [tsn: 0 rdba: 0x5133b8 (1/1127352) obj: 1577349 dobj: 1577349] where: 798 exam: 0
181969: 3256 kcbgtcr(0xFFFFFD7FFFDE4E40,0,798,0) [tsn: 0 rdba: 0x5133b8 (1/1127352) obj: 1577349 dobj: 1577349] where: 798 exam: 0
--Repeated lines removed --
2537995: 2950 kcbgcur(0xFFFFFD7FFA0FB028,2,1199,0) [tsn: 2231 rdba: 0xe5400085 (917/133) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
2543063: 2038 kcbgcur(0xFFFFFD7FFA0FB028,2,1199,0) [tsn: 2231 rdba: 0xe5400085 (917/133) obj: 2286270 dobj: 2286270] where: 1199 mode_held: 2
2557738: 2324 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
2562180: 2074 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2232 rdba: 0xe8c00083 (931/131) obj: 2286271 dobj: 2286271] where: 1062 mode_held: 1
2569550: 3515 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
2575512: 2290 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2232 rdba: 0xe8c00087 (931/135) obj: 2286271 dobj: 2286271] where: 1066 mode_held: 2
2584580: 2492 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
2589073: 2002 kcbgcur(0xFFFFFD7FFFDF4660,1,1062,0) [tsn: 2233 rdba: 0x19400083 (101/131) obj: 2286272 dobj: 2286272] where: 1062 mode_held: 1
2594662: 2312 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
2599288: 1901 kcbget(0xFFFFFD7FFFDF4660,2,1066,0) [tsn: 2233 rdba: 0x19400086 (101/134) obj: 2286272 dobj: 2286272] where: 1066 mode_held: 2
--Repeated lines removed (40 Repeats)--
===================== Logical I/O Summary (grouped by object/function) ==============
function stat object_id data_object_id mode_held where bufs calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
kcbgcur cu 0 -1 2 53 2 2
kcbgcur cu 0 -1 2 88 2 2
kcbgtcr cr 1577349 1577349 799 2 2
kcbgtcr cr 2286272 2286272 798 2 2
kcbgcur cu 0 -1 2 86 4 4
kcbgtcr cr 1577349 1577349 798 4 4
kcbgtcr cr 2286272 2286272 799 4 4
kcbgtcr cr 2286272 2286272 800 4 4
kcbnew cu 0 -1 47 4 4
kcbgtcr cr 2286272 2286272 1153 12 12
kcbgtcr cr 2286272 2286272 1118 24 24
kcbgcur cu 2286270 2286270 2 1199 82 82
kcbgcur cu 2286271 2286271 1 1062 82 82
kcbgcur cu 2286272 2286272 1 1062 82 82
kcbget cu 2286271 2286271 2 1066 82 82
kcbget cu 2286272 2286272 2 1066 82 82
=====================================================================================
================================= Logical I/O Summary (grouped by object) ==========================================
object_id data_object_id lio cr cr (e) cr (d) cu cu (d) ispnd (Y) ispnd (N) pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
1577349 1577349 6 6 0 0 0 0 0 0 6
0 -1 12 0 0 0 12 0 0 0 4
2286270 2286270 82 0 0 0 82 0 0 0 82
2286271 2286271 164 0 0 0 164 0 0 0 0
2286272 2286272 210 46 0 0 164 0 0 0 46
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
total 474 52 0 0 422 0 0 0 138
====================================================================================================================
3. Discussions
Note that Dtrace Script statistics are double counted, which will be discussed in next Section: Dtrace Script double counted Statistics.
(a). Looking execution statistics of all 3 Tests, which delete the same 41 rows:
Test Consistent Gets Current Gets
------ --------------- ------------
Test_1 12 211
Test_2 12 75
Test_3 23 211
the majority of Logical Read is generated from Current Gets.
(b). Test_1 makes 211 Current Mode Gets, whereas Test_2 does 75 Current Mode Gets.
In Test_1, dtrace shows that each Current Get(kcbgcur) of KSUN_TAB (obj: 2286270)
follows by two Current Gets (kcbgcur and kcbget) of KSUN_TAB#U#1 (obj: 2286271)
and two Current Gets (kcbgcur and kcbget) of KSUN_TAB#U#2 (obj: 2286272).
41 deleted Rows results in:
41 (KSUN_TAB) + 2*41 (KSUN_TAB#U#1) + 2*41 (KSUN_TAB#U#2) = 205 Current Gets
plus 4 Current Gets (kcbgcur) and 2 Current Gets (kcbnew) of UNDO Segments (dobj: -1).
So in total, 205 + 4 + 2 = 211.
In Test_2, at first, 41 Current Gets (kcbgcur) of KSUN_TAB (obj: 2286270) for 41 deleted Rows,
then 22 Current Gets (kcbgcur and kcbget) of KSUN_TAB#U#2 (obj: 2286272),
and 8 Current Gets (kcbgcur and kcbget) of KSUN_TAB#U#1 (obj: 2286271):
41 (KSUN_TAB) + 22 (KSUN_TAB#U#2) + 8 (KSUN_TAB#U#1) = 71 Current Gets
plus 3 Current Gets (kcbgcur) and 1 Current Gets (kcbnew) of UNDO Segments (dobj: -1).
So in total, 71 + 3 + 1 = 75.
(c). SQL Trace xplan contains only Consistent Mode Gets ("cr=xxx"), but not Current Mode Gets.
However, Current Mode Gets is included in xplan statistics under Column current.
(d). Test_3 makes 211 Current Mode Gets, same as Test_1 although only one single Index:
KSUN_TAB#U#2 is involved in xplan.
Dtrace shows that it follows the same access pattern as Test_1 to read both KSUN_TAB#U#1
and KSUN_TAB#U#2 in Current Mode, but SQL Trace is not able to point out KSUN_TAB#U#1 Gets.
(e). Test_3 SQL Trace published 23 Consistent Mode Gets (query=23), but Dtrace shows 26 (=52/2).
The 3 (=26-23) is to read RMTAB$ (object_id = 1577349), which are not disclosed in SQL Trace.
(See MOS: Bug 20853821 - HIgh number of executions for queries on rmtab$ (Doc ID 20853821.8))
Therefore, SQL Trace is not able to disclose all Logical Reads.
Probably they stem from recursive calls, which can be visible in Sqlplus Autotrace.
4. Dtrace Script double counted Statistics
Comparing dtracelio.d output with SQL Trace:
Test1: SQL Trace query = 12 current = 211
Dtrace cr = 24 cu = 422
Test2: SQL Trace query = 12 current = 75
Dtrace cr = 24 cu = 150
it seems that Dtrace double counts cr and cu (also verified with Sqlplus Autotrace, v$sql.buffer_gets, and sys.dbms_sqltune.report_sql_monitor).
In all tests, we purposely deleted and selected odd number of rows (41), but all number in dtrace Summary are even number.We can observe this double counting when comparing 3 different Traces: one Sql Trace, one 10200 trace, and one dtrace for the same query.
At first, a small dtrace command shows us that each kcbgtcr is called by ktrget2, so in 10200 Trace, there is almost a 1-to-1 mapping between kcbgtcr and ktrget2.
SQL Trace shows that the query made cr=15 on KSUN_TAB#U#2 (object id 2286272), and 28-15=13 on KSUN_TAB (object id 2286270). dtracelio.d shows that cr=30 on object_id=2286272, cr=26 on object_id= 2286270.
10200 Trace contains two rows for each ktrget2 (which is immediate parent of kcbgtcr) call, first is "started", second is "completed", which probably caused this double counting.
--*************************** kcbgtcr is called by ktrget2 ***************************--
SQL > select/*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1);
$ dtrace -n 'pid$target::kcbgtcr:entry {ustack(2, 0); @[pid, ustack(2, 0)] = count();}' -p 23585
oracle`kcbgtcr
oracle`ktrgtc2+0x332
oracle`kcbgtcr
oracle`ktrgtc2+0x332
oracle`kcbgtcr
oracle`ktrget2+0x2b7
--53 Repeated lines removed--
oracle`kcbgtcr
oracle`ktrgtc2+0x332
2
oracle`kcbgtcr
oracle`ktrget2+0x2b7
54
--******************************* SQL Trace *******************************--
select /*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.00 0 28 0 41
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 28 0 41
Rows (avg) Row Source Operation
---------- ---------------------------------------------------
41 TABLE ACCESS BY INDEX ROWID BATCHED KSUN_TAB (cr=28 pr=0 pw=0 time=49 us cost=7 size=574 card=41)
41 INDEX FULL SCAN KSUN_TAB#U#2 (cr=15 pr=0 pw=0 time=636 us cost=6 size=0 card=41)(object id 2286272)
--******************************* 10200 Trace *******************************--
alter session set tracefile_identifier = 'test_2_10200_trace';
alter session set events '10200 trace name context forever,level 10';
select/*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1);
alter session set events '10200 trace name context off';
ktrget2(): started for block <0x08b7 : 0xe5400083> objd: 0x0022e2be (KSUN_TAB)
ktrget2(): completed for block <0x08b7 : 0xe5400083> objd: 0x0022e2be (KSUN_TAB)
ktrget2(): started for block <0x08b9 : 0x1940008e> objd: 0x0022e2c0 (KSUN_TAB#U#2)
ktrget2(): completed for block <0x08b9 : 0x1940008e> objd: 0x0022e2c0 (KSUN_TAB#U#2)
--Repeated lines removed--
--******************************* dtrace *******************************--
SQL > select/*+ test_2 index(t ksun_tab#U#2) */ * from ksun_tab t where 99 in (id2, id1);
$ > dtracelio.d 23585
1365716: 10444 kcbgtcr(0xFFFFFD7FFAEE4798,0,1061,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1061 exam: 0
1372023: 2458 kcbgtcr(0xFFFFFD7FFAEE4798,0,1061,0) [tsn: 2233 rdba: 0x19400084 (101/132) obj: 2286272 dobj: 2286272] where: 1061 exam: 0
1399863: 2673 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1007 exam: 0
1403855: 2116 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400083 (917/131) obj: 2286270 dobj: 2286270] where: 1007 exam: 0
1457916: 5590 kcbgtcr(0xFFFFFD7FFAEE4798,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
1462033: 2347 kcbgtcr(0xFFFFFD7FFAEE4798,0,1060,0) [tsn: 2233 rdba: 0x19400085 (101/133) obj: 2286272 dobj: 2286272] where: 1060 exam: 0
1493378: 2493 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1007 exam: 0
1497338: 2096 kcbgtcr(0xFFFFFD7FFA0FA518,0,1007,0) [tsn: 2231 rdba: 0xe5400084 (917/132) obj: 2286270 dobj: 2286270] where: 1007 exam: 0
--Repeated lines removed--
===================== Logical I/O Summary (grouped by object/function) ==============
function stat object_id data_object_id mode_held where bufs calls
--------- ------- ----------- ---------------- ----------- ------- -------- ---------
kcbgtcr cr 2286272 2286272 1298 2 2
kcbgtcr cr 2286272 2286272 1299 2 2
kcbgtcr cr 2286272 2286272 1061 6 6
kcbgtcr cr 2286272 2286272 1060 20 20
kcbgtcr cr 2286270 2286270 1007 26 26
=====================================================================================
================================= Logical I/O Summary (grouped by object) ==========================================
object_id data_object_id lio cr cr (e) cr (d) cu cu (d) ispnd (Y) ispnd (N) pin rls
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
0 0 0 0 0 0 0 0 0 2 0
2286270 2286270 26 26 0 0 0 0 130 32 26
2286272 2286272 30 30 2 0 0 0 0 8 28
---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------
total 56 56 2 0 0 0 130 42 54
====================================================================================================================
5. Performance Test
Run above 3 Tests 10000 times and watch their statistics difference.
alter system flush shared_pool;
declare
p_cnt number := 10000;
begin
for i in 1..p_cnt loop
delete /*+ test_1 use_concat index_ss(@DEL$1 T@DEL$1 ksun_tab#u#2) index_ss(@DEL$1_2 T@DEL$1_2 ksun_tab#u#1) */
ksun_tab t where 99 in (id2, id1);
rollback;
end loop;
for i in 1..p_cnt loop
delete /*+ test_2 index(t ksun_tab#U#2) */ ksun_tab t where 99 in (id2, id1);
rollback;
end loop;
for i in 1..p_cnt loop
delete /*+ test_3 use_concat index_ss(@DEL$1_1 T@DEL$1 ksun_tab#u#2) index_ffs(@DEL$1_2 T@DEL$1_2 ksun_tab#u#2) */
ksun_tab t where 99 in (id2, id1);
rollback;
end loop;
end;
/
select substr(sql_text, 1, 18) sql_text, buffer_gets, round(buffer_gets/10000) buffer_gets_per_exec
,rows_processed, physical_read_bytes, physical_write_bytes, elapsed_time, cpu_time, sql_id --, v.*
from v$sql v where lower(sql_text) like 'delete%test%' order by v.sql_text;
SQL_TEXT BUFFER_GETS BUFFER_GETS_PER_EXEC ROWS_PROCESSED PHYSICAL_READ_BYTES PHYSICAL_WRITE_BYTES ELAPSED_TIME CPU_TIME SQL_ID
----------------- ----------- -------------------- -------------- ------------------- -------------------- ------------ -------- -------------
DELETE /*+ test_1 2210823 221 410000 1146880 210026496 7534494 7400730 g2267fmk9u39r
DELETE /*+ test_2 870403 87 410000 786432 210026496 7802519 7755552 5xqavr92xbvw7
DELETE /*+ test_3 2320261 232 410000 401408 105013248 9445604 9320234 66dw2ur1uakhn
6. dtracelio.d
Dtrace script is appended in the Blog for a quick reference. The script is extended with time stamp and time delta similar to truss (-d, -D options) prefixed in each output line.
#!/usr/sbin/dtrace -CZs
/* Add time stamp and time delta similar to truss (-d, -D options) */
/********************************************************************************************/
/* */
/* File Name: dtracelio.d */
/* Version: 2.1 */
/* Authors: Alexander Anokhin ( http://alexanderanokhin.com ) */
/* Andrey Nikolaev ( http://andreynikolaev.wordpress.com ) */
/* Dated: Mar 2012 */
/* Purpose: The script shows calls of the functions */
/* performing logical I/O in Oracle. */
/* */
/* Usage: dtracelio.d [show_each_call] [interval] */
/* PID: unix process ID */
/* show_each_call - Bitmask determining how functions calls will be shown */
/* 1st bit - logical I/O functions */
/* 2nd bit - buffer pinning */
/* Examples: */
/* 0: output of each call will be disabled */
/* 1: logical I/O functions will be shown */
/* 3: logical I/O and buffer pinning functions */
/* will be shown */
/* Default value: 1 */
/* interval - Specifies the number of seconds over which */
/* Summary form with cumulative figures will be shown. */
/* Works only when show_each_call is disabled. */
/* */
/* Other: Some bits of info in 8103.1 */
/* Note that data structures definitions are not full */
/* in current version of the script */
/* */
/********************************************************************************************/
#pragma D option quiet
#pragma D option defaultargs
#pragma D option switchrate=10Hz
/* 0. Several standard oratype.h declarations */
typedef unsigned long long ub8; /* unsigned int of length 8 */
typedef unsigned int ub4;
typedef unsigned short ub2;
typedef unsigned char ub1;
typedef int sb4;
/* */
typedef sb4 kobjd;
typedef sb4 kobjn;
typedef ub4 ktsn;
typedef ub4 krdba;
/* definition from MOS note 8103.1 */
typedef struct kdbafr /* full relative dba */ {
ktsn tsn_kdbafr; /* a tablespace number */
krdba dba_kdbafr; /* a relative dba */ } kdbafr;
typedef struct ktid /* relative dba + objd */ {
struct kdbafr dbr_ktid; /* a relative dba */
kobjd objd_ktid; /* data object number */
kobjn objn_ktid; /* dictionary object number */ } ktid;
typedef struct kcbds
{
struct ktid kcbdstid; /* full relative DBA plus object number */
/* Here unknown (yet ;-)) part of the structure */ } kcbds;
BEGIN
{
show_each_call = ($$2 == NULL) ? 1:$2;
tick_time_interval = ($$3 == NULL) ? 0:$3;
trace_logical_io = 1;
trace_buf_pinning = 1;
show_lio_calls = show_each_call & 1;
show_buf_pins_calls = show_each_call & 2;
printf("\nDynamic tracing of Oracle logical I/O v2.1 by Alexander Anokhin ( http://alexanderanokhin.wordpress.com )\n\n");
t0 = 0;
}
pid$1::kcbgtcr:entry,
pid$1::kcbgcur:entry,
pid$1::kcbnew:entry,
pid$1::kcbrls:entry,
pid$1::kcbispnd:entry,
pid$1::kcbldrget:entry,
pid$1::kcbget:entry
{
blk = ((kcbds *) copyin(arg0, sizeof(kcbds)));
tsn = blk->kcbdstid.dbr_ktid.tsn_kdbafr;
rdba = blk->kcbdstid.dbr_ktid.dba_kdbafr;
objd = blk->kcbdstid.objd_ktid;
objn = blk->kcbdstid.objn_ktid;
rdba_file = rdba >> 22; /* for smallfile tablespaces */
rdba_block = rdba & 0x3FFFFF;
t0 = (t0 == 0) ? timestamp:t0; t1 = timestamp;
}
pid$1::kcbgtcr:entry
/trace_logical_io/
{
stat = "cr";
where = arg2&0xFFFF;
mode_held = "";
@func[probefunc,stat,objn,objd,mode_held,where] = count();
@bufs[probefunc,stat,objn,objd,mode_held,where] = sum(1);
@obj_cr[objn,objd] = sum(1);
@total_cr = sum(1);
@obj_cr_exam[objn,objd] = sum(arg1);
@total_cr_exam = sum(arg1);
@obj_lio[objn,objd] = sum(1);
@total_lio = sum(1);
}
pid$1::kcbgtcr:entry
/trace_logical_io && show_lio_calls/
{ t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2; /* Elapsed nanosecond from beginning: Elapsed delta from last printf */
printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d] where: %d exam: %d\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn, objd, where, arg1); }
pid$1::kcbldrget:entry
/trace_logical_io/
{
stat = "cr (d)";
where = 0;
mode_held = "";
@func[probefunc,stat,objn,objd,mode_held,where] = count();
@bufs[probefunc,stat,objn,objd,mode_held,where] = sum(1);
@obj_cr_d[objn,objd] = sum(1);
@total_cr_d = sum(1);
@obj_cr[objn,objd] = sum(-1);
@total_cr = sum(-1);
/* commented because incremented in kcbgtcr yet
@obj_lio[objn,objd] = sum(1);
@total_lio = sum(1);
*/
}
pid$1::kcbldrget:entry
/trace_logical_io && show_lio_calls/
{ t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
printf("%s(0x%X,%d,%d,%d)\n",probefunc,arg0,arg1,arg2,arg3);
}
pid$1::kcbgcur:entry,
pid$1::kcbget:entry
/trace_logical_io/
{
stat = "cu";
where = arg2&0xFFFF;
mode_held = lltostr(arg1);
@func[probefunc,stat,objn,objd,mode_held,where] = count();
@bufs[probefunc,stat,objn,objd,mode_held,where] = sum(1);
@obj_cu[objn,objd] = sum(1);
@total_cu = sum(1);
@obj_lio[objn,objd] = sum(1);
@total_lio = sum(1);
}
pid$1::kcbgcur:entry,
pid$1::kcbget:entry
/trace_logical_io && show_lio_calls/
{ t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d] where: %d mode_held: %s\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn, objd, where, mode_held); }
pid$1::kcbnew:entry
/trace_logical_io/
{
stat = "cu";
where = arg2&0xFFFF;
mode_held = "";
blocks = arg1;
@func[probefunc,stat,objn,objd,mode_held,where] = count();
@bufs[probefunc,stat,objn,objd,mode_held,where] = sum(blocks);
@obj_cu[objn,objd] = sum(blocks);
@total_cu = sum(blocks);
@obj_lio[objn,objd] = sum(blocks);
@total_lio = sum(blocks);
}
pid$1::kcbnew:entry
/trace_logical_io && show_lio_calls/
{ t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d] where: %d mode_held: %s blocks: %d\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn, objd, where, mode_held, blocks); }
pid$1::kcblnb:entry, pid$1::kcblnb_dscn:entry /trace_logical_io/ {
stat = "cu (d)";
@func[probefunc,stat,0,0,"",0] = count();
@bufs[probefunc,stat,0,0,"",0] = sum(1);
@obj_cu[objn,objd] = sum(1);
@total_cu = sum(1);
@obj_cu_d[objn,objd] = sum(1);
@total_cu_d = sum(1);
@obj_lio[objn,objd] = sum(1);
@total_lio = sum(1);
}
pid$1::kcblnb:entry, pid$1::kcblnb_dscn:entry /trace_logical_io && show_lio_calls/ {
t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
printf("%s(0x%X,%d,%d,%d)\n",probefunc,arg0,arg1,arg2,arg3);
}
/* buffer pinning */
pid$1::kcbispnd:entry
/trace_buf_pinning && show_buf_pins_calls/ {
t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d]: ",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn,objd);
}
pid$1::kcbispnd:return
/trace_buf_pinning && arg1 == 0/
{
@obj_is_not_pnd[objn,objd] = sum(1);
@total_is_not_pnd = sum(1);
}
pid$1::kcbispnd:return
/trace_buf_pinning && arg1 == 1/
{
@obj_is_pnd[objn,objd] = sum(1);;
@total_is_pnd = sum(1);
}
pid$1::kcbispnd:return
/trace_buf_pinning && show_buf_pins_calls/ {
t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
printf("%d\n",arg1);
}
pid$1::kcbrls:entry
/trace_buf_pinning/
{
@obj_pinrls[objn,objd] = sum(1);
@total_pinrls = sum(1);
}
pid$1::kcbrls:entry
/trace_buf_pinning && show_buf_pins_calls/ {
t2 = timestamp; printf("%10d: %6d ", t2-t0, t2-t1); t1 = t2;
printf("%s(0x%X,%d,%d,%d) [tsn: %d rdba: 0x%x (%d/%d) obj: %d dobj: %d]\n",probefunc,arg0,arg1,arg2,arg3,tsn, rdba,rdba_file,rdba_block,objn,objd);
}
tick-1sec
/show_each_call == 0 && tick_time_interval > 0 && ++ticks >= tick_time_interval/ {
printf("\n\n");
printf("\n================================= Logical I/O Summary (grouped by object) ==========================================\n");
printf(" object_id data_object_id lio cr cr (e) cr (d) cu cu (d) ispnd (Y) ispnd (N) pin rls\n");
printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
printa("%10d %15d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n",
@obj_lio, @obj_cr, @obj_cr_exam, @obj_cr_d, @obj_cu, @obj_cu_d, @obj_is_pnd, @obj_is_not_pnd, @obj_pinrls);
printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
printa(" total %25@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n", @total_lio, @total_cr, @total_cr_exam, @total_cr_d, @total_cu, @total_cu_d, @total_is_pnd, @total_is_not_pnd, @total_pinrls);
printf("====================================================================================================================\n");
ticks = 0;
}
END
{
printf("\n===================== Logical I/O Summary (grouped by object/function) ==============\n");
printf(" function stat object_id data_object_id mode_held where bufs calls\n");
printf("--------- ------- ----------- ---------------- ----------- ------- -------- ---------\n");
printa("%9s %7s %11d %16d %11s %7d %@8d %@9d\n", @bufs, @func);
printf("=====================================================================================\n");
}
END
{
printf("\n================================= Logical I/O Summary (grouped by object) ==========================================\n");
printf(" object_id data_object_id lio cr cr (e) cr (d) cu cu (d) ispnd (Y) ispnd (N) pin rls\n");
printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
printa("%10d %15d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n",
@obj_lio, @obj_cr, @obj_cr_exam, @obj_cr_d, @obj_cu, @obj_cu_d, @obj_is_pnd, @obj_is_not_pnd, @obj_pinrls);
printf("---------- --------------- --------- --------- --------- --------- --------- --------- --------- --------- ---------\n");
printa(" total %25@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d %9@d\n", @total_lio, @total_cr, @total_cr_exam, @total_cr_d, @total_cu, @total_cu_d, @total_is_pnd, @total_is_not_pnd, @total_pinrls);
printf("====================================================================================================================\n");
printf("\n");
printf("Legend\n");
printf("lio : logical gets (cr + cu)\n");
printf("cr : consistent gets\n");
printf("cr (e) : consistent gets - examination\n");
printf("cr (d) : consistent gets direct\n");
printf("cu : db block gets\n");
printf("cu (d) : db block gets direct\n");
printf("ispnd (Y): buffer is pinned count\n");
printf("ispnd (N): buffer is not pinned count\n");
printf("pin rls : pin releases\n");
}
