在数据库生成的oracle trace文件中，可读性是比较差的，此时可使用tkprof工具来格式化trace文件，tkprof是一个命令行工具，作用就是把原始的跟踪trace文件作为输入，然后格式化一个可读性比较好的文本文件。
在下面的例子中，输入文件是 ora11g_ora_3918.trc，输出文件是test.log
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 | oracle@root:~/diag/rdbms/orcl/ora11g/trace> tkprof ora11g_ora_3918.trc test.log
TKPROF: Release 11.2.0.1.0 - Development on Sat Jun 22 11:38:40 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
下面我们来了解一下tkprof的参数，直接敲tkprof命令即可查看参数： oracle@root:~/diag/rdbms/orcl/ora11g/trace> tkprof Usage: tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ] table=schema.tablename Use 'schema.tablename' with 'explain=' option. explain=user/password Connect to ORACLE and issue EXPLAIN PLAN. print=integer List only the first 'integer' SQL statements. aggregate=yes|no insert=filename List SQL statements and data inside INSERT statements. sys=no TKPROF does not list SQL statements run as user SYS. record=filename Record non-recursive statements found in the trace file. waits=yes|no Record summary for any wait events found in the trace file. sort=option Set of zero or more of the following sort options: 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 |
explain：参数格式为explain=username/password@server_name 或者explain=username/password，这个参数是通过执行explain plan语句来做到的，在trace文件中找到每个sql语句，提供一个执行计划。一般不是必要情况，指定这个参数并不可取，一旦指定了无效的信息，在输出的文件就会出现error。
table：table参数只和explain参数一起使用，用来指定某个表被explain plan语句使用来生成执行计划，通常尽量避免使用table参数，这里就不详细说明不常用的参数了，大家想要了解的话，可以查看oracle的官方联机文档。
print：参数用来限制输出文件生成的sql语句的数量，默认是无限制的。eg：只输出10个sql语句，则参数指定print=10，一般和sort参数一起使用才具有一定的意义。
insert：生成sql脚本，脚本可以用来把数据存储到数据库中。eg：insert=load_data.sql 。
sys：参数执行sys用户下运行的sql语句是否写入到输出文件，默认为yes。可设置为no，避免输出不必要的信息，这个看情况而定吧。
sort：排序的意思，指定输出文件里面的sql语句的顺序，默认是trace源文件里面的sql顺序。你可以指定根据cpu时间，物理读的块数，调用次数等进行排序，eg：sort=elapsed,disk —多个排序用逗号隔开。
aggregate：参数指定是否合并相同的sql，默认为yes，设置为no，输出文件就会列出每个sql的消耗情况等信息。
用得比较多的一般是sys和aggregate参数。
下面我们来简单分析一下经过tkprof工具格式化处理过的trace文件：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 | oracle@root:~/diag/rdbms/orcl/ora11g/trace> more mount_open.log --头部内容，这里可以看到trace源文件，sort参数等信息 TKPROF: Release 11.2.0.1.0 - Development on Fri Jun 21 14:00:51 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: /opt/oracle/diag/rdbms/orcl/ora11g/trace/ora11g_ora_14009.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 ********************************************************************************
头部内容下面的部分就是针对每个sql的信息：sql文本，统计信息，解析信息，执行计划，等待事件等。 ********************************************************************************
SQL ID: 0cmnx32jn5wsp Plan Hash: 1876228229 CREATE INDEX I_OBJ# ON CLUSTER C_OBJ# PCTFREE 10 INITRANS 2 MAXTRANS 255 STORAGE ( INITIAL 64K NEXT 1024K MINEXTENTS 1 MAXEXTENTS 2147483645 PCTINCREASE 0 OBJNO 3 EXTENTS (FILE 1 BLOCK 168))
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 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 0.00 0.00 0 0 0 0
count：执行的数据库调用数量，也就是当前操作执行的次数 cpu：处理数据花费的cpu时间，单位是秒 elapsed：当前操作花费的总用时，包括cpu时间和等待时间，单位是秒 disk：物理读的数据库数量 query：当前操作的一致性模式读取的数据块数，通常是查询 current：当前操作读取的数据块数，通常是修改数据，比如insert ，update，delete等语句所使用的。 rows：当前操作处理的数据行数
Misses in library cache during parse: 1------表示shared pool没有命中，这是一次硬分析，软分析这里为0 Optimizer mode: CHOOSE -----当前的优化模式 Parsing user id: SYS (recursive depth: 1) ---当前处理的对象
Rows Row Source Operation ------- --------------------------------------------------- 0 INDEX BUILD UNIQUE I_OBJ# (cr=0 pr=0 pw=0 time=0 us)(object id 0) 0 SORT CREATE INDEX (cr=0 pr=0 pw=0 time=0 us cost=0 size=0 card=0) 0 TABLE ACCESS FULL C_OBJ# (cr=0 pr=0 pw=0 time=0 us)
rows：表示当前操作返回的数据条数 Row Source Operation：行源操作，表示当前数据的访问方式 cr：一致性方式读取的数据块数，相当于query列上的fetch步骤的值 pr：物理读的数据块，相当于disk列上的fetch步骤的值 pw：物理写入磁盘的数据块数 time：以微秒表示的总的消逝时间 cost：操作的评估开销 size：操作返回的预估数据量，单位是字节 card：操作返回的语句行数
注意：这些值除了card之外，都是累计的。 ********************************************************************************
此外trace文件有很多内容值得探索，这里基础就不体现了。
下面来看一下原始sql_trace生成的原始trace文件，没有经过tkprof处理 PARSING IN CURSOR #4 len=35 dep=0 uid=85 oct=3 lid=85 tim=1371272962082555 hv=4042069092 ad='7e2769c0' sqlid='6xxmr xrsfu534' select * from t where object_id=345 END OF STMT PARSE #4:c=0,e=2120,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3745387144,tim=1371272962082553 EXEC #4:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3745387144,tim=1371272962082705 FETCH #4:c=0,e=5486,p=5,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3745387144,tim=1371272962088298 FETCH #4:c=0,e=30,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,plh=3745387144,tim=1371272962094265 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=73517 op='TABLE ACCESS BY INDEX ROWID T (cr=4 pr=5 pw=0 time=0 us cost=2 size=29 card=1)' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=73518 op='INDEX RANGE SCAN BIN$3x4G/ATIcRfgQKjAgpEWgw==$0 (cr=3 pr=5 pw=0 time=0 us cost=1 size=0 card=1)' *** 2013-06-15 01:09:36.832 CLOSE #4:c=0,e=40,dep=0,type=0,tim=1371272976832430 |
oracle会首先对这条sql语句作分析，并且有一个游标号：CURSOR #4，这个号在整个trace文件中不是唯一的，当一条sql语句执行结束后，这个号被重用
我们还可以看到这条sql语句被分析了一次，执行了一次，fetch了2次，STAT#4是对这条sql语句执行过程中的资源消耗统计，trace文件中信息的输出顺序就是sql语句执行的顺序，通过这些顺序，就可以知道sql语句是如果执行的
