【TKPROF】使用TKPROF格式化TRACE输出之“解剖麻雀”
《【SQL_TRACE】SQL优化及性能诊断好帮手》http://space.itpub.net/519536/viewspace-616240中简单的提到了使用TKPROF工具格式化SQL_TRACE的输出信息的方法,并没有对输出的内容做比较清楚的描述,通过这个小文儿,展示一下TKPROF对trace文件格式化的魅力,这里只给出具体输出信息含义的描述,不展示真实的性能诊断案例。
1.与之上次使用到的SQL_TRACE功能相比,我们这次将使用更高级的trace命令(10046)来做演示。我们先启用“高级”的10046事件生成一份待格式化的trace文件
1)连接到普通用户sec
sys@ora10g> conn sec/sec
Connected.
2)先将timed_statistics参数设置为true,这样可以使TKPROF工具能提供更多的有意义的信息,方便性能诊断
sec@ora10g> alter session set timed_statistics=true;
Session altered.
3)“高级”之所在,我们这里启用10046的level 12对当前会话进行跟踪。
(1)在此,给出10046各level的解释参考:
level 1 to enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE)
等同于标准的SQL_TRACE=TRUE;
level 4 to enable SQL_TRACE and also capture bind variable values in the trace file
启用SQL_TRACE,并捕捉跟踪文件中的绑定变量;
level 8 to enable SQL_TRACE and also capture wait events into the trace file
启用SQL_TRACE,并捕捉跟踪文件中的等待事件;
level 12 to enable standard SQL_TRACE and also capture bind variables and wait events
启用SQL_TRACE,并捕捉跟踪文件中的绑定变量和等待事件(捕获信息能力最强)。
(2)对当前会话启用level 12的跟踪:
sec@ora10g> alter session set events '10046 trace name context forever, level 12';
Session altered.
(3)【补充】如果想使用这种高级方法对其他的会话进行跟踪的话,可以使用如下的SQL语句开启和关闭:
开启:execute dbms_system.set_ev(sid,serial#,10046,12,'');
关闭:execute dbms_system.set_ev(sid,serial#,10046,0,'');
举例如下:
A.获得sid, serial#的信息
sys@ora10g> select sid, serial# from v$session;
B.开启
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,12,'');
C.关闭
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,0,'');
4)在该会话中运行一条具体的SQL语句,此处使用到的实验表t中包含1亿条数据。该SQL语句的执行情况将被细致的记录到trace文件中。
sec@ora10g> select count(*) from t;
COUNT(*)
----------
100000000
5)关闭当前会话的跟踪
sec@ora10g> alter session set events '10046 trace name context off';
Session altered.
2.在udump目录中找到刚刚生成的trace文件(关于如何快速获得生成的trace文件的方法有很多种,选择一个适合自己的就OK),并使用TKPROF对其进行格式化,然后打印一下全部输出,后面将对每一个输出项做一下“解剖麻雀”:)
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_21213.trc ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:04:40 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:05:43 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_21213.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 5.60 7.74
********************************************************************************
select count(*)
from
t
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 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 2
Fetch 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 10.94 10.68 222186 222957 0 3
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 5.60 7.74
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_21213.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
2 unique SQL statements in trace file.
14392 lines in trace file.
16 elapsed seconds in trace file.
3.对上面的TKPROF格式化输出内容重点内容“解剖麻雀”正式开始
1)摘录第一部分,SQL语句的执行情况总览
select count(*)
from
t
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 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
关于统计表格的标题信息中count、cpu、elapsed、disk、query、current和rows的说明在该trace文件的最前端有一个简要的说明,这里再分别赘述一下。
count :查询在此阶段执行的次数;
cpu :该查询在此阶段的CPU时间量,以毫秒为单位;
elapsed :花费在此阶段上的挂钟时间,该值比cpu值大的时候,表明存在等待事件;
disk :执行物理I/O次数;
query :在意一致性检索方式获得块时,执行逻辑I/O次数;
current :逻辑I/O次数;
rows :此阶段,被处理或受影响的行数。
关于第一列的赘述:
Parse :软编译和硬编译次数;
Execute :在open和execute语句中完成的内容;
Fetch :select中会有数据显示,在update语句中不会有数据显示。
2)摘录运行环境信息
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
第一行的“0”表示查询使用的是软解析(soft parse)。
优化模式是:ALL_ROWS
使用最后一行的用户ID可以获得执行时的会话信息。获得用户信息可以通过下面的SQL语句完成。
sys@ora10g> select * from all_users where user_id = 51;
USERNAME USER_ID CREATED
------------------------------ ---------- -------------------
SEC 51 2009-10-15 13:04:03
3)摘录执行计划信息
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
有趣发现:通过第二行可以得到这个t表的数据量,这里显示结果是1亿。
“解剖”上面出现的几个重要参数:
cr=222957 -- 一致性读取
pr=222186 -- 物理读取
pw=0 -- 物理写
time=100000562 us -- 占用时间,单位:微妙 百万分之一秒
4)摘录等待事件
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
通过这段等待事件的描述,可以清楚的得到在执行SQL语句的过程中都出现了哪些引人注目的等待事件。比如上面显示出的“db file scattered read”和“db file sequential read”信息,如果此类信息在生产环境中大量出现,就需要重点深入分析和研究了。
4.小结
整个“解剖麻雀”的过程到此告一段落,相信您对“10046跟踪”和TKPROF格式化有了一个整体上的了解,这里只是通过一个示例来展示一下trace跟踪和TKPROF的强大。更重要的是在生产环境故障诊断过程中的具体问题具体分析。这里不得不提醒一下的是,在生产环境中使用10046 level 12方法对会话进行跟踪时,要充分考虑到它对系统性能的影响,前期测试是必须的步骤。
-- The End --
分享标题:【TKPROF】使用TKPROF格式化TRACE输出之“解剖麻雀”
转载来源:http://pwwzsj.com/article/jdohjg.html
1.与之上次使用到的SQL_TRACE功能相比,我们这次将使用更高级的trace命令(10046)来做演示。我们先启用“高级”的10046事件生成一份待格式化的trace文件
1)连接到普通用户sec
sys@ora10g> conn sec/sec
Connected.
2)先将timed_statistics参数设置为true,这样可以使TKPROF工具能提供更多的有意义的信息,方便性能诊断
sec@ora10g> alter session set timed_statistics=true;
Session altered.
3)“高级”之所在,我们这里启用10046的level 12对当前会话进行跟踪。
(1)在此,给出10046各level的解释参考:
level 1 to enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE)
等同于标准的SQL_TRACE=TRUE;
level 4 to enable SQL_TRACE and also capture bind variable values in the trace file
启用SQL_TRACE,并捕捉跟踪文件中的绑定变量;
level 8 to enable SQL_TRACE and also capture wait events into the trace file
启用SQL_TRACE,并捕捉跟踪文件中的等待事件;
level 12 to enable standard SQL_TRACE and also capture bind variables and wait events
启用SQL_TRACE,并捕捉跟踪文件中的绑定变量和等待事件(捕获信息能力最强)。
(2)对当前会话启用level 12的跟踪:
sec@ora10g> alter session set events '10046 trace name context forever, level 12';
Session altered.
(3)【补充】如果想使用这种高级方法对其他的会话进行跟踪的话,可以使用如下的SQL语句开启和关闭:
开启:execute dbms_system.set_ev(sid,serial#,10046,12,'');
关闭:execute dbms_system.set_ev(sid,serial#,10046,0,'');
举例如下:
A.获得sid, serial#的信息
sys@ora10g> select sid, serial# from v$session;
B.开启
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,12,'');
C.关闭
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,0,'');
4)在该会话中运行一条具体的SQL语句,此处使用到的实验表t中包含1亿条数据。该SQL语句的执行情况将被细致的记录到trace文件中。
sec@ora10g> select count(*) from t;
COUNT(*)
----------
100000000
5)关闭当前会话的跟踪
sec@ora10g> alter session set events '10046 trace name context off';
Session altered.
2.在udump目录中找到刚刚生成的trace文件(关于如何快速获得生成的trace文件的方法有很多种,选择一个适合自己的就OK),并使用TKPROF对其进行格式化,然后打印一下全部输出,后面将对每一个输出项做一下“解剖麻雀”:)
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_21213.trc ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:04:40 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:05:43 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_21213.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 5.60 7.74
********************************************************************************
select count(*)
from
t
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 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 2
Fetch 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 10.94 10.68 222186 222957 0 3
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 5.60 7.74
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_21213.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
2 unique SQL statements in trace file.
14392 lines in trace file.
16 elapsed seconds in trace file.
3.对上面的TKPROF格式化输出内容重点内容“解剖麻雀”正式开始
1)摘录第一部分,SQL语句的执行情况总览
select count(*)
from
t
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 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
关于统计表格的标题信息中count、cpu、elapsed、disk、query、current和rows的说明在该trace文件的最前端有一个简要的说明,这里再分别赘述一下。
count :查询在此阶段执行的次数;
cpu :该查询在此阶段的CPU时间量,以毫秒为单位;
elapsed :花费在此阶段上的挂钟时间,该值比cpu值大的时候,表明存在等待事件;
disk :执行物理I/O次数;
query :在意一致性检索方式获得块时,执行逻辑I/O次数;
current :逻辑I/O次数;
rows :此阶段,被处理或受影响的行数。
关于第一列的赘述:
Parse :软编译和硬编译次数;
Execute :在open和execute语句中完成的内容;
Fetch :select中会有数据显示,在update语句中不会有数据显示。
2)摘录运行环境信息
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
第一行的“0”表示查询使用的是软解析(soft parse)。
优化模式是:ALL_ROWS
使用最后一行的用户ID可以获得执行时的会话信息。获得用户信息可以通过下面的SQL语句完成。
sys@ora10g> select * from all_users where user_id = 51;
USERNAME USER_ID CREATED
------------------------------ ---------- -------------------
SEC 51 2009-10-15 13:04:03
3)摘录执行计划信息
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
有趣发现:通过第二行可以得到这个t表的数据量,这里显示结果是1亿。
“解剖”上面出现的几个重要参数:
cr=222957 -- 一致性读取
pr=222186 -- 物理读取
pw=0 -- 物理写
time=100000562 us -- 占用时间,单位:微妙 百万分之一秒
4)摘录等待事件
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
通过这段等待事件的描述,可以清楚的得到在执行SQL语句的过程中都出现了哪些引人注目的等待事件。比如上面显示出的“db file scattered read”和“db file sequential read”信息,如果此类信息在生产环境中大量出现,就需要重点深入分析和研究了。
4.小结
整个“解剖麻雀”的过程到此告一段落,相信您对“10046跟踪”和TKPROF格式化有了一个整体上的了解,这里只是通过一个示例来展示一下trace跟踪和TKPROF的强大。更重要的是在生产环境故障诊断过程中的具体问题具体分析。这里不得不提醒一下的是,在生产环境中使用10046 level 12方法对会话进行跟踪时,要充分考虑到它对系统性能的影响,前期测试是必须的步骤。
-- The End --
分享标题:【TKPROF】使用TKPROF格式化TRACE输出之“解剖麻雀”
转载来源:http://pwwzsj.com/article/jdohjg.html