There is another source of information as well, you could call it the DO interface, but the common term is session and system statistics. there Oracle counts what it is doing.
Unfortunately I do not know a simple way to show both realities in a common way.
At least for consistent gets I now can show (most of) them together with wait events.
The magic is done by event 10200 - Dump Consistent Reads.
I create a trace file with both, 10046 and 10200 event:
SET AUTOTRACE ON STATISTICS
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
select * from berx.t1;
Statistics
----------------------------------------------------------
80 recursive calls
0 db block gets
118 consistent gets
0 physical reads
0 redo size
654 bytes sent via SQL*Net to client
524 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
15 sorts (memory)
0 sorts (disk)
3 rows processed
Of course the additional event gives additional lines which will not be processed by those tools to parse SQL traces. I will not go into any detail of those additional lines - especially as I don't know about them to much. If you are interested I'd recommend Charles Hoopers blog.
I just grab lines which contain the string completed for block and rework their values so it looks similar to something the SQL trace parsers know. This is a very inexperienced piece of code!
#!/usr/bin/perl -w
#10200_preproc.pl
use strict;
my $cursor = 0 ;
my $timestamp = 0 ;
my $is_processed = 0 ;
my $tablespace;
my $block;
my $object_id;
while (<>) {
my $line = $_;
if ($line =~ m/.*#(\d+)[: ].*/) {
($cursor = $line) =~ s/.*#(\d+)[: ].*/$1/ ;
}
$cursor =~ tr/\n//d;
if ($line =~ m/.*tim=(\d+).*/) {
($timestamp = $line) =~ s/.*#(\d+)[: ].*/$1/ ;
}
$timestamp =~ tr/\n//d;
if ($line =~ m/completed for block/) {
($tablespace = $line) =~ s/.*\<([abcdefx\d]+) : .*/$1/ ;
($block = $line) =~ s/.* : ([abcdefx\d]+).*/$1/;
($object_id = $line) =~ s/.*objd: ([abcdefx\d]+).*/$1/;
$tablespace =~ tr/\n//d;
$block =~ tr/\n//d;
$object_id =~ tr/\n//d;
$tablespace = hex($tablespace) +1;
$block = hex($block);
$object_id = hex($object_id);
# WAIT #391723720: nam='db file scattered read' ela= 2876 file#=5 block#=129 blocks=127 obj#=71123 tim=90982740602
print "WAIT #"; # as the hash is somethign special ...
print "$cursor: nam='LIO - completed for block' ela=0 tablespace=$tablespace block#=$block obj=$object_id obj#=$object_id tim=$timestamp\n";
$is_processed = 1;
}
if ($is_processed == 0) {
print $line;
}
else {
$is_processed = 0
}
}
This code should really be seen as an example, not a solution!
Out of a line like
ktrgcm(): completed for block <0x0000 : 0x0041560c> objd: 0x0000003e
it creates
WAIT #47572859450312: nam='LIO - completed for block' ela=0 tablespace=1 block#=4281868 obj=62 obj#=62 tim=47572859450312
Probably the only magic is the Cursor and timing info which I just copy from the last SQL trace line above. I'd as well like not to use the keyword WAIT as for sure the process is not waiting in this case, but I have to still trick the tools.
With my modified tracefile from the statement above I create this report:
CALL-NAME DURATION % CALLS MEAN MIN MAX --------------------------- -------- ------ ----- -------- -------- -------- SQL*Net message from client 0.671976 95.8% 3 0.223992 0.000165 0.671529 PARSE 0.025995 3.7% 1 0.025995 0.025995 0.025995 row cache lock 0.001640 0.2% 12 0.000137 0.000079 0.000497 FETCH 0.001000 0.1% 2 0.000500 0.000000 0.001000 library cache pin 0.000471 0.1% 2 0.000236 0.000214 0.000257 library cache lock 0.000443 0.1% 2 0.000222 0.000211 0.000232 Disk file operations I/O 0.000047 0.0% 1 0.000047 0.000047 0.000047 SQL*Net message to client 0.000002 0.0% 3 0.000001 0.000000 0.000001 LIO - completed for block 0.000000 0.0% 117 0.000000 0.000000 0.000000 CLOSE 0.000000 0.0% 3 0.000000 0.000000 0.000000 EXEC 0.000000 0.0% 1 0.000000 0.000000 0.000000 XCTEND 0.000000 0.0% 1 0.000000 0.000000 0.000000 --------------------------- -------- ------ ----- -------- -------- -------- TOTAL (12) 0.701574 100.0% 148 0.004740 0.000000 0.671529
You see 117 LIO - completed for block events here, which is quite close to 118 consistent gets.
There are probably a lot more things to do, still it helps me to show what a statement is doing (in terms of LIO) beside the time it spends waiting.
