如何使用SQL_TRACE和10046事件

kingsql發表於2015-07-23
SQL事件

Eygle大師的微信講堂昨天開課，第一堂課和大家分享了一些學習Oracle的基本方法，其中提到了使用SQL_TRACE和10046事件。SQL_TRACE是Oracle提供的用於進行SQL跟蹤的手段，是強有力的輔助診斷工具。在日常的資料庫問題診斷和解決中，SQL_TRACE是非常常用的方法。

      對於這個工具，我很早就聽過，但是從來就沒用過，“紙上得來終覺淺，絕知此事要躬行”，操練起來。

1.環境準備

      我們在Oracle11g中進行測試。

點選(此處)摺疊或開啟

  1. SQL>
  2. SQL> select * from v$version;

  4. BANNER
  5. --------------------------------------------------------------------------------
  6. Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
  7. PL/SQL Release 11.2.0.3.0 - Production
  8. CORE 11.2.0.3.0 Production
  9. TNS for Linux: Version 11.2.0.3.0 - Production
  10. NLSRTL Version 11.2.0.3.0 - Production

  12. 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，如下所示。

點選(此處)摺疊或開啟

  1. SQL>
  2. SQL> show parameter SQL_TRACE

  4. NAME TYPE VALUE
  5. ------------------------------------ ----------- ------------------------------
  6. SQL_TRACE boolean FALSE
  7. SQL>
  8. SQL> alter session set SQL_TRACE=true;

  10. Session altered.

  12. SQL>
  13. SQL> show parameter SQL_TRACE

  15. NAME TYPE VALUE
  16. ------------------------------------ ----------- ------------------------------
  17. SQL_TRACE boolean TRUE
  18. SQL>

3.連線soctt使用者，執行查詢語句

     登陸scott使用者，執行兩條簡單的查詢語句。

點選(此處)摺疊或開啟

  1. [oracle@hoegh admin]$ sqlplus scott/tiger

  3. SQL*Plus: Release 11.2.0.3.0 Production on Wed May 27 09:59:48 2015

  5. Copyright (c) 1982, 2011, Oracle. All rights reserved.


  8. Connected to:
  9. Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
  10. With the Partitioning, OLAP, Data Mining and Real Application Testing options

  12. SQL> select * from cat;

  14. TABLE_NAME TABLE_TYPE
  15. ------------------------------ -----------
  16. BONUS TABLE
  17. DEPT TABLE
  18. EMP TABLE
  19. SALGRADE TABLE

  21. SQL> select * from dept;

  23.     DEPTNO DNAME LOC
  24. ---------- -------------- -------------
  25.         10 ACCOUNTING NEW YORK
  26.         20 RESEARCH DALLAS
  27.         30 SALES CHICAGO
  28.         40 OPERATIONS BOSTON

4.生成trace檔案

plustrace角色

      和Oracle10g一樣，11g中plustrace角色預設也是disabled的。如果使用非授權使用者開啟Oracle trace功能會得到以下的錯誤。

點選(此處)摺疊或開啟

  1. SQL>
  2. SQL> show user
  3. USER is \"SCOTT\"
  4. SQL>
  5. SQL> set autotrace on
  6. SP2-0618: Cannot find the Session Identifier. Check PLUSTRACE role is enabled
  7. SP2-0611: Error enabling STATISTICS report
  8. 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過程來實現對程式的跟蹤。

點選(此處)摺疊或開啟

  1. SQL>
  2. SQL> select sid,serial#,username from v$session where username=\'SCOTT\';

  4.        SID SERIAL# USERNAME
  5. ---------- ---------- ------------------------------
  6.         21 2615 SCOTT

  8. SQL>
  9. SQL> exec dbms_system.set_ev(21,2615,10046,12,\'SCOTT\');

  11. PL/SQL procedure successfully completed.

  13. SQL>

5.檢視trace檔案

存放目錄

      在11g中trace檔案的存放目錄有了變化，其中，11gR1 或 11gR1 以上版本可以透過查詢diagnostic_dest引數獲得；而11gR1以前版本則是透過user_dump_dest引數來指定。

點選(此處)摺疊或開啟

  1. SQL> show parameter diagnostic_dest

  3. NAME TYPE VALUE
  4. ------------------------------------ ----------- ------------------------------
  5. diagnostic_dest string /u01/app/oracle
  6. SQL>
     在測試資料庫中，trace檔案的具體路徑為：/u01/app/oracle/diag/rdbms/hoegh/HOEGH/trace/。

檢視trace檔案

      tracefile 命名規則 ：_ora_.trc，其中pid為相應session所對應的OS PID。根據生成時間在/u01/app/oracle/diag/rdbms/hoegh/HOEGH/trace目錄下找到了trace檔案HOEGH_ora_16427.trc。我們透過more命令檢視檔案內容，由於內容較多，只擷取了開始部分內容如下。

點選(此處)摺疊或開啟

  1. [oracle@hoegh trace]$ more HOEGH_ora_16427.trc
  2. Trace file /u01/app/oracle/diag/rdbms/hoegh/HOEGH/trace/HOEGH_ora_16427.trc
  3. Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
  4. With the Partitioning, OLAP, Data Mining and Real Application Testing options
  5. ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1
  6. System name: Linux
  7. Node name: hoegh.example.com
  8. Release: 2.6.18-164.el5PAE
  9. Version: #1 SMP Thu Sep 3 02:28:20 EDT 2009
  10. Machine: i686
  11. VM name: VMWare Version: 6
  12. Instance name: HOEGH
  13. Redo thread mounted by this instance: 1
  14. Oracle process number: 23
  15. Unix process pid: 16427, image: oracle@hoegh.example.com (TNS V1-V3)


  18. *** 2015-05-27 09:56:36.240
  19. *** SESSION ID:(142.1705) 2015-05-27 09:56:36.240
  20. *** CLIENT ID:() 2015-05-27 09:56:36.240
  21. *** SERVICE NAME:(SYS$USERS) 2015-05-27 09:56:36.240
  22. *** MODULE NAME:(sqlplus@hoegh.example.com (TNS V1-V3)) 2015-05-27 09:56:36.2
  23. 40
  24. *** ACTION NAME:() 2015-05-27 09:56:36.240
      由於trace檔案的可讀性差，我們使用tkprof對trace檔案進行格式化，以下是格式化後的資訊內容，在這兒也只擷取了開始部門，完整的內容貼到文件的最後供大家參考。

格式化trace檔案


點選(此處)摺疊或開啟

  1. [oracle@hoegh trace]$ tkprof HOEGH_ora_16427.trc 10046.txt

  3. TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 11:20:36 2015

  5. Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.


  8. [oracle@hoegh trace]$

檢視格式化後的trace報告


點選(此處)摺疊或開啟

  1. [oracle@hoegh trace]$ more 10046.txt

  3. TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 11:20:36 2015

  5. Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.


  8. [oracle@ hoegh trace]$



  12. TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 10:06:10 2015

  14. Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.

  16. Trace file: HOEGH_ora_16427.trc
  17. Sort options: default

  19. ********************************************************************************
  20. count = number of times OCI procedure was executed
  21. cpu = cpu time in seconds executing
  22. elapsed = elapsed time in seconds executing
  23. disk = number of physical reads of buffers from disk
  24. query = number of buffers gotten for consistent read
  25. current = number of buffers gotten in current mode (usually for update)
  26. rows = number of rows processed by the fetch or execute call
  27. ********************************************************************************

  29. SQL ID: 4tk6t8tfsfqbf Plan Hash: 0

  31. alter session set sql_trace=true


  34. call count cpu elapsed disk query current rows
  35. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  36. Parse 0 0.00 0.00 0 0 0 0
  37. Execute 1 0.00 0.00 0 0 0 0
  38. Fetch 0 0.00 0.00 0 0 0 0
  39. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  40. total 1 0.00 0.00 0 0 0 0
      以上內容實現了一個應用sql_trace的簡單案例，trace檔案的資訊量較大，我將會在下一篇文章中和大家分享。  

大師論點

     Eygle在課堂上提到他在面試時經常問的一個問題，“在什麼技術上你做過深入思考得到了自己的觀點”，絕大多數人的回答都是NO。
     Eygle提倡由點及面、由淺入深的學習方法，確實，不深入是不可能有收穫的。
     
     期待下一次eygle在微信講堂的精彩分享。

hoegh
15.05.22
-- The End --

附完整trace報告            


點選(此處)摺疊或開啟

  1. TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 11:20:36 2015

  3. Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.


  6. [oracle@ hoegh trace]$



  10. TKPROF: Release 11.2.0.3.0 - Development on Wed May 27 10:06:10 2015

  12. Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.

  14. Trace file: HOEGH_ora_16427.trc
  15. Sort options: default

  17. ********************************************************************************
  18. count = number of times OCI procedure was executed
  19. cpu = cpu time in seconds executing
  20. elapsed = elapsed time in seconds executing
  21. disk = number of physical reads of buffers from disk
  22. query = number of buffers gotten for consistent read
  23. current = number of buffers gotten in current mode (usually for update)
  24. rows = number of rows processed by the fetch or execute call
  25. ********************************************************************************

  27. SQL ID: 4tk6t8tfsfqbf Plan Hash: 0

  29. alter session set sql_trace=true


  32. call count cpu elapsed disk query current rows
  33. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  34. Parse 0 0.00 0.00 0 0 0 0
  35. Execute 1 0.00 0.00 0 0 0 0
  36. Fetch 0 0.00 0.00 0 0 0 0
  37. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  38. total 1 0.00 0.00 0 0 0 0

  40. Misses in library cache during parse: 0
  41. Misses in library cache during execute: 1
  42. Optimizer mode: ALL_ROWS
  43. Parsing user id: SYS
  44. ********************************************************************************

  46. SQL ID: 7cfz5wy9caaf4 Plan Hash: 4015672053

  48. SELECT NAME NAME_COL_PLUS_SHOW_PARAM,DECODE(TYPE,1,\'boolean\',2,\'string\',3,
  49.   \'integer\',4,\'file\',5,\'number\', 6,\'big integer\', \'unknown\') TYPE,
  50.   DISPLAY_VALUE VALUE_COL_PLUS_SHOW_PARAM
  51. FROM
  52.  V$PARAMETER WHERE UPPER(NAME) LIKE UPPER(:NMBIND_SHOW_OBJ) ORDER BY
  53.   NAME_COL_PLUS_SHOW_PARAM,ROWNUM


  56. call count cpu elapsed disk query current rows
  57. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  58. Parse 1 0.00 0.00 0 0 0 0
  59. Execute 1 0.00 0.00 0 0 0 0
  60. Fetch 2 0.00 0.00 0 0 0 1
  61. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  62. total 4 0.01 0.01 0 0 0 1

  64. Misses in library cache during parse: 1
  65. Misses in library cache during execute: 1
  66. Optimizer mode: ALL_ROWS
  67. Parsing user id: SYS
  68. Number of plan statistics captured: 1

  70. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  71. ---------- ---------- ---------- ---------------------------------------------------
  72.          1 1 1 SORT ORDER BY (cr=0 pr=0 pw=0 time=9094 us cost=2 size=2128 card=1)
  73.          1 1 1 COUNT (cr=0 pr=0 pw=0 time=8984 us)
  74.          1 1 1 HASH JOIN (cr=0 pr=0 pw=0 time=8979 us cost=1 size=2128 card=1)
  75.          1 1 1 FIXED TABLE FULL X$KSPPI (cr=0 pr=0 pw=0 time=6028 us cost=0 size=94 card=1)
  76.       2752 2752 2752 FIXED TABLE FULL X$KSPPCV (cr=0 pr=0 pw=0 time=3134 us cost=0 size=203400 card=100)

  78. ********************************************************************************

  80. SQL ID: asvzxj61dc5vs Plan Hash: 3028786551

  82. select timestamp, flags
  83. from
  84.  fixed_obj$ where obj#=:1


  87. call count cpu elapsed disk query current rows
  88. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  89. Parse 1 0.00 0.00 0 0 0 0
  90. Execute 1 0.00 0.00 0 0 0 0
  91. Fetch 1 0.00 0.00 0 2 0 0
  92. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  93. total 3 0.00 0.00 0 2 0 0

  95. Misses in library cache during parse: 1
  96. Misses in library cache during execute: 1
  97. Optimizer mode: CHOOSE
  98. Parsing user id: SYS (recursive depth: 1)
  99. Number of plan statistics captured: 1

  101. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  102. ---------- ---------- ---------- ---------------------------------------------------
  103.          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)
  104.          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)

  106. ********************************************************************************

  108. SQL ID: 96g93hntrzjtr Plan Hash: 2239883476

  110. select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
  111.   sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
  112.   spare1, spare2, avgcln
  113. from
  114.  hist_head$ where obj#=:1 and intcol#=:2


  117. call count cpu elapsed disk query current rows
  118. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  119. Parse 1 0.00 0.00 0 0 0 0
  120. Execute 20 0.00 0.00 0 0 0 0
  121. Fetch 20 0.00 0.00 0 58 0 18
  122. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  123. total 41 0.00 0.00 0 58 0 18

  125. Misses in library cache during parse: 1
  126. Misses in library cache during execute: 1
  127. Optimizer mode: RULE
  128. Parsing user id: SYS (recursive depth: 2)
  129. Number of plan statistics captured: 1

  131. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  132. ---------- ---------- ---------- ---------------------------------------------------
  133.          1 1 1 TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=206 us)
  134.          1 1 1 INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=159 us)(object id 427)

  136. ********************************************************************************

  138. SQL ID: db78fxqxwxt7r Plan Hash: 3312420081

  140. select /*+ rule */ bucket, endpoint, col#, epvalue
  141. from
  142.  histgrm$ where obj#=:1 and intcol#=:2 and row#=:3 order by bucket


  145. call count cpu elapsed disk query current rows
  146. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  147. Parse 1 0.00 0.00 0 0 0 0
  148. Execute 2 0.00 0.00 0 0 0 0
  149. Fetch 2 0.00 0.00 0 6 0 3
  150. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  151. total 5 0.00 0.00 0 6 0 3

  153. Misses in library cache during parse: 1
  154. Misses in library cache during execute: 1
  155. Optimizer mode: RULE
  156. Parsing user id: SYS (recursive depth: 2)
  157. Number of plan statistics captured: 1

  159. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  160. ---------- ---------- ---------- ---------------------------------------------------
  161.          1 1 1 SORT ORDER BY (cr=3 pr=0 pw=0 time=182 us cost=0 size=0 card=0)
  162.          1 1 1 TABLE ACCESS CLUSTER HISTGRM$ (cr=3 pr=0 pw=0 time=150 us)
  163.          1 1 1 INDEX UNIQUE SCAN I_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=102 us)(object id 422)

  165. ********************************************************************************

  167. SQL ID: gcnf7vvsyq6w3 Plan Hash: 0

  169. select SADDR , SID , SERIAL# , AUDSID , PADDR , USER# , USERNAME , COMMAND ,
  170.   OWNERID, TADDR , LOCKWAIT , STATUS , SERVER , SCHEMA# , SCHEMANAME ,OSUSER ,
  171.    PROCESS , MACHINE , PORT , TERMINAL , PROGRAM , TYPE , SQL_ADDRESS ,
  172.   SQL_HASH_VALUE, SQL_ID, SQL_CHILD_NUMBER , SQL_EXEC_START, SQL_EXEC_ID,
  173.   PREV_SQL_ADDR , PREV_HASH_VALUE , PREV_SQL_ID, PREV_CHILD_NUMBER ,
  174.   PREV_EXEC_START , PREV_EXEC_ID , PLSQL_ENTRY_OBJECT_ID,
  175.   PLSQL_ENTRY_SUBPROGRAM_ID, PLSQL_OBJECT_ID, PLSQL_SUBPROGRAM_ID, MODULE ,
  176.   MODULE_HASH , ACTION , ACTION_HASH , CLIENT_INFO , FIXED_TABLE_SEQUENCE ,
  177.   ROW_WAIT_OBJ# , ROW_WAIT_FILE# , ROW_WAIT_BLOCK# , ROW_WAIT_ROW# ,
  178.   TOP_LEVEL_CALL#, LOGON_TIME , LAST_CALL_ET , PDML_ENABLED , FAILOVER_TYPE
  179.   , FAILOVER_METHOD , FAILED_OVER, RESOURCE_CONSUMER_GROUP, PDML_STATUS,
  180.   PDDL_STATUS, PQ_STATUS, CURRENT_QUEUE_DURATION, CLIENT_IDENTIFIER,
  181.   BLOCKING_SESSION_STATUS, BLOCKING_INSTANCE, BLOCKING_SESSION,
  182.   FINAL_BLOCKING_SESSION_STATUS, FINAL_BLOCKING_INSTANCE,
  183.   FINAL_BLOCKING_SESSION, SEQ#, EVENT#,EVENT,P1TEXT,P1,P1RAW,P2TEXT,P2,P2RAW,
  184.   P3TEXT,P3,P3RAW,WAIT_CLASS_ID, WAIT_CLASS#,WAIT_CLASS,WAIT_TIME,
  185.   SECONDS_IN_WAIT,STATE,WAIT_TIME_MICRO,TIME_REMAINING_MICRO,
  186.   TIME_SINCE_LAST_WAIT_MICRO,SERVICE_NAME, SQL_TRACE, SQL_TRACE_WAITS,
  187.   SQL_TRACE_BINDS, SQL_TRACE_PLAN_STATS, SESSION_EDITION_ID, CREATOR_ADDR,
  188.   CREATOR_SERIAL#, ECID
  189. from
  190.  GV$SESSION where inst_id = USERENV(\'Instance\')


  193. call count cpu elapsed disk query current rows
  194. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  195. Parse 1 0.01 0.01 0 0 0 0
  196. Execute 0 0.00 0.00 0 0 0 0
  197. Fetch 0 0.00 0.00 0 0 0 0
  198. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  199. total 1 0.01 0.01 0 0 0 0

  201. Misses in library cache during parse: 1
  202. Optimizer mode: CHOOSE
  203. Parsing user id: SYS (recursive depth: 1)
  204. ********************************************************************************

  206. SQL ID: gzp9y42kcbx6m Plan Hash: 644658511

  208. select sid,serial#,username
  209. from
  210.  v$session where username=\'SCOTT\'


  213. call count cpu elapsed disk query current rows
  214. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  215. Parse 1 0.00 0.00 0 0 0 0
  216. Execute 1 0.00 0.00 0 0 0 0
  217. Fetch 2 0.00 0.00 0 0 0 1
  218. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  219. total 4 0.00 0.00 0 0 0 1

  221. Misses in library cache during parse: 1
  222. Optimizer mode: ALL_ROWS
  223. Parsing user id: SYS
  224. Number of plan statistics captured: 1

  226. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  227. ---------- ---------- ---------- ---------------------------------------------------
  228.          1 1 1 NESTED LOOPS (cr=0 pr=0 pw=0 time=231 us cost=0 size=121 card=1)
  229.          1 1 1 NESTED LOOPS (cr=0 pr=0 pw=0 time=2330 us cost=0 size=108 card=1)
  230.          1 1 1 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=1981 us cost=0 size=82 card=1)
  231.          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)
  232.          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)

  234. ********************************************************************************

  236. SQL ID: 3nkd3g3ju5ph1 Plan Hash: 2853959010

  238. select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1,
  239.   spare2
  240. from
  241.  obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
  242.   and linkname is null and subname is null


  245. call count cpu elapsed disk query current rows
  246. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  247. Parse 1 0.00 0.00 0 0 0 0
  248. Execute 4 0.00 0.00 0 0 0 0
  249. Fetch 4 0.00 0.00 0 16 0 4
  250. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  251. total 9 0.00 0.00 0 16 0 4

  253. Misses in library cache during parse: 1
  254. Misses in library cache during execute: 1
  255. Optimizer mode: CHOOSE
  256. Parsing user id: SYS (recursive depth: 1)
  257. Number of plan statistics captured: 1

  259. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  260. ---------- ---------- ---------- ---------------------------------------------------
  261.          1 1 1 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=4 pr=0 pw=0 time=145 us cost=4 size=82 card=1)
  262.          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)

  264. ********************************************************************************

  266. SQL ID: 7ng34ruy5awxq Plan Hash: 2542797530

  268. select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,
  269.   i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,
  270.   i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,
  271.   nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),
  272.   i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),
  273.   nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,
  274.   null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,
  275.   ist.logicalread
  276. from
  277.  ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,
  278.   min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))
  279.   valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where
  280.   i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#


  283. call count cpu elapsed disk query current rows
  284. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  285. Parse 1 0.00 0.00 0 0 0 0
  286. Execute 5 0.00 0.00 0 0 0 0
  287. Fetch 10 0.00 0.00 0 36 0 5
  288. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  289. total 16 0.00 0.00 0 36 0 5

  291. Misses in library cache during parse: 1
  292. Misses in library cache during execute: 1
  293. Optimizer mode: CHOOSE
  294. Parsing user id: SYS (recursive depth: 2)
  295. Number of plan statistics captured: 1

  297. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  298. ---------- ---------- ---------- ---------------------------------------------------
  299.          1 1 1 SORT ORDER BY (cr=8 pr=0 pw=0 time=644 us cost=7 size=372 card=2)
  300.          1 1 1 HASH JOIN OUTER (cr=8 pr=0 pw=0 time=608 us cost=6 size=372 card=2)
  301.          1 1 1 NESTED LOOPS OUTER (cr=5 pr=0 pw=0 time=177 us cost=2 size=286 card=2)
  302.          1 1 1 TABLE ACCESS CLUSTER IND$ (cr=4 pr=0 pw=0 time=100 us cost=2 size=182 card=2)
  303.          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)
  304.          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)
  305.          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)
  306.          0 0 0 VIEW (cr=3 pr=0 pw=0 time=202 us cost=3 size=43 card=1)
  307.          0 0 0 SORT GROUP BY (cr=3 pr=0 pw=0 time=200 us cost=3 size=15 card=1)
  308.          0 0 0 TABLE ACCESS CLUSTER CDEF$ (cr=3 pr=0 pw=0 time=149 us cost=2 size=15 card=1)
  309.          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)

  311. ********************************************************************************

  313. SQL ID: 5n1fs4m2n2y0r Plan Hash: 299250003

  315. select pos#,intcol#,col#,spare1,bo#,spare2,spare3
  316. from
  317.  icol$ where obj#=:1


  320. call count cpu elapsed disk query current rows
  321. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  322. Parse 1 0.00 0.00 0 0 0 0
  323. Execute 5 0.00 0.00 0 0 0 0
  324. Fetch 20 0.00 0.00 0 40 0 15
  325. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  326. total 26 0.00 0.00 0 40 0 15

  328. Misses in library cache during parse: 1
  329. Misses in library cache during execute: 1
  330. Optimizer mode: CHOOSE
  331. Parsing user id: SYS (recursive depth: 2)
  332. Number of plan statistics captured: 1

  334. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  335. ---------- ---------- ---------- ---------------------------------------------------
  336.          1 1 1 TABLE ACCESS BY INDEX ROWID ICOL$ (cr=4 pr=0 pw=0 time=52 us cost=2 size=54 card=2)
  337.          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)

  339. ********************************************************************************

  341. SQL ID: 83taa7kaw59c1 Plan Hash: 3765558045

  343. select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,
  344.   nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,
  345.   scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,
  346.   rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,
  347.   nvl(spare3,0)
  348. from
  349.  col$ where obj#=:1 order by intcol#


  352. call count cpu elapsed disk query current rows
  353. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  354. Parse 1 0.00 0.00 0 0 0 0
  355. Execute 5 0.00 0.00 0 0 0 0
  356. Fetch 31 0.00 0.00 0 16 0 26
  357. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  358. total 37 0.00 0.00 0 16 0 26

  360. Misses in library cache during parse: 1
  361. Misses in library cache during execute: 1
  362. Optimizer mode: CHOOSE
  363. Parsing user id: SYS (recursive depth: 2)
  364. Number of plan statistics captured: 1

  366. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  367. ---------- ---------- ---------- ---------------------------------------------------
  368.          4 4 4 SORT ORDER BY (cr=4 pr=0 pw=0 time=54 us cost=3 size=708 card=12)
  369.          4 4 4 TABLE ACCESS CLUSTER COL$ (cr=4 pr=0 pw=0 time=27 us cost=2 size=708 card=12)
  370.          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)

  372. ********************************************************************************

  374. SQL ID: 3ktacv9r56b51 Plan Hash: 4184428695

  376. select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#,
  377.   nvl(property,0),subname,type#,d_attrs
  378. from
  379.  dependency$ d, obj$ o where d_obj#=:1 and p_obj#=obj#(+) order by order#


  382. call count cpu elapsed disk query current rows
  383. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  384. Parse 2 0.00 0.00 0 0 0 0
  385. Execute 2 0.00 0.00 0 0 0 0
  386. Fetch 12 0.00 0.00 0 27 0 10
  387. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  388. total 16 0.00 0.00 0 27 0 10

  390. Misses in library cache during parse: 1
  391. Misses in library cache during execute: 1
  392. Optimizer mode: CHOOSE
  393. Parsing user id: SYS (recursive depth: 1)
  394. Number of plan statistics captured: 2

  396. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  397. ---------- ---------- ---------- ---------------------------------------------------
  398.          1 5 9 SORT ORDER BY (cr=14 pr=0 pw=0 time=304 us cost=11 size=330 card=3)
  399.          1 5 9 NESTED LOOPS OUTER (cr=14 pr=0 pw=0 time=297 us cost=10 size=330 card=3)
  400.          1 5 9 TABLE ACCESS BY INDEX ROWID DEPENDENCY$ (cr=4 pr=0 pw=0 time=80 us cost=4 size=84 card=3)
  401.          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)
  402.          1 3 5 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=10 pr=0 pw=0 time=157 us cost=2 size=82 card=1)
  403.          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)

  405. ********************************************************************************

  407. SQL ID: 87gaftwrm2h68 Plan Hash: 1218588913

  409. select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname
  410. from
  411.  obj$ o where o.obj#=:1


  414. call count cpu elapsed disk query current rows
  415. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  416. Parse 1 0.00 0.00 0 0 0 0
  417. Execute 1 0.00 0.00 0 0 0 0
  418. Fetch 1 0.00 0.00 0 3 0 1
  419. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  420. total 3 0.00 0.00 0 3 0 1

  422. Misses in library cache during parse: 1
  423. Misses in library cache during execute: 1
  424. Optimizer mode: CHOOSE
  425. Parsing user id: SYS (recursive depth: 2)
  426. Number of plan statistics captured: 1

  428. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  429. ---------- ---------- ---------- ---------------------------------------------------
  430.          1 1 1 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=38 us cost=3 size=82 card=1)
  431.          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)

  433. ********************************************************************************

  435. SQL ID: ga9j9xk5cy9s0 Plan Hash: 1697022209

  437. select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece
  438. from
  439.  idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#


  442. call count cpu elapsed disk query current rows
  443. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  444. Parse 3 0.00 0.00 0 0 0 0
  445. Execute 3 0.00 0.00 0 0 0 0
  446. Fetch 7 0.00 0.00 1 18 0 4
  447. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  448. total 13 0.00 0.00 1 18 0 4

  450. Misses in library cache during parse: 1
  451. Misses in library cache during execute: 1
  452. Optimizer mode: CHOOSE
  453. Parsing user id: SYS (recursive depth: 1)
  454. Number of plan statistics captured: 3

  456. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  457. ---------- ---------- ---------- ---------------------------------------------------
  458.          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)
  459.          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)

  461. ********************************************************************************

  463. SQL ID: cvn54b7yz0s8u Plan Hash: 3246118364

  465. select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece
  466. from
  467.  idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#


  470. call count cpu elapsed disk query current rows
  471. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  472. Parse 3 0.00 0.00 0 0 0 0
  473. Execute 3 0.00 0.00 0 0 0 0
  474. Fetch 6 0.00 0.00 3 20 0 5
  475. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  476. total 12 0.00 0.00 3 20 0 5

  478. Misses in library cache during parse: 1
  479. Misses in library cache during execute: 1
  480. Optimizer mode: CHOOSE
  481. Parsing user id: SYS (recursive depth: 1)
  482. Number of plan statistics captured: 3

  484. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  485. ---------- ---------- ---------- ---------------------------------------------------
  486.          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)
  487.          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)

  489. ********************************************************************************

  491. SQL ID: c6awqs517jpj0 Plan Hash: 1319326155

  493. select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece
  494. from
  495.  idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#


  498. call count cpu elapsed disk query current rows
  499. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  500. Parse 3 0.00 0.00 0 0 0 0
  501. Execute 3 0.00 0.00 0 0 0 0
  502. Fetch 4 0.00 0.01 1 9 0 1
  503. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  504. total 10 0.00 0.01 1 9 0 1

  506. Misses in library cache during parse: 1
  507. Misses in library cache during execute: 1
  508. Optimizer mode: CHOOSE
  509. Parsing user id: SYS (recursive depth: 1)
  510. Number of plan statistics captured: 3

  512. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  513. ---------- ---------- ---------- ---------------------------------------------------
  514.          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)
  515.          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)

  517. ********************************************************************************

  519. SQL ID: 39m4sx9k63ba2 Plan Hash: 2317816222

  521. select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece
  522. from
  523.  idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#


  526. call count cpu elapsed disk query current rows
  527. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  528. Parse 3 0.00 0.00 0 0 0 0
  529. Execute 3 0.00 0.00 0 0 0 0
  530. Fetch 4 0.00 0.00 1 11 0 2
  531. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  532. total 10 0.00 0.01 1 11 0 2

  534. Misses in library cache during parse: 1
  535. Misses in library cache during execute: 1
  536. Optimizer mode: CHOOSE
  537. Parsing user id: SYS (recursive depth: 1)
  538. Number of plan statistics captured: 3

  540. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  541. ---------- ---------- ---------- ---------------------------------------------------
  542.          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)
  543.          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)

  545. ********************************************************************************

  547. SQL ID: 83sp8xb9ytgkv Plan Hash: 0

  549. BEGIN dbms_system.set_ev(21,2615,10046,12,\'SCOTT\'); END;


  552. call count cpu elapsed disk query current rows
  553. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  554. Parse 1 0.00 0.00 0 0 0 0
  555. Execute 1 0.00 0.00 0 0 0 1
  556. Fetch 0 0.00 0.00 0 0 0 0
  557. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  558. total 2 0.00 0.00 0 0 0 1

  560. Misses in library cache during parse: 1
  561. Optimizer mode: ALL_ROWS
  562. Parsing user id: SYS
  563. ********************************************************************************

  565. SQL ID: b1wc53ddd6h3p Plan Hash: 1637390370

  567. select audit$,options
  568. from
  569.  procedure$ where obj#=:1


  572. call count cpu elapsed disk query current rows
  573. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  574. Parse 2 0.00 0.00 0 0 0 0
  575. Execute 2 0.00 0.00 0 0 0 0
  576. Fetch 2 0.00 0.00 0 6 0 2
  577. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  578. total 6 0.00 0.00 0 6 0 2

  580. Misses in library cache during parse: 1
  581. Misses in library cache during execute: 1
  582. Optimizer mode: CHOOSE
  583. Parsing user id: SYS (recursive depth: 1)
  584. Number of plan statistics captured: 2

  586. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  587. ---------- ---------- ---------- ---------------------------------------------------
  588.          1 1 1 TABLE ACCESS BY INDEX ROWID PROCEDURE$ (cr=3 pr=0 pw=0 time=46 us cost=2 size=47 card=1)
  589.          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)

  591. ********************************************************************************

  593. SQL ID: 8swypbbr0m372 Plan Hash: 893970548

  595. select order#,columns,types
  596. from
  597.  access$ where d_obj#=:1


  600. call count cpu elapsed disk query current rows
  601. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  602. Parse 2 0.00 0.00 0 0 0 0
  603. Execute 2 0.00 0.00 0 0 0 0
  604. Fetch 9 0.00 0.00 0 18 0 7
  605. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  606. total 13 0.00 0.00 0 18 0 7

  608. Misses in library cache during parse: 1
  609. Misses in library cache during execute: 1
  610. Optimizer mode: CHOOSE
  611. Parsing user id: SYS (recursive depth: 1)
  612. Number of plan statistics captured: 2

  614. Rows (1st) Rows (avg) Rows (max) Row Source Operation
  615. ---------- ---------- ---------- ---------------------------------------------------
  616.          7 4 7 TABLE ACCESS BY INDEX ROWID ACCESS$ (cr=9 pr=0 pw=0 time=56 us cost=3 size=161 card=7)
  617.          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)




  622. ********************************************************************************

  624. OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

  626. call count cpu elapsed disk query current rows
  627. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  628. Parse 3 0.00 0.00 0 0 0 0
  629. Execute 4 0.01 0.01 0 0 0 1
  630. Fetch 4 0.01 0.01 0 0 0 2
  631. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  632. total 11 0.02 0.03 0 0 0 3

  634. Misses in library cache during parse: 3
  635. Misses in library cache during execute: 2


  638. OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

  640. call count cpu elapsed disk query current rows
  641. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  642. Parse 27 0.03 0.03 0 0 0 0
  643. Execute 61 0.01 0.02 0 0 0 0
  644. Fetch 133 0.01 0.02 6 286 0 103
  645. ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  646. total 221 0.06 0.08 6 286 0 103

  648. Misses in library cache during parse: 16
  649. Misses in library cache during execute: 15

  651.     4 user SQL statements in session.
  652.    27 internal SQL statements in session.
  653.    31 SQL statements in session.
  654. ********************************************************************************
  655. Trace file: HOEGH_ora_16427.trc
  656. Trace file compatibility: 11.1.0.7
  657. Sort options: default

  659.        1 session in tracefile.
  660.        4 user SQL statements in trace file.
  661.       27 internal SQL statements in trace file.
  662.       31 SQL statements in trace file.
  663.       20 unique SQL statements in trace file.
  664.      534 lines in trace file.
  665.      337 elapsed seconds in trace file.


來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/28389881/viewspace-1745592/，如需轉載，請註明出處，否則將追究法律責任。

相關文章