怎么看tkprof后的trace文件？

显示全部楼层 · 2007-9-26 18:42:10

我使用了alter session set events '10046 trace name context forever,level 12';来trace session。
我对tkprof后的trace文件只能看懂很少的一部分，
如query 对应 consistent gets
Parsing下的为执行计划。
但这里还有很多的内容的，我就不太清楚。
比如：
1、如何看出是软分析还是硬分析；
2、如何看出是否绑定；是不是看是否有执行计划？
3、以下是不是的Parse2、Execute 2、Fetch4是不是说明该sql有一次硬分析，1次软分析，执行了2次？
还是因为Misses in library cache during parse: 2说明2次都是硬分析呢？
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse20.00 0.00
0
0
0 0
Execute20.01 0.00
0
0
0 0
Fetch40.06 0.05
0 2156
0 4
------- -------------- ---------- ---------- ---------- --------------------
total80.07 0.05
0 2156
0 4
Misses in library cache during parse: 2
4、最后的部分的各个项的含义应该都是汇总信息吧：
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 8750 11.1813.82
0120
0 0
Execute 87511.81 2.34
0
0
0 0
Fetch16273103.85 122.51 86453527064
08926
------- -------------- ---------- ---------- ---------- --------------------
total33774116.84 138.69 86453527184
08926
Misses in library cache during parse: 3701

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 300.03 0.09
1 39
0 0
Execute 560.00 0.00
0
0
0 0
Fetch1770.01 0.00
0221
0 133
------- -------------- ---------- ---------- ---------- --------------------
total2630.04 0.10
1260
0 133
Misses in library cache during parse: 13
8751userSQL statements in session.
30internal SQL statements in session.
8781SQL statements in session.
********************************************************************************
Trace file: e:\work_doc\sdp\unicode_ora_2627.trc
Trace file compatibility: 9.00.01
Sort options: default
1session in tracefile.
8751userSQL statements in trace file.
30internal SQL statements in trace file.
8781SQL statements in trace file.
3232unique SQL statements in trace file.
128622lines in trace file.
其中Misses in library cache during parse: 3701 是不是说明硬分析有这么多？
8781SQL statements in trace file.
3232unique SQL statements in trace file.
这是不是说明8781- 3232=5549的sql是与其他sql相同的？
最后部分也应该能看出绑定等信息吧。
请教大家了。

千问 · 2007-9-26 18:42:10

我也想知道

千问 · 2007-9-26 18:42:10

这个，看看tom的oracle高效率设计吧。要说清楚还是要花不少篇幅的。

千问 · 2007-9-26 18:42:10

最初由 monkeyai 发布
[B]这个，看看tom的oracle高效率设计吧。要说清楚还是要花不少篇幅的。 [/B]
我现在没法看到这本书，能先帮我点点吗？

千问 · 2007-9-26 18:42:10

最初由 cjf107 发布
[B]我使用了alter session set events '10046 trace name context forever,level 12';来trace session。
我对tkprof后的trace文件只能看懂很少的一部分，
如query 对应 consistent gets
Parsing下的为执行计划。
但这里还有很多的内容的，我就不太清楚。
比如：
1、如何看出是软分析还是硬分析；
2、如何看出是否绑定；是不是看是否有执行计划？
3、以下是不是的Parse2、Execute 2、Fetch4是不是说明该sql有一次硬分析，1次软分析，执行了2次？
还是因为Misses in library cache during parse: 2说明2次都是硬分析呢？
parse 1次，而execute大于1次，就表示使用了绑定。
现在这种情况是没有使用绑定变量，导致执行2次需要解析2次。
[/COLOR]
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse20.00 0.00
0
0
0 0
Execute20.01 0.00
0
0
0 0
Fetch40.06 0.05
0 2156
0 4
------- -------------- ---------- ---------- ---------- --------------------
total80.07 0.05
0 2156
0 4
Misses in library cache during parse: 2
4、最后的部分的各个项的含义应该都是汇总信息吧：
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 8750 11.1813.82
0120
0 0
Execute 87511.81 2.34
0
0
0 0
Fetch16273103.85 122.51 86453527064
08926
------- -------------- ---------- ---------- ---------- --------------------
total33774116.84 138.69 86453527184
08926
Misses in library cache during parse: 3701

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 300.03 0.09
1 39
0 0
Execute 560.00 0.00
0
0
0 0
Fetch1770.01 0.00
0221
0 133
------- -------------- ---------- ---------- ---------- --------------------
total2630.04 0.10
1260
0 133
Misses in library cache during parse: 13
8751userSQL statements in session.
30internal SQL statements in session.
8781SQL statements in session.
********************************************************************************
Trace file: e:\work_doc\sdp\unicode_ora_2627.trc
Trace file compatibility: 9.00.01
Sort options: default
1session in tracefile.
8751userSQL statements in trace file.
30internal SQL statements in trace file.
8781SQL statements in trace file.
3232unique SQL statements in trace file.
128622lines in trace file.
其中Misses in library cache during parse: 3701 是不是说明硬分析有这么多？
8781SQL statements in trace file.
3232unique SQL statements in trace file.
这是不是说明8781- 3232=5549的sql是与其他sql相同的？
最后部分也应该能看出绑定等信息吧。
这里应该是说有3232 条sql语句是独一无二的，但不能说明就一定没有使用绑定变量，说不定绑定了，也只执行一次。
[/COLOR]
请教大家了。 [/B]

千问 · 2007-9-26 18:42:10

最初由 hanson 发布
parse 1次，而execute大于1次，就表示使用了绑定。
现在这种情况是没有使用绑定变量，导致执行2次需要解析2次。
[B] [/B]
我觉得用了绑定也可能出现parse=execute，都大于1次，这时的parse为软解析：
如我先alter session set events '10046 trace name context forever,level 12';
再用exec :var :=不同的值，手工运行同一个sql16次，在trace文件中只出现一次这个sql，其中如下：
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 160.01 0.01
0
2
0 0
Execute 160.00 0.00
0
0
0 0
Fetch 180.01 0.38472 1058
0
10
------- -------------- ---------- ---------- ---------- --------------------
total 500.03 0.40472 1060
0
10
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id:
这样应该是进行了bind的，而在Misses in library cache during parse: 1
也应该说明了这个问题。

千问 · 2007-9-26 18:42:10

最初由 cjf107 发布
[B]我使用了alter session set events '10046 trace name context forever,level 12';来trace session。
我对tkprof后的trace文件只能看懂很少的一部分，
如query 对应 consistent gets
Parsing下的为执行计划。
但这里还有很多的内容的，我就不太清楚。
比如：
1、如何看出是软分析还是硬分析；
2、如何看出是否绑定；是不是看是否有执行计划？
3、以下是不是的Parse2、Execute 2、Fetch4是不是说明该sql有一次硬分析，1次软分析，执行了2次？
还是因为Misses in library cache during parse: 2说明2次都是硬分析呢？
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse20.00 0.00
0
0
0 0
Execute20.01 0.00
0
0
0 0
Fetch40.06 0.05
0 2156
0 4
------- -------------- ---------- ---------- ---------- --------------------
total80.07 0.05
0 2156
0 4
Misses in library cache during parse: 2
4、最后的部分的各个项的含义应该都是汇总信息吧：
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 8750 11.1813.82
0120
0 0
Execute 87511.81 2.34
0
0
0 0
Fetch16273103.85 122.51 86453527064
08926
------- -------------- ---------- ---------- ---------- --------------------
total33774116.84 138.69 86453527184
08926
Misses in library cache during parse: 3701

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 300.03 0.09
1 39
0 0
Execute 560.00 0.00
0
0
0 0
Fetch1770.01 0.00
0221
0 133
------- -------------- ---------- ---------- ---------- --------------------
total2630.04 0.10
1260
0 133
Misses in library cache during parse: 13
8751userSQL statements in session.
30internal SQL statements in session.
8781SQL statements in session.
********************************************************************************
Trace file: e:\work_doc\sdp\unicode_ora_2627.trc
Trace file compatibility: 9.00.01
Sort options: default
1session in tracefile.
8751userSQL statements in trace file.
30internal SQL statements in trace file.
8781SQL statements in trace file.
3232unique SQL statements in trace file.
128622lines in trace file.
其中Misses in library cache during parse: 3701 是不是说明硬分析有这么多？
8781SQL statements in trace file.
3232unique SQL statements in trace file.
这是不是说明8781- 3232=5549的sql是与其他sql相同的？
最后部分也应该能看出绑定等信息吧。
请教大家了。 [/B]
Misses in library cache during parse: 2，这说明有2次硬分析；
parse和execute的值大小接近，说明未使用绑定变量；
最后一部分是汇总信息，Misses in library cache during parse: 3701 说明有3701次硬分析。
更详细的解释请点击这个链接http://dbaoracle.itpub.net/post/901/127799。
或者下载下面这个文档。

千问 · 2007-9-26 18:42:10

最初由 cjf107 发布
[B]
我觉得用了绑定也可能出现parse=execute，都大于1次，这时的parse为软解析：
如我先alter session set events '10046 trace name context forever,level 12';
再用exec :var :=不同的值，手工运行同一个sql16次，在trace文件中只出现一次这个sql，其中如下：
call count cpuelapsed diskquerycurrentrows
------- -------------- ---------- ---------- ---------- --------------------
Parse 160.01 0.01
0
2
0 0
Execute 160.00 0.00
0
0
0 0
Fetch 180.01 0.38472 1058
0
10
------- -------------- ---------- ---------- ---------- --------------------
total 500.03 0.40472 1060
0
10
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id:
这样应该是进行了bind的，而在Misses in library cache during parse: 1
也应该说明了这个问题。 [/B]
此时可以得知这16个sql的运行只在v$sqlarea中产生1行记录。
我该如何使软分析消失呢？