在 Oracle SQL-Trace 中:如何在未检测代码时对一组 SQL 执行进行分组?
in Oracle SQL-Trace: how can I group a set of SQL executions when the code is not instrumented?
我有一个 oracle-10046 — 又名。 sqltrace——类似于此结构的文件:
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
我将 sqlid 'A' 确定为特定序列的开始,将 sqlid 'B' 确定为结束。在我的示例中,中间只有 sqlid 'r',但它可能更多,甚至不是相同的 SQL 或 SQL 序列。
sqlid 'X' 和 'Y' 等其他 SQL 不在我感兴趣的序列范围内,因此应该是可见的。
我现在选择的工具是 methodr 的 Method R Tools 产品中的 mrskew。
因为它可以用 Perl 代码扩展,我相信这是可以做到的,但我的 Perl 技能是有限的,因为我对 mrskew 内部的理解。
我非常感谢这里的任何提示或帮助。
使用您的测试数据,martin1.trc,我创建了 rc 文件,martin1.rc。
--init='
my $xfrm_id;
sub xfrm {
$xfrm_id = $exec_id if ($sqlid//"") eq "A";
return $xfrm_id//$exec_id;
}
'
--group='xfrm()'
然后我执行了mrskew --rc martin1.rc martin1.trc
,我得到了这个输出:
'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
此报告显示了有趣事务的两次执行。最有趣(最长响应时间)的事务执行从跟踪文件第 25 行开始,在 3 个数据库调用中占总响应时间的 0.000056 秒(占总数的 75.7%)。另一个最有趣的执行从第 18 行开始,占总数的 24.3%。我们知道第22-23行是无趣的,但是简单的方法并没有区分它们。这就是为什么报告说从第 18 行开始的执行有 5 个 dbcalls 持续 0.000018 秒,而不是 3 个 dbcalls 持续 0.000007 秒。
如果我们显着更改转换函数,那么我们可以处理以语句 B 结束的事务(即使 B 是一个 EXEC,后面跟着其他 B dbcalls(例如,FETCH)。这里是 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()'
为了与配置文件的概念保持一致(总计代表整个体验的总计),我决定将所有不感兴趣的事务 dbcalls 转换为 0,这是一个不能出现在文件中的行号。这样您就可以看到有趣的交易排名 w.r.t。整个体验。
$ 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
如果我复制第 20 行(需要 4 微秒),那么输出是这样的:
'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
您可以看到从第 18 行开始的有趣事务现在在 4 个数据库调用中贡献了 11 微秒。这似乎是一个更完整的测试,确认 martin2.rc.
的适当性
在上一份报告中,您可以看到感兴趣的事务占文件总响应时间的 71.8%+14.1%=85.9%。如果你进一步修改转换函数(练习留给reader),那么你可以聚合成"interesting"和"not interesting"而不是我做的,即添加两个百分比。
我有一个 oracle-10046 — 又名。 sqltrace——类似于此结构的文件:
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
我将 sqlid 'A' 确定为特定序列的开始,将 sqlid 'B' 确定为结束。在我的示例中,中间只有 sqlid 'r',但它可能更多,甚至不是相同的 SQL 或 SQL 序列。 sqlid 'X' 和 'Y' 等其他 SQL 不在我感兴趣的序列范围内,因此应该是可见的。
我现在选择的工具是 methodr 的 Method R Tools 产品中的 mrskew。 因为它可以用 Perl 代码扩展,我相信这是可以做到的,但我的 Perl 技能是有限的,因为我对 mrskew 内部的理解。
我非常感谢这里的任何提示或帮助。
使用您的测试数据,martin1.trc,我创建了 rc 文件,martin1.rc。
--init='
my $xfrm_id;
sub xfrm {
$xfrm_id = $exec_id if ($sqlid//"") eq "A";
return $xfrm_id//$exec_id;
}
'
--group='xfrm()'
然后我执行了mrskew --rc martin1.rc martin1.trc
,我得到了这个输出:
'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
此报告显示了有趣事务的两次执行。最有趣(最长响应时间)的事务执行从跟踪文件第 25 行开始,在 3 个数据库调用中占总响应时间的 0.000056 秒(占总数的 75.7%)。另一个最有趣的执行从第 18 行开始,占总数的 24.3%。我们知道第22-23行是无趣的,但是简单的方法并没有区分它们。这就是为什么报告说从第 18 行开始的执行有 5 个 dbcalls 持续 0.000018 秒,而不是 3 个 dbcalls 持续 0.000007 秒。
如果我们显着更改转换函数,那么我们可以处理以语句 B 结束的事务(即使 B 是一个 EXEC,后面跟着其他 B dbcalls(例如,FETCH)。这里是 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()'
为了与配置文件的概念保持一致(总计代表整个体验的总计),我决定将所有不感兴趣的事务 dbcalls 转换为 0,这是一个不能出现在文件中的行号。这样您就可以看到有趣的交易排名 w.r.t。整个体验。
$ 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
如果我复制第 20 行(需要 4 微秒),那么输出是这样的:
'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
您可以看到从第 18 行开始的有趣事务现在在 4 个数据库调用中贡献了 11 微秒。这似乎是一个更完整的测试,确认 martin2.rc.
的适当性在上一份报告中,您可以看到感兴趣的事务占文件总响应时间的 71.8%+14.1%=85.9%。如果你进一步修改转换函数(练习留给reader),那么你可以聚合成"interesting"和"not interesting"而不是我做的,即添加两个百分比。