Oracle Trace文件生成及查看

目录

Oracle Trace文件生成及查看

Oracle查看trace文件步骤

Oracle-trace文件分析

Trace 文件具体解析

---

转载https://blog.csdn.net/weiwenhp/article/details/6932835

Oracle Trace文件生成及查看

1.Trace file简介:
Trace file（追踪文件)是以trc为后续的文本文件,它记录了各种sql操作及所消耗的时间等,根据trace文件我们就可以了解哪些sql导致了系统的性能瓶颈，进而采取恰当的方式调优.

2.怎么生成trace file:
1. 首先用sqlplus登陆Oracle.

show parameter sql_trace

Name          Type        Value

-------------------------------------------

sql_trace     boolean      false

如果value是false表示系统当前不会产生trace文件.采取如下操作让系统产生trace文件:

alter session set sql_trace=true;

或者:alter system set sql_trace=true;

2.执行一些sql语句后.停止产生trace文件.alter session(或system)  set sql_trace=false.

3.trace文件所在的默认路径.

SELECT VALUE  FROM V$PARAMETER WHERE NAME = 'user_dump_dest'

我本机的查找结果是:C:\ORACLE\PRODUCT\10.2.0\ADMIN\ORA102\UDUMP.

3.怎么更改trace文件的保存目录:
如果是oracle 11g 以下的版本则:

alter system set user_dump_dest = 'd:\oracle\trace';

(注意:trace文件就直接生成在trace目录下)

如果是oracle 11g.则

alter system set user_diagnostic_dest = 'd:\oracle\trace';

(注意:trace文件不会直接生成在trace目录下.trace目录下会生成其他很多目录.

trace文件的具体目录是:d:\oracle\trace\diag\rdbms\orli11r2\orli11r2\trace.其中的orli11r2是SID)

4.怎么查看trace文件:
如果直接看trace文件是很难看懂的.就是下面的样子(我只是随便复制一段):

1319423003070764
=====================
PARSING IN CURSOR #2 len=90 dep=1 uid=0 oct=3 lid=0 tim=1319423003070864 hv=673844243 ad='7ecb9458' sqlid='9g485acn2n30m'
select col#,intcol#,reftyp,stabid,expctoid from refcon$ where obj#=:1 order by intcol# asc
END OF STMTPARSE #2:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2544153582,tim=1319423003070864
BINDS #2: Bind#0oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxs

我们可以用oracle自带的工具TKPROF转化后再查看trace文件.转化后是下面的样子:

SQL ID : 0zzk39z279q41
SELECT version 
FROM
product_component_version WHERE product LIKE 'Oracle%'


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          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 69 

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  VIEW  PRODUCT_COMPONENT_VERSION (cr=0 pr=0 pw=0 time=0 us cost=2 size=168 card=2)
      1   SORT UNIQUE (cr=0 pr=0 pw=0 time=0 us cost=2 size=110 card=2)
      1    UNION-ALL  (cr=0 pr=0 pw=0 time=0 us)
      0     FIXED TABLE FULL X$VERSION (cr=0 pr=0 pw=0 time=0 us cost=0 size=55 card=1)
      1     FIXED TABLE FULL X$VERSION (cr=0 pr=0 pw=0 time=0 us cost=0 size=55 card=1)

********************************************************************************

--------------------- 
作者：聪明的笨蛋 
来源：CSDN 
原文：https://blog.csdn.net/weiwenhp/article/details/6932835 
版权声明：本文为博主原创文章，转载请附上博文链接！

 

Oracle查看trace文件步骤

https://www.2cto.com/database/201210/159305.html

 

1.获得当前trace文件生成路径

SQL> select tracefile from v$process where addr in (select paddr from v$session where sid in (select sid from v$mystat));

 

TRACEFILE  www.2cto.com  

-------------------------------------------------------------------------------------------------------------------------------

f:\oracle\administrator\diag\rdbms\orcl\orcl\trace\orcl_ora_1160.trc

 

2.开启当前session的trace

SQL> alter session set sql_trace=true;

SQL> select count(*) from t1;

 

3.转换trc文件内容为可读的输出结果

 

C:\Documents and Settings\Administrator>tkprof f:\oracle\administrator\diag\rdbm

s\orcl\orcl\trace\orcl_ora_1160.trc output=c:\aa.txt

 

TKPROF: Release 11.2.0.1.0 - Development on 星期六 10月 6 23:51:07 2012

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

 

4.打开c:\aa.txt, 就会看到关于SQL语句 ‘ select count(*) from t1;’ 的执行计划

[sql] 

********************************************************************************  

SQL ID: 5bc0v4my7dvr5  

Plan Hash: 3724264953  

select count(*)  

from    www.2cto.com  

 t1  

  

call     count       cpu    elapsed       disk      query    current        rows  

------- ------  -------- ---------- ---------- ---------- ----------  ----------  

Parse        1      0.00       0.04          0          1          0           0  

Execute      1      0.00       0.00          0          0          0           0  

Fetch        2      0.03       0.01          0       1070          0           1  

------- ------  -------- ---------- ---------- ---------- ----------  ----------  

total        4      0.03       0.06          0       1071          0           1  

  

Misses in library cache during parse: 1  

Optimizer mode: ALL_ROWS  

Parsing user id: 91    

  

Rows     Row Source Operation  

-------  ---------------------------------------------------  

      1  SORT AGGREGATE (cr=1070 pr=0 pw=0 time=0 us)  

  72597   TABLE ACCESS FULL T1 (cr=1070 pr=0 pw=0 time=172543 us cost=298 size=0 card=66014)  

    www.2cto.com  

******************************************************************************** 

Oracle-trace文件分析

https://blog.csdn.net/boer521314/article/details/48734689

Trace 文件具体解析

 

转载https://www.2cto.com/database/201408/326439.html

下面是trace文件中的一个片段，表示一个SQL执行的过程，一个trace文件由很多这样的片段组成：

?

1 2 3 4 5 6 7 8 9 10 11

PARSING IN CURSOR #4 len=135 dep=1 uid=0 oct=3 lid=0 tim=777069789359 hv=1115215392 ad='33e7e384' 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# END OF STMT PARSE #4:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789357 --BINDS #2: EXEC #4:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789415 --WAIT #2: nam='SQL*Net message from client' ela= 143 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=775454461373 FETCH #4:c=0,e=18,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=777069789450 FETCH #4:c=0,e=5,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789477 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=74 op='TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=4 pr=0 pw=0 time=20 us)' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=115 op='INDEX RANGE SCAN I_IDL_CHAR1 (cr=3 pr=0 pw=0 time=12 us)'

以"--"开头是人为添加的，在其它查询中可能存在，下面关键字段的含义：
1）PARSING IN CURSOR和END OF STMT包含了SQL语句文本；
2）PARSE、EXEC和FETCH分别表示解析（parse）、执行（execution）和获取（fetch）调用；
3）BINDS表示绑定变量的定义与值；
4）WAIT表示在处理过程汇总发生的等待事件；
5）STAT表示产生的执行计划以及相关的统计。
下面是更细致的一些解释（来自：Interpreting Raw SQL_TRACE and DBMS_SUPPORTSTART_TRACE output），由于Oracle每个版本都有差异，所以这些内容仅供参考。

-------------------------------------------------------------------------
PARSING IN CURSOR # len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X' 
SQL语句
END OF STMT
--------------------------------------------------------------------------
len：SQL语句长度
dep：游标递归调用的深度
uid：分析SQL的用户ID
oct：ORACLE命令类型
lid：特权用户id
tim：时间抽。ORACLE 9i以前，单位仅仅为1/100秒；ORACLE 9i之后单位为1/1000000秒。时间戳可以用来决定两点之间的时间间隔。该数值取自v$timer中的数值，可以用2个操作的'tim'差决定绝对时间
hv：SQL HASH ID（对应V$SQLAREA视图和V$SQLTEXT视图的HASH_VALUE字段）
ad：SQLTEXT地址（对应V$SQLAREA视图和V$SQLTEXT视图的ADDRESS字段）

--------------------------------------------------------------------------
PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d
SQL语句
--------------------------------------------------------------------------
len：SQL语句长度
dep：游标递归调用的深度
uid：分析SQL的用户ID
oct：ORACLE命令类型
tim：时间抽。同上
err：Oracle错误代码（e.g.ORA-XXXXX）

--------------------------------------------------------------------------
PARSE #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 
EXEC #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 
FETCH #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 
UNMAP #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 
--------------------------------------------------------------------------
操作：
1）PARSE：解析SQL
2）EXEC：执行已经分析的SQL
3）FETCH：从游标中获取记录
4）UNMAP：如果游标使用了临时表，当游标关闭的时候，该操作用来释放临时表资源（释放锁、删除状态对象、释放临时段等）。在tkprof产生的报告中，UNMAP的统计信息加入到EXECUTE操作的统计信息中。
5）SORT UNMAP：如上类似，但是为OS文件排序或者TEMP表段（segment）

c：CPU time（1/100秒在Oracle7、8和9）
e：Elapsed time（1/100秒在Oracle7、8，微秒在Oracle 9和之后版本）
p：物理读（Number of physical reads）
cr：CR（consistent read，一致性读）读的数量
cu：在当前模式（current mode）下读的数量
mis：cursor在缓存中错过的数量
r：涉及的记录数量
dep：递归调用深度（0 = user SQL，>0 = recursive）
og：优化器模式：1=All_Rows,2=First_Rows,3=Rule,4=Choose
tim：时间戳，用于确定两个操作之间的时间

--------------------------------------------------------------------------
ERROR #%d:err=%d tim=%lu
--------------------------------------------------------------------------
一个execution或者tetch错误后的错误展示
err：在堆栈顶的Oracle错误码（例如：ORA-XXXX）
tim：时间戳

--------------------------------------------------------------------------
STAT #<CURSOR> id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE '] 
--------------------------------------------------------------------------
STAT：为<CURSOR>的执行计划统计报告
<CURSOR>：统计应用到的Cursor
id：执行计划中个操作在执行计划树中的编号
cnt：涉及的行数
pid：这行的父id
pos：在执行计划中的位置
obj：行的对象id（如果这是一个基本对象）
op：行涉及的操作

--------------------------------------------------------------------------
XCTEND rlbk=%d rd_only=%d 
--------------------------------------------------------------------------
XCTEND：事务结束标志
rlbk：1表示rollback，0表示commit
rd_only：事务只读则是1，写则是0

注：下面的只有当WAITS或者BINDS出现时才存在

--------------------------------------------------------------------------
BINDS #%d: 
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=24 offset=0
bfp=02fedb44 bln=22 avl=00 flg=05 
value=10 
--------------------------------------------------------------------------
BIND：游标绑定变量

bind N：绑定变量位置
dty：数据类型
mxl：绑定变量最大长度
mal：数组长度
scl：规模（Scale）
pre：进度（precision）
oacflg：表明绑定选项的特定标志
oacfl2：oacflg的延续
size：为这块分配的内存
offset：为这个绑定缓存进入这块的偏移量

bfp：绑定地址
bln：绑定缓存长度
avl：实际值长度（也是数组长度）
flg：表明绑定状态的特定标志
value：绑定变量的实际值

--------------------------------------------------------------------------
WAIT #<CURSOR>: nam="" ela=0 p1=0 p2=0 p3=0 
--------------------------------------------------------------------------
WAIT：等待事件信息
nam：等待事件名称
ela：操作花费的时间
p1：为等待事件提供的参数p1
p2：为等待事件提供的参数p2
p3：为等待事件提供的参数p3

Example (Full Table Scan): 
WAIT #1: nam="db file scattered read" ela= 5 p1=4 p2=1435 p3=25 
WAITing under CURSOR no 1 
for "db file scattered read" 
解读：我们等待0.05秒。为一个读：文件4，开始块1435，共25块 

Example (Index Scan): 
WAIT #1: nam="db file sequential read" ela= 4 p1=4 p2=1224 p3=1 
WAITing under CURSOR no 1 
for "db file sequential read" 
解读：我们等待0.04秒，为单块读（p3=1），从文件4，开始块1224