*************************************************************
1.开启10046
*************************************************************
SQL> oradebug setmypid
Statement processed.
// 激活 10046 事件
SQL> oradebug event 10046 trace name context forever,level 12;
Statement processed.
SQL> select count(*) from scott.tblorders;
COUNT(*)
----------
167
// 在当前 session 关闭 10046 事件
SQL> oradebug event 10046 trace name context off;
Statement processed.
// 使用 oradebug tracefile_name 可以直接看到生成的 trace 文件的位置
SQL> oradebug tracefile_name;
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc
*************************************************************
2.直接读取文件
*************************************************************
----------------------trace文件内容
Trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1
System name: Linux
Node name: timesten.ocp.com
Release: 2.6.32-431.el6.x86_64
Version: #1 SMP Fri Nov 22 03:15:09 UTC 2013
Machine: x86_64
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 20
Unix process pid: 2551, image: [email protected] (TNS V1-V3)
*** 2015-02-10 17:34:40.127
*** SESSION ID:(132.9911) 2015-02-10 17:34:40.127
*** CLIENT ID:() 2015-02-10 17:34:40.127
*** SERVICE NAME:(SYS$USERS) 2015-02-10 17:34:40.127
*** MODULE NAME:([email protected] (TNS V1-V3)) 2015-02-10 17:34:40.127
*** ACTION NAME:() 2015-02-10 17:34:40.127
Processing Oradebug command 'setmypid'
*** 2015-02-10 17:34:40.127
Oradebug command 'setmypid' console output: <none>
*** 2015-02-10 17:34:48.483
Processing Oradebug command 'event 10046 trace name context forever,level 12'
*** 2015-02-10 17:34:48.484
Oradebug command 'event 10046 trace name context forever,level 12' console output: <none>
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560888484461
*** 2015-02-10 17:35:09.044
WAIT #0: nam='SQL*Net message from client' ela= 20559954 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560909044435
=====================
PARSING IN CURSOR #140199425457600 len=37 dep=0 uid=0 oct=3 lid=0 tim=1423560909045924 hv=2120411436 ad='28d609c60' sqlid='23uhtxpz65u9c'
select count(*) from scott.tblorders
END OF STMT
PARSE #140199425457600:c=1000,e=1393,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1853518045,tim=1423560909045922
EXEC #140199425457600:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1853518045,tim=1423560909046084
WAIT #140199425457600: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560909046130
FETCH #140199425457600:c=0,e=99,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=1853518045,tim=1423560909046258
STAT #140199425457600 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=110 us)'
STAT #140199425457600 id=2 cnt=167 pid=1 pos=1 obj=89045 op='INDEX FULL SCAN PK_ORDERID (cr=1 pr=0 pw=0 time=76 us cost=1 size=0 card=167)'
WAIT #140199425457600: nam='SQL*Net message from client' ela= 148 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560909046527
FETCH #140199425457600:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1853518045,tim=1423560909046560
WAIT #140199425457600: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560909046581
*** 2015-02-10 17:35:27.589
WAIT #140199425457600: nam='SQL*Net message from client' ela= 18543034 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560927589630
CLOSE #140199425457600:c=0,e=10,dep=0,type=0,tim=1423560927589767
*** 2015-02-10 17:35:27.589
Processing Oradebug command 'event 10046 trace name context off'
*** 2015-02-10 17:35:27.590
Oradebug command 'event 10046 trace name context off' console output: <none>
*** 2015-02-10 17:35:35.918
Processing Oradebug command 'tracefile_name'
*** 2015-02-10 17:35:35.918
Oradebug command 'tracefile_name' console output:
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc
***************************解释******************************************************
第1部分:parse(解析)
PARSING IN CURSOR #140199425457600 len=37 dep=0 uid=0 oct=3 lid=0 tim=1423560909045924 hv=2120411436
ad='28d609c60' sqlid='23uhtxpz65u9c'
cursor cursor number
len sql 语句长度
dep sql 语句递归深度
uid user id
oct oracle command type
lid privilege user id
tim timestamp，时间戳
hv hash id
ad sql address 地址, 用在 v$sqltext
sqlid sql id
第2部分:exec(执行)
PARSE #140199425457600:c=1000,e=1393,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1853518045,tim=1423560909045922
EXEC #140199425457600:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1853518045,tim=1423560909046084
c CPU 消耗的时间
e Elapsed time
p number of physical reads 物理读的次数
cr number of buffers retrieved for CR reads 逻辑读的数据块
cu number of buffers retrieved in current mode (current 模式读取的数据块)
mis cursor missed in the cache 库缓存中丢失的游标, 硬解析次数
r number of rows processed 处理的行数
dep 递归深度
og optimizer mode 【1：all_rows, 2：first_rows, 3：rule, 4：choose】
plh plan hash value
tim timestamp 时间戳
第3部分:执行过程中的发生的等待事件
WAIT #0: nam='SQL*Net message from client' ela= 20559954 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560909044435
nam an event that we waited for 等待事件
ela 此操作消耗的时间
p3 block 块号
trm timestamp 时间戳
第4部分:该游标的执行计划
STAT #140199425457600 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=110 us)'
STAT #140199425457600 id=2 cnt=167 pid=1 pos=1 obj=89045 op='INDEX FULL SCAN PK_ORDERID
(cr=1 pr=0 pw=0 time=76 us cost=1 size=0 card=167)'
cnt 当前行源返回的行数
pid parent id of this row source 当前行源的父结点 id
pos position in explain plan 执行计划的位置
obj object id of row source (if this is a base object)
op the row source access operation
******************************************************************************************************************************************************************
*************************************************************
3.使用 tkprof 命令翻译 trace 文件
*************************************************************
tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc ./test.trc
TKPROF: Release 11.2.0.4.0 - Development on 星期二 2月 10 17:47:28 2015
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.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: 23uhtxpz65u9c Plan Hash: 1853518045
select count(*)
from
scott.tblorders
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 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 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 SORT AGGREGATE (cr=1 pr=0 pw=0 time=110 us)
167 167 167 INDEX FULL SCAN PK_ORDERID (cr=1 pr=0 pw=0 time=76 us cost=1 size=0 card=167)(object id 89045)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 18.54 18.54
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
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 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 0 1
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 20.55 39.10
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
1 user SQL statements in session.
0 internal SQL statements in session.
1 SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
1 user SQL statements in trace file.
0 internal SQL statements in trace file.
1 SQL statements in trace file.
1 unique SQL statements in trace file.
66 lines in trace file.
0 elapsed seconds in trace file.
时间： 2024-10-26 10:29:50