一、10046介绍
最为常用的诊断事件是10046和10053事件。10046事件是Oracle提供的内部事件，是对SQL_TRACE的增强。Oracle的10046事件，可以跟踪应用程序所执行的SQL语句，并且得到其解析次数、执行次数、CPU使用时间等信息。这对DBA来分析、定位数据库性能问题是非常有用的。
10046事件可分成不同的级别（LEVEL），分别追踪记录不同程度的有用信息。对于这些不同的级别，应当注意的是向下兼容的，即高一级的TRACE信息包含低于此级的所有信息。
10046事件可以设置以下级别:
- level 0：禁用SQL_TRACE，等价于SQL_TRACE=FALSE
- level 1：启用标准的SQL_TRACE功能跟踪SQL语句，包括解析、执行、提取、提交、回滚、响应时间、服务时间、处理的行数，物理读和写的数目、执行计划以及其它一些额外信息，等价于SQL_TRACE=TRUE
- level 4：Level 1 + 包括绑定变量（Bind Values）的详细信息
- level 8：Level 1 + 包括等待事件
- level 12：包括绑定变量与等待事件，包含Level 1 + Level 4 + Level 8
获取10046 trace 示例
从11gR1开始，Oracle引入了新的诊断结构，以参数DIAGNOSTIC_DEST控制存放trace文件与core文件的路径。可以用以下命令，获取DIAGNOSTIC_DEST的位置：
SQL> show parameter diagnostic_dest;
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
diagnostic_dest string /u01/app/oracle
一般默认路径就是跟告警日志目录一直，文件名称默认为sid_ora_spid.trc，下面可以查看当前会话的trace目录
SQL> select value from v$diag_info where name like 'Default%';
VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_14611.trc
也可以指定特别的trace文件名称
SQL> alter session set tracefile_identifier='10046';
Session altered.
SQL> select value from v$diag_info where name like 'Default%';
VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_14611_10046.trc
开启10046 trace
SQL> alter session set events '10046 trace name context forever,level 12';
执行SQL
SQL> select * from scott.emp where empno=7788;
EMPNO ENAME JOB MGR HIREDATE SAL COMM
---------- ---------- --------- ---------- --------- ---------- ----------
DEPTNO
----------
7788 SCOTT ANALYST 7566 19-APR-87 3000
20
关闭10046 trace
SQL> alter system set events '10046 trace name context off';
查看10046 trace 文件
more /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_14611_10046.trc
使用tkprof格式化10046 trace 文件
tkprof /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_14611_10046.trc 10046sql.txt
查看格式化后输出
[oracle@test ~]$ more 10046sql.txt
TKPROF: Release 12.2.0.1.0 - Development on Fri May 2 18:59:44 2025
Copyright (c) 1982, 2017, Oracle and/or its affiliates. All rights reserved.
Trace file: /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_14611_10046.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: 9nrttza3c2x2u Plan Hash: 2949544139
select *
from
scott.emp where empno=7788
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 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 2 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY INDEX ROWID EMP (cr=2 pr=0 pw=0 time=69 us starts=1 cost=1 size=87 card=1)
1 1 1 INDEX UNIQUE SCAN PK_EMP (cr=1 pr=0 pw=0 time=35 us starts=1 cost=1 size=0 card=1)(object id 73543)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 66.39 66.39
********************************************************************************
SQL ID: 4c3xypdrqwgdc Plan Hash: 0
alter system 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: SYS
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 32.87 32.87
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
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 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 2 0 1
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 2 0.00 0.00
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 66.39 99.27
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_14611_10046.trc
Trace file compatibility: 12.2.0.0
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 unique SQL statements in trace file.
54 lines in trace file.
66 elapsed seconds in trace file.
关键指标说明
行解释
- 解析（Parse）：此阶段是Oracle的优化器为SQL语句生成执行计划的阶段。
- 执行（Execute）：此阶段是服务器进程按照执行计划执行语句的阶段。
- 抓取（Fetch）：此阶段是服务器进程从表中抓取结果的阶段。只有 Select 语句才须要此阶段，Update、Insert、Delete等这些DML语句并不须要抓取行。
列解释
- Call：说明了语句执行的每一个阶段。
- Count：此阶段的执行次数。
- CPU：完成此阶段工做所耗的 CPU时间，单位是毫秒。
- Elapsed：完成此阶段工做所耗费的 CPU时间再加上等待的时间，单位也是毫秒。
- Disk：完成此阶段工做所用的物理读次数。
- Query：完成此阶段工做所用的一致读次数。
- Current：完成此阶段工做所用的当前读次数。Query 和 Current加起来就是逻辑读。
- Rows：完成此阶段工做所操做的行数。
接下来一行：
“Misses in library cache during parse:”说明硬解析的次数，本例中语句的执行进行了1次硬解析。
“Optimizer mode”是优化器模式
另外，在目标文件中还会发现大量的其余语句，注意，咱们在跟踪其间，只执行了一条SQL语句，跟踪文件中其余的语句，其实就是所谓的递归调用。也就是为了完成的语句，Oracle内部执行的一些其余的 SQL语句。经过观察跟踪文件的目标文件，能够观察到比较精确的 CPU时间、物理读逻辑读等信息，这有助于咱们了解一条 SQL语句是否有效。
二、10053 介绍
10053事件是最常用的Oracle优化器跟踪Trace。10053事件解析优化器为什么选择某个执行计划但并不记录这个执行计划到底运行地如何。10046事件并不解释优化器的工作，但它记录了在SQL解析阶段所遇到的等待事件和所消耗的CPU等资源，以及执行阶段的各项指标。
Level 2：2级是1级的一个子集，它包含以下内容：
- Column statistics
- Single Access Paths
- Join Costs
- Table Joins Considered
- Join Methods Considered (NL/MS/HA)
Level 1：1级比2级更详细，它包含2级的所有内容，额外增加如下内容：
- Parameters used by the optimizer
- Index statistics
实时SQL获取10053
SQL> alter session set tracefile_identifier='10053';
Session altered.
SQL> select value from v$diag_info where name like 'Default%';
VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_16005_10053.trc
SQL> ALTER SESSION SET EVENTS='10053 trace name context forever, level 1';
Session altered.
SQL> select * from scott.emp where mgr=7698;
EMPNO ENAME JOB MGR HIREDATE SAL COMM DEPTNO
---------- ---------- --------- ---------- --------- ---------- ---------- ----------
7499 ALLEN SALESMAN 7698 20-FEB-81 1600 300 30
7521 WARD SALESMAN 7698 22-FEB-81 1250 500 30
7654 MARTIN SALESMAN 7698 28-SEP-81 1250 1400 30
7844 TURNER SALESMAN 7698 08-SEP-81 1500 0 30
7900 JAMES CLERK 7698 03-DEC-81 950 30
SQL> ALTER SESSION SET EVENTS '10053 trace name context off';
Session altered.
more /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_16005_10053.trc
需要注意的是，这里面的SQL必须是首次执行，即在Shared_pool中没有缓存，否则不会有trace内容
获取历史SQL的10053
如果SQL已经被解析过，通过上述的方法是得不到该SQL的10053 trace 的可以通过DBMS包获取历史SQL的10053 trace
SQL> execute DBMS_SQLDIAG.DUMP_TRACE(p_sql_id=>'5jnxkcqutz8h2', p_child_number=>0, p_component=>'Optimizer', p_file_id=>'hist_10053');
PL/SQL procedure successfully completed.
SQL> SELECT value FROM v$diag_info WHERE name='Default Trace File';
VALUE
------------------------------------------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_16005_hist_10053.trc
查看trace文件
more /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_16005_hist_10053.trc
10053的trace 文件特别丰富，里面详解记录了一个SQL的解析过程，里面会列出各种表访问方式、表连接方式的代价，可以使我们进入CBO优化器内部，去了解CBO是如何工作的，按照什么样的依据给出的执行计划。也能够通过trace文件看出CBO使用的统计信息数据是否正确，如果信息不准确造成的问题，可以重新分析问题数据库对象，使CBO做出正确的执行计划。对深入了解CBO的工作原理有很大的帮助。
三、10046和10053对比
- 10046事件记录SQL如何运行，而10053记录优化器为什么为这个SQL选择某个执行计划。
- 如果一个SQL语句已经被解析过，那么就不会生成10053的trace文件，但10046的trace文件可以重复生成。
扫一扫
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
