Tkprof是一个用于分析Oracle跟踪文件并且产生一个更加清晰合理的输出结果的可执行工具。如果一个系统的执行效率比较低，一个比较好的方法是通过跟踪用户的会话并且使用Tkprof工具使用排序功能格式化输出，从而找出有问题的SQL语句。
一. TKPROF 命令语法：
TKPROF filename1, filename2 [ SORT = [ opion][,option] ]
[ PRINT = integer ]
[ AGGREGATE = [ YES | NO ] ]
[ INSERT = filename3 ]
[ SYS = [ YES | NO ] ]
[ [ TABLE = schema.table ] | [ EXPLAIN = user/password ] ]
[ RECORD = filename ]
相关说明：
filename1 指定的输入文件，可以是多个文件联起来。
Filename2 格式化输出文件。
SORT 在输出到输出文件前，先进程排序。如果省去，则按照实际使用的顺序输出到文件中。排序选项有以下多种：
prscnt number of times parse was called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor
filename1 指定的输入文件，可以是多个文件联起来。
Filename2 格式化输出文件。
SORT 在输出到输出文件前，先进程排序。如果省去，则按照实际使用的顺序输出到文件中。排序选项有以下多种：
prscnt number of times parse was called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor
PRINT 只列出输出文件的第一个integer 的SQL语句。默认为所有的SQL语句。
AGGREGATE 如果= NO ，则不对多个相同的SQL进行汇总。
INSERT SQL 语句的一种，用于将跟踪文件的统计信息存储到数据库中。在TKPROF创建脚本后，在将结果输入到数据库中。
SYS 禁止或启用 将SYS用户所发布的SQL语句列表到输出文件中。
TABLE 在输出到输出文件前，用于存放临时表的用户名和表名。
EXPLAIN 对每条SQL 语句确定其执行规划。并将执行规划写到输出文件中。
其中比较有用的一个排序选项是fchela，即按照elapsed time fetching来对分析的结果排序（记住要设置初始化参数timed_statistics=true），生成的文件将把最消耗时间的sql放在最前面显示。另外一个有用的参数就是sys，这个参数设置为no可以阻止所有以sys用户执行的sql被显示出来，这样可以减少分析出来的文件的复杂度，便于查看。
二. 对Tkprof命令输出的解释：
首先解释输出文件中列的含义：
CALL：每次SQL语句的处理都分成三个部分
Parse：这步将SQL语句转换成执行计划，包括检查是否有正确的授权和所需要用到的表、列以及其他引用到的对象是否存在。
Execute：这步是真正的由Oracle来执行语句。对于insert、update、delete操作，这步会修改数据，对于select操作，这步就只是确定选择的记录。
Fetch：返回查询语句中所获得的记录，这步只有select语句会被执行。
COUNT:这个语句被parse、execute、fetch的次数。
CPU：这个语句对于所有的parse、execute、fetch所消耗的cpu的时间，以秒为单位。
ELAPSED：这个语句所有消耗在parse、execute、fetch的总的时间。
DISK：从磁盘上的数据文件中物理读取的块的数量。一般来说更想知道的是正在从缓存中读取的数据而不是从磁盘上读取的数据。
QUERY：在一致性读模式下，所有parse、execute、fetch所获得的buffer的数量。一致性模式的buffer是用于给一个长时间运行的事务提供一个一致性读的快照，缓存实际上在头部存储了状态。
CURRENT：在current模式下所获得的buffer的数量。一般在current模式下执行insert、update、delete操作都会获取buffer。在current模式下如果在高速缓存区发现有新的缓存足够给当前的事务使用，则这些buffer都会被读入了缓存区中。
ROWS: 所有SQL语句返回的记录数目，但是不包括子查询中返回的记录数目。对于select语句，返回记录是在fetch这步，对于insert、update、delete操作，返回记录则是在execute这步。
三. Tkprof的使用步骤基本上遵循以下几步：
1、设置TIMED_STATISTICS为True，可以在会话级别，也可以在实例级别。
会话级：
SQL> alter session set timed_statistics=True;
实例级：
SQL> alter system set timed_statistics=True scope=both;
2、 设置SQL_TRACE，可以在会话级，也可以在数据库级。
会话级：
alter session set sql_trace=true;
alter session set sql_trace=false;
exec SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION=（ SID ， SERIAL# ， TRUE ）；
alter session set sql_trace=true;
alter session set sql_trace=false;
exec SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION=（ SID ， SERIAL# ， TRUE ）；
exec dbms_monitor.session_trace_enable(session_id =>SID,
serial_num => SERIAL#,
waits => TRUE,
binds => TRUE)
serial_num => SERIAL#,
waits => TRUE,
binds => TRUE)
※SID，SERIAL#可以从V$SESSION视图获得。select username,sid,serial# from v$session where username='SYS';
ALTER SESSION SET EVENTS
alter session set events '10046 trace name context forever,level<n>';
alter session set events '10046 trace name context off';
n=1---------激活标准SQL_TRACE工具，这与设置SQL_TRACE=TRUE 没有任何不同；
n=4---------激活标准SQL_TRACE，且可以扑获跟踪文件中的绑定变量。
n=8---------激活标准SQL_TRACE,且可在查询级上扑获跟踪文件中的等待事件。
n=12--------激活标准SQL_TRACE,并包括扑获绑定变量与等待事件。
实例级：
alter system set sql_trace=true;
alter system set sql_trace=false;
ALTER SESSION SET EVENTS
alter session set events '10046 trace name context forever,level<n>';
alter session set events '10046 trace name context off';
n=1---------激活标准SQL_TRACE工具，这与设置SQL_TRACE=TRUE 没有任何不同；
n=4---------激活标准SQL_TRACE，且可以扑获跟踪文件中的绑定变量。
n=8---------激活标准SQL_TRACE,且可在查询级上扑获跟踪文件中的等待事件。
n=12--------激活标准SQL_TRACE,并包括扑获绑定变量与等待事件。
实例级：
alter system set sql_trace=true;
alter system set sql_trace=false;
exec dbms_monitor.database_trace_enable(waits => TRUE,
binds => TRUE,
instance_name => NULL)
binds => TRUE,
instance_name => NULL)
exec dbms_monitor.database_trace_disable(instance_name => NULL)
四．举例说明：
--启用SQL_TRACE
SQL> alter session set sql_trace=true;
会话已更改。
SQL> select count(*) from bigtab;
--启用SQL_TRACE
SQL> alter session set sql_trace=true;
会话已更改。
SQL> select count(*) from bigtab;
COUNT(*)
----------
1922423
--启用timed_statistics
SQL> alter session set timed_statistics=true;
--启用timed_statistics
SQL> alter session set timed_statistics=true;
会话已更改。
SQL> select count(*) from bigtab;
COUNT(*)
----------
1922423
SQL> alter session set sql_trace =false;
会话已更改。
--查询此会话产生的TRACE文件
SQL>select * from v$diag_info;
INST_ID NAME VALUE
1 Diag Enabled TRUE
1 ADR Base /u01/app/oracle
1 ADR Home /u01/app/oracle/diag/rdbms/orcl/orcl
1 Diag Trace /u01/app/oracle/diag/rdbms/orcl/orcl/trace
1 Diag Alert /u01/app/oracle/diag/rdbms/orcl/orcl/alert
1 Diag Incident /u01/app/oracle/diag/rdbms/orcl/orcl/incident
1 Diag Cdump /u01/app/oracle/diag/rdbms/orcl/orcl/cdump
1 Health Monitor /u01/app/oracle/diag/rdbms/orcl/orcl/hm
1 Default Trace File /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc
1 Active Problem Count 0
1 Active Incident Count 0
--使用tkprof分析trace文件
C:/Users/Administrator.DavidDai>tkprof d:/app/administrator/diag/rdbms/orcl/orcl
/trace/orcl_ora_7240.trc D:/orcl_ora_7240.txt aggregate=yes sys=no waits=yes sor
t=fchela
TKPROF: Release 11.2.0.1.0 - Development on 星期五 5月 28 16:48:49 2010
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
--tkprocf输出了以下文件：D:/orcl_ora_7240.txt
TKPROF: Release 11.2.0.1.0 - Development on 星期五 5月 28 16:48:49 2010
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc
Sort options: fchela
********************************************************************************
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
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 5 0.00 0.00 0 0 0 0
Fetch 4 0.79 7.45 57075 57082 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 13 0.79 7.45 57075 57082 0 2
Misses in library cache during parse: 3
Misses in library cache during execute: 1
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
5 user SQL statements in session.
0 internal SQL statements in session.
5 SQL statements in session.
********************************************************************************
Trace file: d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc
Trace file compatibility: 11.1.0.7
Sort options: fchela
1 session in tracefile.
5 user SQL statements in trace file.
0 internal SQL statements in trace file.
5 SQL statements in trace file.
5 unique SQL statements in trace file.
73 lines in trace file.
75 elapsed seconds in trace file.
问题判断：
1. query+current/rows 平均每行所需的block数，太大的话（超过20）SQL语句效率太低
2. parse count应尽量接近1，如果太高的话，SQL会进行不必要的reparse。
要检查Pro*C程序的MAXOPENCURSORS是不是太低了，或不适当的使用的RELEASE_CURSOR选项
3. rows Fetch/Fetch Fetch Array的大小，太小的话就没有充分利用批量Fetch的功能，
增加了数据在客户端和服务器之间的往返次数。在Pro*C中可以用prefetch=NN,Java/JDBC中可调用SETROWPREFETCH,在PL/SQL中可以用BULK COLLECT,SQLPLUS中的arraysize(缺省是15)
4. disk/query+current 磁盘IO所占逻辑IO的比例，太大的话有可能是db_buffer_size过小(也跟SQL的具体特性有关)
5. elapsed/cpu 太大表示执行过程中花费了大量的时间等待某种资源
6. cpu/elapsed 太大表示执行时间过长，或消耗了大量的CPU时间，应该考虑优化
7. 执行计划中的Rows 表示在该处理阶段所访问的行数，要尽量减少
问题判断：
1. query+current/rows 平均每行所需的block数，太大的话（超过20）SQL语句效率太低
2. parse count应尽量接近1，如果太高的话，SQL会进行不必要的reparse。
要检查Pro*C程序的MAXOPENCURSORS是不是太低了，或不适当的使用的RELEASE_CURSOR选项
3. rows Fetch/Fetch Fetch Array的大小，太小的话就没有充分利用批量Fetch的功能，
增加了数据在客户端和服务器之间的往返次数。在Pro*C中可以用prefetch=NN,Java/JDBC中可调用SETROWPREFETCH,在PL/SQL中可以用BULK COLLECT,SQLPLUS中的arraysize(缺省是15)
4. disk/query+current 磁盘IO所占逻辑IO的比例，太大的话有可能是db_buffer_size过小(也跟SQL的具体特性有关)
5. elapsed/cpu 太大表示执行过程中花费了大量的时间等待某种资源
6. cpu/elapsed 太大表示执行时间过长，或消耗了大量的CPU时间，应该考虑优化
7. 执行计划中的Rows 表示在该处理阶段所访问的行数，要尽量减少
五. 分析会话的示例：
先从os上利用top命令找到当前占用cpu资源最高的一个进程的PID号：14483
然后在数据库中根据PID号找到相应的sid号和serial#：
SQL> select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and p.spid='14483';
SID SERIAL#
---------- ----------
101 25695
使用dbms_system.set_sql_trace_in_session包来对这个session进行trace：
SQL> exec DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(101,25695,true);
PL/SQL procedure successfully completed.
到user_dump_dest定义的路径下查找刚刚最近生成的trace文件，可以根据时间来排序，找最近的trace文件，也可以根据SID_ORA_SPID.TRC的规则，即ORCL_ORA_14483.TRC找到TRACE文件。
接着使用tkprof工具对此trace文件进行格式化分析，生成分析后的trace文件。
$tkprof orcl_ora_14483.trc allan.txt explain=system/manager aggregate=yes sys=no waits=yes sort=fchela
$tkprof orcl_ora_14483.trc allan.txt explain=system/manager aggregate=yes sys=no waits=yes sort=fchela
TKPROF: Release 11.2.0.1.0 - Development on 星期五 5月 28 16:48:49 2010
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
这里生成的allan.txt文件就是我们最终得到的格式化后的trace文件了，然后打开这个文件进行分析。
最后总的统计：
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- --------
Parse 20 0.01 0.02 0 58 0 0
Execute 13197 0.81 0.90 17 7436 6316 1484
Fetch 12944 22.86 22.10 20 2205941 0 8972
------- ------ -------- ---------- ---------- ---------- ---------- --------
total 26161 23.68 23.02 37 2213435 6316 10456
没有评论:
发表评论