10046事件
Oracle的10046事件，可以跟踪应用程序所执行的SQL语句，并且得到其解析次数.执行次数,CPU使用时间等信息。这对我们分析、定位数据库性能问题是非常有用的。
10046 event是oracle用于系统性能分析时的一个最重要的事件。当激活这个事件后，将通知oracle kernel追踪会话的相关即时信息，并写入到相应trace文件中。
这些有用的信息主要包括sql是如何进行解析，绑定变量的使用情况，会话中发生的等待事件等
10046 event 可分成不同的级别（level），分别追踪记录不同程度的有用信息。对于这些不同的级别，应当注意的是向下兼容的，即高一级的trace信息包含低于此级的所有信息。
10046event的追踪级别大致有：
level 1：跟踪sql语句，包括解析、执行、提取、提交和回滚等。
level 4：包括变量的详细信息
level 8：包括等待事件
level 12：包括绑定变量与等待事件
其中，level 1相当于打开了sql_trace
在打开10046时间的SQL Trace之前，要先设置好下面几个参数。
timed_statistics
这个参数决定了是否收集与时间相关的统计信息，如果这个参数为FALSE的话，那么SQL Trace的结果基本没有多大的用处，默认情况下这个参数设置为TRUE。
max_dump_file_size
dump文件的大小，也就是决定是否限制SQL Trace文件的大小，在一个很忙的系统上面做SQL Trace的话可能会生成很多的信息，因此最好在会话级别将这个参数设置成unlimited。
tracefile_identifier
给Trace文件设置识别字符串，这是个非常有用的参数，设置一个易读的字串能更快的找到Trace文件。
要在当前会话修改上述参数很简单，只要使用下面的命令即可：
ALTER SESSION SET timed_statistics=true
ALTER SESSION SET max_dump_file_size=unlimited
ALTER SESSION SET tracefile_identifier='my_trace_session'
实验：设置10046事件
alter session set events '10046 trace name context forever ,level 12';
select *
from (select deptno,
ename,
sal,
row_number() over(partition by deptno order by sal desc) rn
from emp)
where rn <= 2;
alter session set events '10046 trace name context off';
当前会话查看生成的trace 文件
select value from v$diag_info where name='Default Trace File';
使用工具格式化trace文件
[oracle@rac1 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
格式化之后的trace
TKPROF: Release 11.2.0.4.0 - Development on Fri Aug 25 15:51:18 2017
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: PROD1_ora_32508.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
select *
from (select deptno,
ename,
sal,
row_number() over(partition by deptno order by sal desc) rn
from emp)
where rn <= 2
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 6 0 6
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 6 0 6
Misses in library cache during parse: 1----
硬解析
Optimizer mode: ALL_ROWS
Parsing user id: 83
Number of plan statistics captured: 1
--
-访问路径
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
6 6 6 VIEW (cr=6 pr=0 pw=0 time=293 us cost=4 size=644 card=14)
10 10 10 WINDOW SORT PUSHED RANK (cr=6 pr=0 pw=0 time=290 us cost=4 size=182 card=14)
14 14 14 TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=238 us cost=3 size=182 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 7.60 7.60
********************************************************************************
SQL ID: 5dt9w7dmjqp7a Plan Hash: 0----c
此处有SQL_ID
alter session set events '10046 trace name context off'
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
Misses in library cache during parse: 0
Parsing user id: 83
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS-----
#非递归SQL语句
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 6 0 6
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 6 0 6
Misses in library cache during parse: 1---
一次硬解析
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 16.10 23.71
裸trace文件
PARSING IN CURSOR 部分：
Len: 被解析SQL的长度
Dep: 产生递归SQL的深度
Uid：user id
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 misss in cache 硬分析次数
R: -rows 处理的行数
Dep: depth 递归SQL的深度
Og： optimizer goal 优化器模式
Tim：timestamp时间戳
STATS 部分：
Id: 执行计划的行源号
Cnt：当前行源返回的行数
Pid：当前行源号的父号
Pos：执行计划中的位置
Obj：当前操作的对象id（如果当前行原始一个对象的话）
Op：当前行源的数据访问操作
Trace file /u01/app/oracle/diag/rdbms/prod/PROD1/trace/PROD1_ora_32508.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/11.2.0
System name: Linux
Node name: rac1
Release: 2.6.32-431.el6.x86_64
Version: #1 SMP Sun Nov 10 22:19:54 EST 2013
Machine: x86_64
VM name: VMWare Version: 6
Instance name: PROD1
Redo thread mounted by this instance: 1
Oracle process number: 50
Unix process pid: 32508, image: oracle@rac1 (TNS V1-V3)
*** 2017-08-25 15:40:37.519
*** SESSION ID:(42.691) 2017-08-25 15:40:37.519
*** CLIENT ID:() 2017-08-25 15:40:37.519
*** SERVICE NAME:(SYS$USERS) 2017-08-25 15:40:37.519
*** MODULE NAME:(SQL*Plus) 2017-08-25 15:40:37.519
*** ACTION NAME:() 2017-08-25 15:40:37.519
WAIT #139754621488360: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646837519024
*** 2017-08-25 15:40:53.628
WAIT #139754621488360: nam='SQL*Net message from client' ela= 16109440 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853628880
CLOSE #139754621488360:c=0,e=7,dep=0,type=1,tim=1503646853628983
=====================
PARSING IN CURSOR #139754621554208 len=183 dep=0 uid=83 oct=3 lid=83 tim=1503646853634437 hv=2495311492 ad='8369e2d0' sqlid='gn1w5juabqvn4'
select *
from (select deptno,
ename,
sal,
row_number() over(partition by deptno order by sal desc) rn
from emp)
where rn <= 2
END OF STMT
PARSE #139754621554208:c=2000,e=5415,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3291446077,tim=1503646853634432
EXEC #139754621554208:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3291446077,tim=1503646853634605
WAIT #139754621554208: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853634674
FETCH #139754621554208:c=0,e=289,p=0,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3291446077,tim=1503646853635022
WAIT #139754621554208: nam='SQL*Net message from client' ela= 311 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853635376
WAIT #139754621554208: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853635422
FETCH #139754621554208:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=5,dep=0,og=1,plh=3291446077,tim=1503646853635451
STAT #139754621554208 id=1 cnt=6 pid=0 pos=1 obj=0 op='VIEW (cr=6 pr=0 pw=0 time=293 us cost=4 size=644 card=14)'
STAT #139754621554208 id=2 cnt=10 pid=1 pos=1 obj=0 op='WINDOW SORT PUSHED RANK (cr=6 pr=0 pw=0 time=290 us cost=4 size=182 card=14)'
STAT #139754621554208 id=3 cnt=14 pid=2 pos=1 obj=87108 op='TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=238 us cost=3 size=182 card=14)'
*** 2017-08-25 15:41:01.238
WAIT #139754621554208: nam='SQL*Net message from client' ela= 7601437 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646861238782
CLOSE #139754621554208:c=0,e=12,dep=0,type=0,tim=1503646861238957
=====================
PARSING IN CURSOR #139754621485288 len=56 dep=0 uid=83 oct=42 lid=83 tim=1503646861239192 hv=1729844458 ad='0' sqlid='5dt9w7dmjqp7a'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #139754621485288:c=0,e=151,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1503646861239192
EXEC #139754621485288:c=1000,e=309,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1503646861239561
