Eygle大师的微信讲堂昨天开课，第一堂课和大家分享了一些学习Oracle的基本方法，其中提到了使用SQL_TRACE和10046事件。SQL_TRACE是Oracle提供的用于进行SQL跟踪的手段，是强有力的辅助诊断工具。在日常的数据库问题诊断和解决中，SQL_TRACE是非常常用的方法。
对于这个工具，我很早就听过，但是从来就没用过，“纸上得来终觉浅，绝知此事要躬行”，操练起来。
1.环境准备
我们在Oracle11g中进行测试。
-
SQL>
-
SQL> select * from v$version;
-
-
BANNER
-
--------------------------------------------------------------------------------
-
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
-
PL/SQL Release 11.2.0.3.0 - Production
-
CORE 11.2.0.3.0 Production
-
TNS for Linux: Version 11.2.0.3.0 - Production
-
NLSRTL Version 11.2.0.3.0 - Production
-
-
SQL>
2.启用SQL_TRACE
在Oracle中初始化设置中SQL_TRACE默认是关闭的，它可以作为初始化参数在全局启用，也可以通过命令行方式在具体session启用。
1．
在全局启用
在参数文件(pfile/spfile)中指定:
SQL_TRACE =true
在全局启用SQL_TRACE会导致所有进程的活动被跟踪，包括后台进程及所有用户进程，这通常会导致比较严重的性能问题，所以在生产环境中要谨慎使用，这个参数在10g之后是动态参数，可以随时调整，在某些诊断中非常有效。
提示: 通过在全局启用SQL_TRACE，我们可以跟踪到所有后台进程的活动，很多在文档中的抽象说明，通过跟踪文件的实时变化，我们可以清晰的看到各个进程之间的紧密协调。
2． 在当前session级设置
大多数时候我们使用SQL_TRACE跟踪当前进程.通过跟踪当前进程可以发现当前操作的后台数据库递归活动(这在研究数据库新特性时尤其有效)，研究SQL执行，发现后台错误等。
我在测试中启用session级别的SQL_TRACE，如下所示。
-
SQL>
-
SQL> show parameter SQL_TRACE
-
-
NAME TYPE VALUE
-
------------------------------------ ----------- ------------------------------
-
SQL_TRACE boolean FALSE
-
SQL>
-
SQL> alter session set SQL_TRACE=true;
-
-
Session altered.
-
-
SQL>
-
SQL> show parameter SQL_TRACE
-
-
NAME TYPE VALUE
-
------------------------------------ ----------- ------------------------------
-
SQL_TRACE boolean TRUE
-
SQL>
3.连接soctt用户，执行查询语句
登陆scott用户，执行两条简单的查询语句。
-
[oracle@hoegh admin]$ sqlplus scott/tiger
-
-
SQL*Plus: Release 11.2.0.3.0 Production on Wed May 27 09:59:48 2015
-
-
Copyright (c) 1982, 2011, Oracle. All rights reserved.
-
-
-
Connected to:
-
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
-
With the Partitioning, OLAP, Data Mining and Real Application Testing options
-
-
SQL> select * from cat;
-
-
TABLE_NAME TABLE_TYPE
-
------------------------------ -----------
-
BONUS TABLE
-
DEPT TABLE
-
EMP TABLE
-
SALGRADE TABLE
-
-
SQL> select * from dept;
-
-
DEPTNO DNAME LOC
-
---------- -------------- -------------
-
10 ACCOUNTING NEW YORK
-
20 RESEARCH DALLAS
-
30 SALES CHICAGO
-
40 OPERATIONS BOSTON
4.生成trace文件
plustrace角色
和Oracle10g一样，11g中plustrace角色默认也是disabled的。如果使用非授权用户打开Oracle trace功能会得到以下的错误。
-
SQL>
-
SQL> show user
-
USER is \"SCOTT\"
-
SQL>
-
SQL> set autotrace on
-
SP2-0618: Cannot find the Session Identifier. Check PLUSTRACE role is enabled
-
SP2-0611: Error enabling STATISTICS report
-
SQL>
这时需要执行$ORACLE_HOME/sqlplus/admin/plustrce.sql脚本，手工创建plustrace角色，在此不做演示。因为我们更多的时候是需要跟踪其他用户的进程，而很多这样的用户可能没有被授予或者不允许授予plustrace角色。这时可以使用DBMS_SYSTEM包来实现对进程的跟踪，这儿需要提供用户进程的sid和serial#。
10046事件
在这儿就不得不提到10046事件，10046事件是Oracle提供的内部事件，是对SQL_TRACE的增强。
10046事件可以设置以下四个级别：
1 - 启用标准的SQL_TRACE功能,等价于SQL_TRACE
4 - Level 1 加上绑定值(bind values)
8 - Level 1 + 等待事件跟踪
12 - Level 1 + Level 4 + Level 8
和SQL_TRACE类似，10046事件可以在全局设置，也可以在session级设置。
生成trace文件
首先，我们通过查询v$session视图获取scott用户进程的sid和serial#；
然后执行dbms_system.set_ev过程来实现对进程的跟踪。
-
SQL>
-
SQL> select sid,serial#,username from v$session where username=\‘SCOTT\‘;
-
-
SID SERIAL# USERNAME
-
---------- ---------- ------------------------------
-
21 2615 SCOTT
-
-
SQL>
-
SQL> exec dbms_system.set_ev(21,2615,10046,12,\‘SCOTT\‘);
-
-
PL/SQL procedure successfully completed.
-
-
SQL>
5.查看trace文件
存放目录
在11g中trace文件的存放目录有了变化，其中，11gR1 或 11gR1 以上版本可以通过查询diagnostic_dest参数获得；而11gR1以前版本则是通过user_dump_dest参数来指定。
-
SQL> show parameter diagnostic_dest
-
-
NAME TYPE VALUE
-
------------------------------------ ----------- ------------------------------
-
diagnostic_dest string /u01/app/oracle
-
SQL>
在测试数据库中，trace文件的具体路径为：/u01/app/oracle/diag/rdbms/hoegh/HOEGH/trace/。
查看trace文件
tracefile 命名规则 ：<ORACLE_SID>_ora_<pid>.trc，其中pid为相应session所对应的OS PID。根据生成时间在/u01/app/oracle/diag/rdbms/hoegh/HOEGH/trace目录下找到了trace文件HOEGH_ora_16427.trc。我们通过more命令查看文件内容，由于内容较多，只截取了开始部分内容如下。
-
[oracle@hoegh trace]$ more HOEGH_ora_16427.trc
-
Trace file /u01/app/oracle/diag/rdbms/hoegh/HOEGH/trace/HOEGH_ora_16427.trc
-
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
-
With the Partitioning, OLAP, Data Mining and Real Application Testing options
-
ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1
-
System name: Linux
-
Node name: hoegh.example.com
-
Release: 2.6.18-164.el5PAE
-
Version: #1 SMP Thu Sep 3 02:28:20 EDT 2009
-
Machine: i686
-
VM name: VMWare Version: 6
-
Instance name: HOEGH
-
Redo thread mounted by this instance: 1
-
Oracle process number: 23
-
Unix process pid: 16427, image: oracle@hoegh.example.com (TNS V1-V3)
-
-
-
*** 2015-05-27 09:56:36.240
-
*** SESSION ID:(142.1705) 2015-05-27 09:56:36.240
-
*** CLIENT ID:() 2015-05-27 09:56:36.240
-
*** SERVICE NAME:(SYS$USERS) 2015-05-27 09:56:36.240
-
*** MODULE NAME:(sqlplus@hoegh.example.com (TNS V1-V3)) 2015-05-27 09:56:36.2
-
40
-
*** ACTION NAME:() 2015-05-27 09:56:36.240
-
由于trace文件的可读性差，我们使用tkprof对trace文件进行格式化，以下是格式化后的信息内容，在这儿也只截取了开始部门，完整的内容贴到文档的最后供大家参考。
格式化trace文件
-
[oracle@hoegh trace]$ tkprof HOEGH_ora_16427.trc 10046.txt
-
-
TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 11:20:36 2015
-
-
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
-
-
-
[oracle@hoegh trace]$
查看格式化后的trace报告
-
[oracle@hoegh trace]$ more 10046.txt
-
-
TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 11:20:36 2015
-
-
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
-
-
-
[oracle@ hoegh trace]$
-
-
-
-
TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 10:06:10 2015
-
-
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
-
-
Trace file: HOEGH_ora_16427.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: 4tk6t8tfsfqbf Plan Hash: 0
-
-
alter session set sql_trace=true
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 0 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 1 0.00 0.00 0 0 0 0
以上内容实现了一个应用sql_trace的简单案例，trace文件的信息量较大，我将会在下一篇文章中和大家分享。
大师论点
Eygle在课堂上提到他在面试时经常问的一个问题，“在什么技术上你做过深入思考得到了自己的观点”，绝大多数人的回答都是NO。
Eygle提倡由点及面、由浅入深的学习方法，确实，不深入是不可能有收获的。
期待下一次eygle在微信讲堂的精彩分享。
hoegh
15.05.22
-- The End --
附完整trace报告
-
TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 11:20:36 2015
-
-
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
-
-
-
[oracle@ hoegh trace]$
-
-
-
-
TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 10:06:10 2015
-
-
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
-
-
Trace file: HOEGH_ora_16427.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: 4tk6t8tfsfqbf Plan Hash: 0
-
-
alter session set sql_trace=true
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 0 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 1 0.00 0.00 0 0 0 0
-
-
Misses in library cache during parse: 0
-
Misses in library cache during execute: 1
-
Optimizer mode: ALL_ROWS
-
Parsing user id: SYS
-
********************************************************************************
-
-
SQL ID: 7cfz5wy9caaf4 Plan Hash: 4015672053
-
-
SELECT NAME NAME_COL_PLUS_SHOW_PARAM,DECODE(TYPE,1,\‘boolean\‘,2,\‘string\‘,3,
-
\‘integer\‘,4,\‘file\‘,5,\‘number\‘, 6,\‘big integer\‘, \‘unknown\‘) TYPE,
-
DISPLAY_VALUE VALUE_COL_PLUS_SHOW_PARAM
-
FROM
-
V$PARAMETER WHERE UPPER(NAME) LIKE UPPER(:NMBIND_SHOW_OBJ) ORDER BY
-
NAME_COL_PLUS_SHOW_PARAM,ROWNUM
-
-
-
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 0 0 1
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 4 0.01 0.01 0 0 0 1
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 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 SORT ORDER BY (cr=0 pr=0 pw=0 time=9094 us cost=2 size=2128 card=1)
-
1 1 1 COUNT (cr=0 pr=0 pw=0 time=8984 us)
-
1 1 1 HASH JOIN (cr=0 pr=0 pw=0 time=8979 us cost=1 size=2128 card=1)
-
1 1 1 FIXED TABLE FULL X$KSPPI (cr=0 pr=0 pw=0 time=6028 us cost=0 size=94 card=1)
-
2752 2752 2752 FIXED TABLE FULL X$KSPPCV (cr=0 pr=0 pw=0 time=3134 us cost=0 size=203400 card=100)
-
-
********************************************************************************
-
-
SQL ID: asvzxj61dc5vs Plan Hash: 3028786551
-
-
select timestamp, flags
-
from
-
fixed_obj$ where obj#=:1
-
-
-
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 1 0.00 0.00 0 2 0 0
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 3 0.00 0.00 0 2 0 0
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
0 0 0 TABLE ACCESS BY INDEX ROWID FIXED_OBJ$ (cr=2 pr=0 pw=0 time=15 us cost=2 size=17 card=1)
-
0 0 0 INDEX UNIQUE SCAN I_FIXED_OBJ$_OBJ# (cr=2 pr=0 pw=0 time=10 us cost=1 size=0 card=1)(object id 102)
-
-
********************************************************************************
-
-
SQL ID: 96g93hntrzjtr Plan Hash: 2239883476
-
-
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
-
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
-
spare1, spare2, avgcln
-
from
-
hist_head$ where obj#=:1 and intcol#=:2
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 1 0.00 0.00 0 0 0 0
-
Execute 20 0.00 0.00 0 0 0 0
-
Fetch 20 0.00 0.00 0 58 0 18
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 41 0.00 0.00 0 58 0 18
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: RULE
-
Parsing user id: SYS (recursive depth: 2)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 1 1 TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=206 us)
-
1 1 1 INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=159 us)(object id 427)
-
-
********************************************************************************
-
-
SQL ID: db78fxqxwxt7r Plan Hash: 3312420081
-
-
select /*+ rule */ bucket, endpoint, col#, epvalue
-
from
-
histgrm$ where obj#=:1 and intcol#=:2 and row#=:3 order by bucket
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 1 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 3
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 5 0.00 0.00 0 6 0 3
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: RULE
-
Parsing user id: SYS (recursive depth: 2)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 1 1 SORT ORDER BY (cr=3 pr=0 pw=0 time=182 us cost=0 size=0 card=0)
-
1 1 1 TABLE ACCESS CLUSTER HISTGRM$ (cr=3 pr=0 pw=0 time=150 us)
-
1 1 1 INDEX UNIQUE SCAN I_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=102 us)(object id 422)
-
-
********************************************************************************
-
-
SQL ID: gcnf7vvsyq6w3 Plan Hash: 0
-
-
select SADDR , SID , SERIAL# , AUDSID , PADDR , USER# , USERNAME , COMMAND ,
-
OWNERID, TADDR , LOCKWAIT , STATUS , SERVER , SCHEMA# , SCHEMANAME ,OSUSER ,
-
PROCESS , MACHINE , PORT , TERMINAL , PROGRAM , TYPE , SQL_ADDRESS ,
-
SQL_HASH_VALUE, SQL_ID, SQL_CHILD_NUMBER , SQL_EXEC_START, SQL_EXEC_ID,
-
PREV_SQL_ADDR , PREV_HASH_VALUE , PREV_SQL_ID, PREV_CHILD_NUMBER ,
-
PREV_EXEC_START , PREV_EXEC_ID , PLSQL_ENTRY_OBJECT_ID,
-
PLSQL_ENTRY_SUBPROGRAM_ID, PLSQL_OBJECT_ID, PLSQL_SUBPROGRAM_ID, MODULE ,
-
MODULE_HASH , ACTION , ACTION_HASH , CLIENT_INFO , FIXED_TABLE_SEQUENCE ,
-
ROW_WAIT_OBJ# , ROW_WAIT_FILE# , ROW_WAIT_BLOCK# , ROW_WAIT_ROW# ,
-
TOP_LEVEL_CALL#, LOGON_TIME , LAST_CALL_ET , PDML_ENABLED , FAILOVER_TYPE
-
, FAILOVER_METHOD , FAILED_OVER, RESOURCE_CONSUMER_GROUP, PDML_STATUS,
-
PDDL_STATUS, PQ_STATUS, CURRENT_QUEUE_DURATION, CLIENT_IDENTIFIER,
-
BLOCKING_SESSION_STATUS, BLOCKING_INSTANCE, BLOCKING_SESSION,
-
FINAL_BLOCKING_SESSION_STATUS, FINAL_BLOCKING_INSTANCE,
-
FINAL_BLOCKING_SESSION, SEQ#, EVENT#,EVENT,P1TEXT,P1,P1RAW,P2TEXT,P2,P2RAW,
-
P3TEXT,P3,P3RAW,WAIT_CLASS_ID, WAIT_CLASS#,WAIT_CLASS,WAIT_TIME,
-
SECONDS_IN_WAIT,STATE,WAIT_TIME_MICRO,TIME_REMAINING_MICRO,
-
TIME_SINCE_LAST_WAIT_MICRO,SERVICE_NAME, SQL_TRACE, SQL_TRACE_WAITS,
-
SQL_TRACE_BINDS, SQL_TRACE_PLAN_STATS, SESSION_EDITION_ID, CREATOR_ADDR,
-
CREATOR_SERIAL#, ECID
-
from
-
GV$SESSION where inst_id = USERENV(\‘Instance\‘)
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 1 0.01 0.01 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 1 0.01 0.01 0 0 0 0
-
-
Misses in library cache during parse: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
********************************************************************************
-
-
SQL ID: gzp9y42kcbx6m Plan Hash: 644658511
-
-
select sid,serial#,username
-
from
-
v$session where username=\‘SCOTT\‘
-
-
-
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 0 0 1
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 4 0.00 0.00 0 0 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 NESTED LOOPS (cr=0 pr=0 pw=0 time=231 us cost=0 size=121 card=1)
-
1 1 1 NESTED LOOPS (cr=0 pr=0 pw=0 time=2330 us cost=0 size=108 card=1)
-
1 1 1 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=1981 us cost=0 size=82 card=1)
-
1 1 1 FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=339 us cost=0 size=26 card=1)
-
1 1 1 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=2 us cost=0 size=13 card=1)
-
-
********************************************************************************
-
-
SQL ID: 3nkd3g3ju5ph1 Plan Hash: 2853959010
-
-
select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1,
-
spare2
-
from
-
obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
-
and linkname is null and subname is null
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 1 0.00 0.00 0 0 0 0
-
Execute 4 0.00 0.00 0 0 0 0
-
Fetch 4 0.00 0.00 0 16 0 4
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 9 0.00 0.00 0 16 0 4
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 1 1 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=4 pr=0 pw=0 time=145 us cost=4 size=82 card=1)
-
1 1 1 INDEX RANGE SCAN I_OBJ2 (cr=3 pr=0 pw=0 time=109 us cost=3 size=0 card=1)(object id 37)
-
-
********************************************************************************
-
-
SQL ID: 7ng34ruy5awxq Plan Hash: 2542797530
-
-
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,
-
i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,
-
i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,
-
nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),
-
i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),
-
nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,
-
null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,
-
ist.logicalread
-
from
-
ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,
-
min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))
-
valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where
-
i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 1 0.00 0.00 0 0 0 0
-
Execute 5 0.00 0.00 0 0 0 0
-
Fetch 10 0.00 0.00 0 36 0 5
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 16 0.00 0.00 0 36 0 5
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 2)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 1 1 SORT ORDER BY (cr=8 pr=0 pw=0 time=644 us cost=7 size=372 card=2)
-
1 1 1 HASH JOIN OUTER (cr=8 pr=0 pw=0 time=608 us cost=6 size=372 card=2)
-
1 1 1 NESTED LOOPS OUTER (cr=5 pr=0 pw=0 time=177 us cost=2 size=286 card=2)
-
1 1 1 TABLE ACCESS CLUSTER IND$ (cr=4 pr=0 pw=0 time=100 us cost=2 size=182 card=2)
-
1 1 1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=38 us cost=1 size=0 card=1)(object id 3)
-
0 0 0 TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=1 pr=0 pw=0 time=71 us cost=0 size=52 card=1)
-
0 0 0 INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=1 pr=0 pw=0 time=66 us cost=0 size=0 card=1)(object id 433)
-
0 0 0 VIEW (cr=3 pr=0 pw=0 time=202 us cost=3 size=43 card=1)
-
0 0 0 SORT GROUP BY (cr=3 pr=0 pw=0 time=200 us cost=3 size=15 card=1)
-
0 0 0 TABLE ACCESS CLUSTER CDEF$ (cr=3 pr=0 pw=0 time=149 us cost=2 size=15 card=1)
-
1 1 1 INDEX UNIQUE SCAN I_COBJ# (cr=2 pr=0 pw=0 time=43 us cost=1 size=0 card=1)(object id 30)
-
-
********************************************************************************
-
-
SQL ID: 5n1fs4m2n2y0r Plan Hash: 299250003
-
-
select pos#,intcol#,col#,spare1,bo#,spare2,spare3
-
from
-
icol$ where obj#=:1
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 1 0.00 0.00 0 0 0 0
-
Execute 5 0.00 0.00 0 0 0 0
-
Fetch 20 0.00 0.00 0 40 0 15
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 26 0.00 0.00 0 40 0 15
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 2)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 1 1 TABLE ACCESS BY INDEX ROWID ICOL$ (cr=4 pr=0 pw=0 time=52 us cost=2 size=54 card=2)
-
1 1 1 INDEX RANGE SCAN I_ICOL1 (cr=3 pr=0 pw=0 time=48 us cost=1 size=0 card=2)(object id 42)
-
-
********************************************************************************
-
-
SQL ID: 83taa7kaw59c1 Plan Hash: 3765558045
-
-
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,
-
nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,
-
scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,
-
rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,
-
nvl(spare3,0)
-
from
-
col$ where obj#=:1 order by intcol#
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 1 0.00 0.00 0 0 0 0
-
Execute 5 0.00 0.00 0 0 0 0
-
Fetch 31 0.00 0.00 0 16 0 26
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 37 0.00 0.00 0 16 0 26
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 2)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
4 4 4 SORT ORDER BY (cr=4 pr=0 pw=0 time=54 us cost=3 size=708 card=12)
-
4 4 4 TABLE ACCESS CLUSTER COL$ (cr=4 pr=0 pw=0 time=27 us cost=2 size=708 card=12)
-
1 1 1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=9 us cost=1 size=0 card=1)(object id 3)
-
-
********************************************************************************
-
-
SQL ID: 3ktacv9r56b51 Plan Hash: 4184428695
-
-
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#,
-
nvl(property,0),subname,type#,d_attrs
-
from
-
dependency$ d, obj$ o where d_obj#=:1 and p_obj#=obj#(+) order by order#
-
-
-
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 12 0.00 0.00 0 27 0 10
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 16 0.00 0.00 0 27 0 10
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 2
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 5 9 SORT ORDER BY (cr=14 pr=0 pw=0 time=304 us cost=11 size=330 card=3)
-
1 5 9 NESTED LOOPS OUTER (cr=14 pr=0 pw=0 time=297 us cost=10 size=330 card=3)
-
1 5 9 TABLE ACCESS BY INDEX ROWID DEPENDENCY$ (cr=4 pr=0 pw=0 time=80 us cost=4 size=84 card=3)
-
1 5 9 INDEX RANGE SCAN I_DEPENDENCY1 (cr=3 pr=0 pw=0 time=51 us cost=3 size=0 card=3)(object id 106)
-
1 3 5 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=10 pr=0 pw=0 time=157 us cost=2 size=82 card=1)
-
1 3 5 INDEX RANGE SCAN I_OBJ1 (cr=6 pr=0 pw=0 time=97 us cost=1 size=0 card=1)(object id 36)
-
-
********************************************************************************
-
-
SQL ID: 87gaftwrm2h68 Plan Hash: 1218588913
-
-
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname
-
from
-
obj$ o where o.obj#=:1
-
-
-
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 1 0.00 0.00 0 3 0 1
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 3 0.00 0.00 0 3 0 1
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 2)
-
Number of plan statistics captured: 1
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 1 1 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=38 us cost=3 size=82 card=1)
-
1 1 1 INDEX RANGE SCAN I_OBJ1 (cr=2 pr=0 pw=0 time=31 us cost=2 size=0 card=1)(object id 36)
-
-
********************************************************************************
-
-
SQL ID: ga9j9xk5cy9s0 Plan Hash: 1697022209
-
-
select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece
-
from
-
idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 3 0.00 0.00 0 0 0 0
-
Execute 3 0.00 0.00 0 0 0 0
-
Fetch 7 0.00 0.00 1 18 0 4
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 13 0.00 0.00 1 18 0 4
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 3
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
2 1 2 TABLE ACCESS BY INDEX ROWID IDL_SB4$ (cr=5 pr=0 pw=0 time=205 us cost=3 size=19 card=1)
-
2 1 2 INDEX RANGE SCAN I_IDL_SB41 (cr=3 pr=0 pw=0 time=36 us cost=2 size=0 card=1)(object id 239)
-
-
********************************************************************************
-
-
SQL ID: cvn54b7yz0s8u Plan Hash: 3246118364
-
-
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece
-
from
-
idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 3 0.00 0.00 0 0 0 0
-
Execute 3 0.00 0.00 0 0 0 0
-
Fetch 6 0.00 0.00 3 20 0 5
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 12 0.00 0.00 3 20 0 5
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 3
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 2 2 TABLE ACCESS BY INDEX ROWID IDL_UB1$ (cr=5 pr=1 pw=0 time=160 us cost=3 size=44 card=2)
-
1 2 2 INDEX RANGE SCAN I_IDL_UB11 (cr=3 pr=0 pw=0 time=30 us cost=2 size=0 card=2)(object id 236)
-
-
********************************************************************************
-
-
SQL ID: c6awqs517jpj0 Plan Hash: 1319326155
-
-
select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece
-
from
-
idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 3 0.00 0.00 0 0 0 0
-
Execute 3 0.00 0.00 0 0 0 0
-
Fetch 4 0.00 0.01 1 9 0 1
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 10 0.00 0.01 1 9 0 1
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 3
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 0 1 TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=3 pr=0 pw=0 time=3509 us cost=3 size=21 card=1)
-
1 0 1 INDEX RANGE SCAN I_IDL_CHAR1 (cr=2 pr=0 pw=0 time=30 us cost=2 size=0 card=1)(object id 237)
-
-
********************************************************************************
-
-
SQL ID: 39m4sx9k63ba2 Plan Hash: 2317816222
-
-
select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece
-
from
-
idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
-
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 3 0.00 0.00 0 0 0 0
-
Execute 3 0.00 0.00 0 0 0 0
-
Fetch 4 0.00 0.00 1 11 0 2
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 10 0.00 0.01 1 11 0 2
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 3
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
2 1 2 TABLE ACCESS BY INDEX ROWID IDL_UB2$ (cr=3 pr=0 pw=0 time=2460 us cost=3 size=40 card=2)
-
2 1 2 INDEX RANGE SCAN I_IDL_UB21 (cr=2 pr=0 pw=0 time=29 us cost=2 size=0 card=2)(object id 238)
-
-
********************************************************************************
-
-
SQL ID: 83sp8xb9ytgkv Plan Hash: 0
-
-
BEGIN dbms_system.set_ev(21,2615,10046,12,\‘SCOTT\‘); END;
-
-
-
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 1
-
Fetch 0 0.00 0.00 0 0 0 0
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 2 0.00 0.00 0 0 0 1
-
-
Misses in library cache during parse: 1
-
Optimizer mode: ALL_ROWS
-
Parsing user id: SYS
-
********************************************************************************
-
-
SQL ID: b1wc53ddd6h3p Plan Hash: 1637390370
-
-
select audit$,options
-
from
-
procedure$ where obj#=:1
-
-
-
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 2
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 6 0.00 0.00 0 6 0 2
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 2
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
1 1 1 TABLE ACCESS BY INDEX ROWID PROCEDURE$ (cr=3 pr=0 pw=0 time=46 us cost=2 size=47 card=1)
-
1 1 1 INDEX UNIQUE SCAN I_PROCEDURE1 (cr=2 pr=0 pw=0 time=26 us cost=1 size=0 card=1)(object id 231)
-
-
********************************************************************************
-
-
SQL ID: 8swypbbr0m372 Plan Hash: 893970548
-
-
select order#,columns,types
-
from
-
access$ where d_obj#=:1
-
-
-
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 9 0.00 0.00 0 18 0 7
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 13 0.00 0.00 0 18 0 7
-
-
Misses in library cache during parse: 1
-
Misses in library cache during execute: 1
-
Optimizer mode: CHOOSE
-
Parsing user id: SYS (recursive depth: 1)
-
Number of plan statistics captured: 2
-
-
Rows (1st) Rows (avg) Rows (max) Row Source Operation
-
---------- ---------- ---------- ---------------------------------------------------
-
7 4 7 TABLE ACCESS BY INDEX ROWID ACCESS$ (cr=9 pr=0 pw=0 time=56 us cost=3 size=161 card=7)
-
7 4 7 INDEX RANGE SCAN I_ACCESS1 (cr=6 pr=0 pw=0 time=48 us cost=2 size=0 card=7)(object id 108)
-
-
-
-
-
********************************************************************************
-
-
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 3 0.00 0.00 0 0 0 0
-
Execute 4 0.01 0.01 0 0 0 1
-
Fetch 4 0.01 0.01 0 0 0 2
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 11 0.02 0.03 0 0 0 3
-
-
Misses in library cache during parse: 3
-
Misses in library cache during execute: 2
-
-
-
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
-
-
call count cpu elapsed disk query current rows
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
Parse 27 0.03 0.03 0 0 0 0
-
Execute 61 0.01 0.02 0 0 0 0
-
Fetch 133 0.01 0.02 6 286 0 103
-
------- ------ -------- ---------- ---------- ---------- ---------- ----------
-
total 221 0.06 0.08 6 286 0 103
-
-
Misses in library cache during parse: 16
-
Misses in library cache during execute: 15
-
-
4 user SQL statements in session.
-
27 internal SQL statements in session.
-
31 SQL statements in session.
-
********************************************************************************
-
Trace file: HOEGH_ora_16427.trc
-
Trace file compatibility: 11.1.0.7
-
Sort options: default
-
-
1 session in tracefile.
-
4 user SQL statements in trace file.
-
27 internal SQL statements in trace file.
-
31 SQL statements in trace file.
-
20 unique SQL statements in trace file.
-
534 lines in trace file.
-
337 elapsed seconds in trace file.
如何使用SQL_TRACE和10046事件
原文：http://blog.itpub.net/30162081/viewspace-1666982/
