|
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。
|
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语句是如果执行的
原文：http://www.cnblogs.com/haoxiaoyu/p/3556814.html