I have an oracle-10046—aka. sqltrace—file similar to this structure:
Oracle Release 11.2
PARSING IN CURSOR #1 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=1 ad='1' sqlid='A'
insert
END OF STMT
PARSING IN CURSOR #2 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=2 ad='2' sqlid='r'
update next_step
END OF STMT
PARSING IN CURSOR #3 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=3 ad='3' sqlid='B'
update complete
END OF STMT
PARSING IN CURSOR #4 len=20 dep=0 uid=7 oct=3 lid=7 tim=2 hv=4 ad='4' sqlid='X'
select X
END OF STMT
PARSING IN CURSOR #5 len=20 dep=0 uid=7 oct=3 lid=7 tim=2 hv=5 ad='5' sqlid='Y'
select Y
END OF STMT
EXEC #1:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=100
EXEC #2:c=2,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=200
EXEC #3:c=4,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=300
EXEC #4:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=310
EXEC #5:c=6,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=320
EXEC #1:c=8,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=400
EXEC #2:c=16,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=416
EXEC #3:c=32,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=448
I identified sqlid 'A' as the beginning of a specific sequence, and sqlid 'B' as it's end. In between there is only sqlid 'r' in my example, but it could be much more, even not the same SQLs or sequence of SQLs. Other SQLs like sqlid 'X' and 'Y' are not within my sequence of interest and should be visible as such.
My tool of choice right now is mrskew from the Method R Tools product from methodr. As it can be extended with Perl code, I'm sure this can be done, but my Perl skills are limited as my understanding of mrskew internals.
I highly appreciate any hint or help here.
Using your test data, martin1.trc, I created the rc file, martin1.rc.
--init='
my $xfrm_id;
sub xfrm {
$xfrm_id = $exec_id if ($sqlid//"") eq "A";
return $xfrm_id//$exec_id;
}
'
--group='xfrm()'
Then I executed mrskew --rc martin1.rc martin1.trc and I got this output:
'xfrm()' DURATION % CALLS MEAN MIN MAX
--------- -------- ------ ----- -------- -------- --------
25 0.000056 75.7% 3 0.000019 0.000008 0.000032
18 0.000018 24.3% 5 0.000004 0.000001 0.000006
--------- -------- ------ ----- -------- -------- --------
TOTAL (2) 0.000074 100.0% 8 0.000009 0.000001 0.000032
This report shows two executions of the interesting transaction. The most interesting (greatest response time) transaction execution began on trace file line 25 and contributed 0.000056 seconds (75.7% of the total) over 3 dbcalls to the total response time. The other most interesting execution began on line 18 and contributed the other 24.3% to the total. We know that lines 22-23 are uninteresting, but the simple method does not distinguish them. And that is why the report says the execution starting on line 18 has 5 dbcalls for 0.000018 seconds instead of 3 dbcalls for 0.000007 seconds.
If we significantly change the transformation function then we can handle the transaction ending at statement B (even if B is an EXEC followed by other B dbcalls (e.g., FETCH). Here is martin2.rc:
--init='
my $sawB;
my $xfrm_id;
sub xfrm {
if (($sqlid//"") eq "A") {
$xfrm_id = $exec_id; # global scope maintains state
} else {
if (($sqlid//"") eq "B") {
$sawB = 1;
} else {
if ($sawB) {
$sawB = undef;
$xfrm_id = undef;
}
}
}
return $xfrm_id//0;
}
'
--group='xfrm()'
In keeping with the notion of a profile (whereby the total represents the total for the whole experience), I decided to transform all non-interesting transaction dbcalls to 0 which is a line number that cannot appear in a file. This way you can see how the interesting transactions rank w.r.t. the whole experience.
$ mrskew --rc martin2.rc martin1.trc
'xfrm()' DURATION % CALLS MEAN MIN MAX
--------- -------- ------ ----- -------- -------- --------
25 0.000056 75.7% 3 0.000019 0.000008 0.000032
0 0.000011 14.9% 2 0.000005 0.000005 0.000006
18 0.000007 9.5% 3 0.000002 0.000001 0.000004
--------- -------- ------ ----- -------- -------- --------
TOTAL (3) 0.000074 100.0% 8 0.000009 0.000001 0.000032
If I duplicate line 20 (which takes 4 µsecs), then the output says this:
'xfrm()' DURATION % CALLS MEAN MIN MAX
--------- -------- ------ ----- -------- -------- --------
26 0.000056 71.8% 3 0.000019 0.000008 0.000032
18 0.000011 14.1% 4 0.000003 0.000001 0.000004
0 0.000011 14.1% 2 0.000005 0.000005 0.000006
--------- -------- ------ ----- -------- -------- --------
TOTAL (3) 0.000078 100.0% 9 0.000009 0.000001 0.000032
You can see that the interesting transaction starting on line 18 now contributes 11 µsecs over 4 dbcalls. This seems to be a more complete test confirming the appropriateness of martin2.rc.
In the last report, you can see that the interesting transaction represents 71.8%+14.1%=85.9% of the total response time in the file. If you further modify the transformation function (exercise left to the reader), then you can aggregate into "interesting" and "not interesting" rather than what I did, which was to add two percentages.