做Oracle方面的工作时间长了，经常会听人提起10046事件，尤其是涉及到SQL调优的时候更甚。那10046事件到底是什么呢，先做一个简单的介绍。
1、什么是10046事件
10046事件是Oracle提供的一个用于分析性能的工具，它能帮助我们解析一条/多条SQL、PL/SQL语句的运行状态，这些状态包括 ：Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、CPU时间、执行计划等等。
2、10046事件的Level
不同的Level对应不同的跟踪级别
-
1 启用标准的SQL_TRACE功能(默认)包含了SQL语句、响应时间、服务时间、处理的行数，物理读和写的数目、执行计划以及其他一些额外信息。到版本10.2中执行计划写入到trace的条件是仅当相关游标已经关闭时，且与之相关的执行统计信息是所有执行次数的总和数据。到版本11.1中仅在每次游标的第一次执行后将执行计划写入到trace，执行统计信息仅仅和这第一次执行相关
-
4 比level 1时多出绑定变量的trace
-
8 比level 1多出等待事件，特别对于9i中指出latchfree等待事件很有用，对于分析全表扫描和索引扫描也很有用
-
12 比level 1多出绑定变量和等待事件
11g及以上版本
-
16 在11g中为每一次执行生成STAT信息
-
32 比level 1少执行计划
11.2.0.2及以上版本
-
64 和level 1相比在第一次执行后还可能生成执行计划信息；条件是某个游标在前一次执行的前提下运行耗时变长了一分钟。
3、启用10046事件
1)对本session启用10046事件
a.
alter session set events '10046 trace name context forever,level 12'
b.
oradebug setmypid
oradebug event 10046 trace name context ,level 12
其中能修改的只有level级别
2)对其他session启用10046事件
oradebug setospid|setorapid xxx
oradebug event 10046 trace name context ,level 12
4、停用10046事件
分别对应上面不同的启用方式
alter session set events '10046 trace name context forever off'
oradebug event 10046 trace name context off
或者退出启用10046事件的session
5、获取10046事件生成的trace文件
a.对于11g及以上的版本，使用如下语句可以轻松得到
select value from v$diag_info where name='Default Trace File';
b.对于10g及以前的版本中需要使用如下sql
|
1
2
3
4
5
6
7
8
9
10
11
12
|
SELECT
D.VALUE ||
''
||
LOWER
(RTRIM(I.INSTANCE, CHR(0))) ||
'_ora_'
||
P.SPID ||
'.trc'
TRACE_FILE_NAME
FROM
(
SELECT
P.SPID
FROM
SYS.V$MYSTAT M, SYS.V$SESSION S, SYS.V$PROCESS P
WHERE
M.STATISTIC# = 1
AND
S.SID = M.SID
AND
P.ADDR = S.PADDR) P,
(
SELECT
T.INSTANCE
FROM
SYS.V$THREAD T, SYS.V$PARAMETER V
WHERE
V.
NAME
=
'thread'
AND
(V.VALUE = 0
OR
T.THREAD# = TO_NUMBER(V.VALUE))) I,
(
SELECT
VALUE
FROM
SYS.V$PARAMETER
WHERE
NAME
=
'user_dump_dest'
) D;
|
c.如果使用oradebug命令则使用相对应的oradebug tracefile_name即可得到trace文件
6、格式化trace文件
10046事件所产生的原始trace文件习惯称之为裸trace文件(raw trace)，Oracle记录在裸trace文件中的内容一眼看上去并不是那么观，也不是那么容易看懂。为了祼trace文件能够以一种更直观、更容易懂的方式展现出来，Oracle提供了tkprof命令，这个命令是Oracle自带的，可以用它来翻译祼trace文件。
tkprof的语法如下：
|
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
|
[oracle@rhel6 10046]$ 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
|
7、简单示例，数据库版本11.2.0.4
|
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
85
86
|
zx@ORCL>
alter
session
set
events
'10046 trace name context forever,level 12'
;
Session altered.
zx@ORCL>
select
*
from
scott.emp;
EMPNO ENAME JOB MGR HIREDATE SAL COMM DEPTNO
---------- ------------------------------ --------------------------- ---------- ------------------- ---------- ---------- ----------
7369 SMITH CLERK 7902 1980-12-17 00:00:00 800 20
7499 ALLEN SALESMAN 7698 1981-02-20 00:00:00 1600 300 30
......
14
rows
selected.
zx@ORCL>
alter
session
set
events
'10046 trace name context off'
;
Session altered.
zx@ORCL>
select
value
from
v$diag_info
where
name
=
'Default Trace File'
;
VALUE
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
/u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.trc
zx@ORCL>!
[oracle@rhel6 trace]$ tkprof /u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.trc 10046.trc
TKPROF: Release 11.2.0.4.0 - Development
on
Thu Feb 16 21:38:57 2017
Copyright (c) 1982, 2011, Oracle
and
/
or
its affiliates.
All
rights reserved.
[oracle@rhel6 trace]$ cat 10046.trc
TKPROF: Release 11.2.0.4.0 - Development
on
Thu Feb 16 21:38:57 2017
Copyright (c) 1982, 2011, Oracle
and
/
or
its affiliates.
All
rights reserved.
Trace file: /u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.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 ID: ggqns3c1jz86c Plan Hash: 3956160932
select
*
from
scott.emp
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 0.00 0.00 0 7 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 7 0 14
Misses
in
library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing
user
id: SYS
Number
of
plan
statistics
captured: 1
Rows
(1st)
Rows
(
avg
)
Rows
(
max
) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
14 14 14
TABLE
ACCESS
FULL
EMP (cr=7 pr=0 pw=0
time
=81 us cost=3
size
=532 card=14)
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 0.00 0.00
********************************************************************************
......省略部分内容
|
参考文档：https://blogs.oracle.com/askmaclean/entry/maclean教你读oracle_10046_sql_trace
MOS文档EVENT: 10046 "enable SQL statement tracing (including binds/waits)" (文档 ID 21154.1)
How To Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues (文档 ID 376442.1)
官方文档：http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94981
本文转自hbxztc 51CTO博客，原文链接：http://blog.51cto.com/hbxztc/1898624，如需转载请自行联系原作者
