在数据库生成的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语句是如果执行的
PARSING IN CURSOR 部分：
len：被分析sql的长度
dep：产生递归sql的深度
uid：userid
otc：oracle command type命令的类型
lid：私有的用户id
tim：时间戳
hv：hash value
ad：sql address
PARSE, EXEC, FETCH部分：
c：消耗的cpu time
e：elapsed time操作用时
p：physical reads物理读的次数
cr：consistent reads一致性方式读取的数据块数
cu：current方式读取的数据块数
mis：cursor miss in cache 硬分析的次数
r：rows处理的行数
dep：depth递归sql的深度
og：optimizer goal优化器模式
tim：timestamp 时间戳
STAT部分：
id：执行计划的行源号
cnt：当前行源返回的行数
pid：当前行源号的父号
pos：当前操作的对象id，如果当前行原始一个对象的话
op：当前行源的数据访问操作
笔记