如何使用SQL_TRACE和10046事件

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 - ProductionPL/SQL Release 11.2.0.3.0 - ProductionCORE 11.2.0.3.0 ProductionTNS for Linux: Version 11.2.0.3.0 - ProductionNLSRTL Version 11.2.0.3.0 - ProductionSQL>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_TRACENAME TYPE VALUE------------------------------------ ----------- ------------------------------SQL_TRACE boolean FALSESQL>SQL> alter session set SQL_TRACE=true;Session altered.SQL>SQL> show parameter SQL_TRACENAME TYPE VALUE------------------------------------ ----------- ------------------------------SQL_TRACE boolean TRUESQL>
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 2015Copyright （c） 1982, 2011, Oracle. All rights reserved.Connected to:Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - ProductionWith the Partitioning, OLAP, Data Mining and Real Application Testing optionsSQL> select * from cat;TABLE_NAME TABLE_TYPE------------------------------ -----------BONUS TABLEDEPT TABLEEMP TABLESALGRADE TABLESQL> 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 userUSER is "SCOTT"SQL>SQL> set autotrace onSP2-0618: Cannot find the Session Identifier. Check PLUSTRACE role is enabledSP2-0611: Error enabling STATISTICS reportSQL>
这时需要执行$ORACLE_HOME/sqlplus/admin/plustrce.sql脚本，手工创建plustrace角色，在此不做演示。因为我们更多的时候是需要跟踪其他用户的进程，而很多这样的用户可能没有被授予或者不允许授予plustrace角色。这时可以使用DBMS_SYSTEM包来实现对进程的跟踪，这儿需要提供用户进程的sid和serial#。
10046事件
在这儿就不得不提到10046事件，10046事件是Oracle提供的内部事件，是对SQL_TRACE的增强。
10046事件可以设置以下四个级别：1 - 启用标准的SQL_TRACE功能,等价于SQL_TRACE4 - 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 SCOTTSQL>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/oracleSQL>
在测试数据库中，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.trcOracle Database 11g Enterprise Edition Release 11.2.0.3.0 - ProductionWith the Partitioning, OLAP, Data Mining and Real Application Testing optionsORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1System name: LinuxNode name: hoegh.example.comRelease: 2.6.18-164.el5PAEVersion: #1 SMP Thu Sep 3 02:28:20 EDT 2009Machine: i686VM name: VMWare Version: 6Instance name: HOEGHRedo thread mounted by this instance: 1Oracle process number: 23Unix 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.240*** 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 2015Copyright （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 2015Copyright （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 2015Copyright （c） 1982, 2011, Oracle and/or its affiliates. All rights reserved.Trace file: HOEGH_ora_16427.trcSort options: default********************************************************************************count = number of times OCI procedure was executedcpu = cpu time in seconds executingelapsed = elapsed time in seconds executingdisk = number of physical reads of buffers from diskquery = number of buffers gotten for consistent readcurrent = 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: 0alter session set sql_trace=truecall count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 0 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 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在微信讲堂的精彩分享。
hoegh15.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 2015Copyright （c） 1982, 2011, Oracle and/or its affiliates. All rights reserved.Trace file: HOEGH_ora_16427.trcSort options: default********************************************************************************count = number of times OCI procedure was executedcpu = cpu time in seconds executingelapsed = elapsed time in seconds executingdisk = number of physical reads of buffers from diskquery = number of buffers gotten for consistent readcurrent = 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: 0alter session set sql_trace=truecall count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 0 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 0 0.00 0.00 0 0 0 0------- ------ -------- ---------- ---------- ---------- ---------- ----------total 1 0.00 0.00 0 0 0 0Misses in library cache during parse: 0Misses in library cache during execute: 1Optimizer mode: ALL_ROWSParsing user id: SYS********************************************************************************SQL ID: 7cfz5wy9caaf4 Plan Hash: 4015672053SELECT 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_PARAMFROM V$PARAMETER WHERE UPPER（NAME） LIKE UPPER（:NMBIND_SHOW_OBJ） ORDER BY NAME_COL_PLUS_SHOW_PARAM,ROWNUMcall count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 2 0.00 0.00 0 0 0 1------- ------ -------- ---------- ---------- ---------- ---------- ----------total 4 0.01 0.01 0 0 0 1Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: ALL_ROWSParsing user id: SYSNumber of plan statistics captured: 1Rows （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: 3028786551select timestamp, flagsfrom fixed_obj$ where obj#=:1call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 1 0.00 0.00 0 2 0 0------- ------ -------- ---------- ---------- ---------- ---------- ----------total 3 0.00 0.00 0 2 0 0Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 1Rows （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: 2239883476select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgclnfrom hist_head$ where obj#=:1 and intcol#=:2call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 20 0.00 0.00 0 0 0 0Fetch 20 0.00 0.00 0 58 0 18------- ------ -------- ---------- ---------- ---------- ---------- ----------total 41 0.00 0.00 0 58 0 18Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: RULEParsing user id: SYS （recursive depth: 2）Number of plan statistics captured: 1Rows （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: 3312420081select /*+ rule */ bucket, endpoint, col#, epvaluefrom histgrm$ where obj#=:1 and intcol#=:2 and row#=:3 order by bucketcall count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 2 0.00 0.00 0 0 0 0Fetch 2 0.00 0.00 0 6 0 3------- ------ -------- ---------- ---------- ---------- ---------- ----------total 5 0.00 0.00 0 6 0 3Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: RULEParsing user id: SYS （recursive depth: 2）Number of plan statistics captured: 1Rows （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: 0select 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#, ECIDfrom GV$SESSION where inst_id = USERENV（"Instance"）call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.01 0.01 0 0 0 0Execute 0 0.00 0.00 0 0 0 0Fetch 0 0.00 0.00 0 0 0 0------- ------ -------- ---------- ---------- ---------- ---------- ----------total 1 0.01 0.01 0 0 0 0Misses in library cache during parse: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）********************************************************************************SQL ID: gzp9y42kcbx6m Plan Hash: 644658511select sid,serial#,usernamefrom v$session where username="SCOTT"call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 2 0.00 0.00 0 0 0 1------- ------ -------- ---------- ---------- ---------- ---------- ----------total 4 0.00 0.00 0 0 0 1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: SYSNumber of plan statistics captured: 1Rows （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: 2853959010select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is nullcall count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 4 0.00 0.00 0 0 0 0Fetch 4 0.00 0.00 0 16 0 4------- ------ -------- ---------- ---------- ---------- ---------- ----------total 9 0.00 0.00 0 16 0 4Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 1Rows （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: 2542797530select 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.logicalreadfrom 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 0Execute 5 0.00 0.00 0 0 0 0Fetch 10 0.00 0.00 0 36 0 5------- ------ -------- ---------- ---------- ---------- ---------- ----------total 16 0.00 0.00 0 36 0 5Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 2）Number of plan statistics captured: 1Rows （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: 299250003select pos#,intcol#,col#,spare1,bo#,spare2,spare3from icol$ where obj#=:1call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 5 0.00 0.00 0 0 0 0Fetch 20 0.00 0.00 0 40 0 15------- ------ -------- ---------- ---------- ---------- ---------- ----------total 26 0.00 0.00 0 40 0 15Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 2）Number of plan statistics captured: 1Rows （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: 3765558045select 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 0Execute 5 0.00 0.00 0 0 0 0Fetch 31 0.00 0.00 0 16 0 26------- ------ -------- ---------- ---------- ---------- ---------- ----------total 37 0.00 0.00 0 16 0 26Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 2）Number of plan statistics captured: 1Rows （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: 4184428695select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#, nvl（property,0）,subname,type#,d_attrsfrom 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 0Execute 2 0.00 0.00 0 0 0 0Fetch 12 0.00 0.00 0 27 0 10------- ------ -------- ---------- ---------- ---------- ---------- ----------total 16 0.00 0.00 0 27 0 10Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 2Rows （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: 1218588913select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subnamefrom obj$ o where o.obj#=:1call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 1 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 1 0.00 0.00 0 3 0 1------- ------ -------- ---------- ---------- ---------- ---------- ----------total 3 0.00 0.00 0 3 0 1Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 2）Number of plan statistics captured: 1Rows （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: 1697022209select /*+ index（idl_sb4$ i_idl_sb41） +*/ piece#,length,piecefrom 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 0Execute 3 0.00 0.00 0 0 0 0Fetch 7 0.00 0.00 1 18 0 4------- ------ -------- ---------- ---------- ---------- ---------- ----------total 13 0.00 0.00 1 18 0 4Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 3Rows （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: 3246118364select /*+ index（idl_ub1$ i_idl_ub11） +*/ piece#,length,piecefrom 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 0Execute 3 0.00 0.00 0 0 0 0Fetch 6 0.00 0.00 3 20 0 5------- ------ -------- ---------- ---------- ---------- ---------- ----------total 12 0.00 0.00 3 20 0 5Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 3Rows （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: 1319326155select /*+ index（idl_char$ i_idl_char1） +*/ piece#,length,piecefrom 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 0Execute 3 0.00 0.00 0 0 0 0Fetch 4 0.00 0.01 1 9 0 1------- ------ -------- ---------- ---------- ---------- ---------- ----------total 10 0.00 0.01 1 9 0 1Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 3Rows （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: 2317816222select /*+ index（idl_ub2$ i_idl_ub21） +*/ piece#,length,piecefrom 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 0Execute 3 0.00 0.00 0 0 0 0Fetch 4 0.00 0.00 1 11 0 2------- ------ -------- ---------- ---------- ---------- ---------- ----------total 10 0.00 0.01 1 11 0 2Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 3Rows （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: 0BEGIN 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 0Execute 1 0.00 0.00 0 0 0 1Fetch 0 0.00 0.00 0 0 0 0------- ------ -------- ---------- ---------- ---------- ---------- ----------total 2 0.00 0.00 0 0 0 1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: SYS********************************************************************************SQL ID: b1wc53ddd6h3p Plan Hash: 1637390370select audit$,optionsfrom procedure$ where obj#=:1call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 2 0.00 0.00 0 0 0 0Execute 2 0.00 0.00 0 0 0 0Fetch 2 0.00 0.00 0 6 0 2------- ------ -------- ---------- ---------- ---------- ---------- ----------total 6 0.00 0.00 0 6 0 2Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 2Rows （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: 893970548select order#,columns,typesfrom access$ where d_obj#=:1call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 2 0.00 0.00 0 0 0 0Execute 2 0.00 0.00 0 0 0 0Fetch 9 0.00 0.00 0 18 0 7------- ------ -------- ---------- ---------- ---------- ---------- ----------total 13 0.00 0.00 0 18 0 7Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS （recursive depth: 1）Number of plan statistics captured: 2Rows （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 STATEMENTScall count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 3 0.00 0.00 0 0 0 0Execute 4 0.01 0.01 0 0 0 1Fetch 4 0.01 0.01 0 0 0 2------- ------ -------- ---------- ---------- ---------- ---------- ----------total 11 0.02 0.03 0 0 0 3Misses in library cache during parse: 3Misses in library cache during execute: 2OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------Parse 27 0.03 0.03 0 0 0 0Execute 61 0.01 0.02 0 0 0 0Fetch 133 0.01 0.02 6 286 0 103------- ------ -------- ---------- ---------- ---------- ---------- ----------total 221 0.06 0.08 6 286 0 103Misses in library cache during parse: 16Misses 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.trcTrace file compatibility: 11.1.0.7Sort 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.更多Oracle相关信息见Oracle 专题页面 http://www.linuxidc.com/topicnews.aspx？tid=12本文永久更新链接地址