如何做trace 每一步 每一行

Trace的作用

a)        优化sql

b)        跟踪系统动作

                        i.             根据参数追踪，重现出错；

                      ii.             查找运行缓慢的部分；

  Trace文件是我们可以得到的，系统最明细的执行过程，从执行起始，流经的包，过程或函数，传入的参数，具体到每句sql的执行计划，执行时间，执行时间分布。

借助trace文件，我们可以做两部分事情，一是优化：trace可以具体到每句sql的执行计划以及执行时间，可以用来查找哪些sql消耗了最大量的时间；并通过观察执行过程，判断优化方式。Trace文件的第二部分作用，是当系统出现问题时，精确定位出错的sql，根据trace中传入的参数，重现问题，进而分析出错的原因。

 

Trace的一般流程

获取Trace文件路径

select * from v$parameter t WHERE t.NAME='user_dump_dest'

也可以在command窗口使用如下命令

show parameter user_dump_dest；

启动trace

对于Form

帮助-》诊断-》跟踪-》跟踪约束值和等待事件

 

系统将会提示trace文件的位置和文件名称。

 

对于请求(Request)

在请求程序定义的界面中，勾选“启用跟踪”复选框；另外对于请求来说，无法追踪其bind的变量值，也就是生成的trace文件中不包含sql绑定的变量值这一项。

生成的trace文件名:

 

SELECT'Request id: '||REQUEST_ID,

      'Trace id: '||ORACLE_PROCESS_ID,

      'Trace Flag: '||REQ.ENABLE_TRACE,

      'Trace Name:'||DEST.VALUE||'/'||LOWER(DBNM.VALUE)||'_ora_'||

      ORACLE_PROCESS_ID||'.trc',

      'File Name: '||EXECNAME.EXECUTION_FILE_NAME||

      EXECNAME.SUBROUTINE_NAME,

      'Status : '||DECODE(PHASE_CODE,'R','Running')||'-'||

      DECODE(STATUS_CODE,'R','Normal'),

      'SID Serial: '||SES.SID||','||SES.SERIAL#,

      'Module : '||SES.MODULE

 FROMFND_CONCURRENT_REQUESTSREQ,

      V$SESSION              SES,

      V$PROCESS              PROC,

      V$PARAMETER            DEST,

      V$PARAMETER            DBNM,

      FND_CONCURRENT_PROGRAMSPROG,

      FND_EXECUTABLES        EXECNAME

 WHEREREQ.REQUEST_ID=&REQUEST

  ANDREQ.ORACLE_PROCESS_ID=PROC.SPID(+)

  ANDPROC.ADDR=SES.PADDR(+)

  ANDDEST.NAME='user_dump_dest'

  ANDDBNM.NAME='db_name'

  ANDREQ.CONCURRENT_PROGRAM_ID=PROG.CONCURRENT_PROGRAM_ID

  ANDREQ.PROGRAM_APPLICATION_ID=PROG.APPLICATION_ID

  ANDPROG.APPLICATION_ID=EXECNAME.APPLICATION_ID

  ANDPROG.EXECUTABLE_ID=EXECNAME.EXECUTABLE_ID;

 

 

对于OAF

首先确认配置文件”FND:诊断”的值为“是”；

点击页面右上角“诊断”；

Set Trace Level开始;

Trace with binds and waits保存；

 

获取trace文件名：

记录左上角生成的trace id tr_id；

进入用户trace目录；

执行ls –al *tr_id*;

列出了刚生成的trace文件名；

 

使用cmd下载trace文件

Wind+R

Cmd

ftp 10.118.15.217

cd /u01/test/db/tech_st/11.2.0/admin/TEST_tcltest/diag/rdbms/test/TEST/trace

get TEST_vkrm_1626584.trc

--退出

bye

get到的trace文件在这个命令的目录下

lcd

 

分析Trace文件

常用的trace标记

网上搜集了一部分感觉还算比较全。

 

MODULE NAME：如果是request的trace文档，这里会描述请求所运行的并发程序。如果是OAF页面的trace文档，这里会指出页面所使用的Application Module(AM)。

Ex.

a.

*** MODULE NAME:(HCM_REFRESH_SUB_INV) 2010-06-27 09:42:12.406

b.

*** MODULE NAME:(hjit.pobalance.server.PoBalanceAM) 2010-06-27 10:06:37.989

 

PARSING IN CURSOR:每句执行的sql的起始标记，每出现这样一个标记，就代表了一句sql开始被执行了。其中有一个比较重要的信息，是“sqlid”，可以根据这个id找到执行sql的最详细的描述信息。

 

Ex.

PARSING IN CURSOR #6 len=216 dep=1 uid=44 ct=3 lid=44 tim=10801021445054 hv=3104242407 ad='70000007d285380' sqlid='0p5cpqqwhdyr7';

 

这里可以用select t.* FROM v$sql t WHERE t.SQL_ID='0p5cpqqwhdyr7'来查找这句sql的其它明细信息，比如物理读取数，缓存使用数，发生锁的次数，等待时间等。

具体每个参数的含义：

Len：sql的长度；

Dep：当前sql语句的递规深度，如果为0则表示是用户提交的sql，为1则是由于用户sql而导致oracle后台自己执行的sql，为2则是由1级sql继续诱发的下一级sql。

uid：schema user id of parsing user.

oct：oracle command type.

lid：privilege user id.

tim：timestamp。在oracle9i之前单位是1/100秒，9i则是1/1,000,000秒。利用这个值可以计算一个sql执行了到底多长时间。这个值就是当前行被写入trace文件时数据库v$timer视图的值。

hv：hash id.

ad：sqltext address，sqltext的地址，跟v$sqlarea和v$sqltext视图中的address字段值相等。

parse：parse a statement.解析一个sql

exec：execute a pre-parsed statement.执行已经解析完毕的sql

fetch：fetch rows from a cursor.从游标中得到数据，通常指select返回记录

unmap：如果游标使用了临时表（temporary table）,当游标关闭的时候将会看到unmap

c：cpu time (100ths of a second in oracle7 ,8 and 9).

e：elapsed time (100ths of a second oracle7, 8. microseconds in oracle 9 onwards).

p：number of physical reads.

cr：number of buffers retrieved for cr reads.

cu：number of buffers retrieved in current mode.

mis：cursor missed in the cache.

r：number of rows processed.

dep：recursive call depth (0 = user sql, >0 = recursive).

og：optimizer goal: 1=all_rows, 2=first_rows, 3=rule, 4=choose

tim：timestamp (large number in 100ths of a second).

 

 

 

stat #<cursor> id=n cnt=0 [pid=0 pos=0 bj=0 p=sort aggregate ]

 

<cursor>的执行计划.

<cursor>：cursor which the statistics apply to.

id：line of the explain plan which the row count applies to (从1开始).

cnt：number of rows for this row source.

pid：parent id of this row source.

pos：position in explain plan.

obj：object id of row source (if this is a base object).

op：the row source access operation.

 

 

binds #%d:

 

bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 acflg=03 oacfl2=0 size=24 ffset=0

 

bfp=02fedb44 bln=22 avl=00 flg=05

 

value=10

 

bind：variables bound to a cursor.

bind n：the bind position being bound.

dty：data type.

mxl：maximum length of the bind variable (private max len in paren).

mal：array length.

scl：scale.

pre：precision.

oacflg：special flag indicating bind options

oacflg2：continuation of oacflg

size：amount of memory to be allocated for this chunk

offset：offset into this chunk for this bind buffer

bfp：bind address.

bln：bind buffer length.

avl：actual value length (array length too).

flg：special flag indicating bind status

value：the actual value of the bind variable.

 

 

wait #<cursor>: nam="<event name>" ela=0 p1=0 p2=0 p3=0

 

wait：an event that we waited for.

nam：what was being waited for.

ela：elapsed time for the operation.

p1：p1 for the given wait event.

p2：p2 for the given wait event.

p3：p3 for the given wait event.

 

begin :1 := fnd_session_management.GETID(:2,:3);end;

Begin调用某个过程的标记。

 

 

使用tkprof格式化trace文件

Tkprof工具是Oracle用来格式化trace文件，便于我们进行分析。

TKPROF的语法如下所示：

tkprof tracefile output_file [sort = parameters] [print=number]

[explain=username/password] [waits=yes|no] [aggregate=yes|no] [insert=filename]

[sys=yes|no] [table=schema.table] [record=filename]

表6-1 命令行选项

 

变   量	定   义
Tracefile	这就是包含了SQL_TRACE统计信息的TRACE文件名
Output_file	TKPROF写入其输出的文件名
print = number	包含在输出结果中的语句数目。如果没有包含这条语句，TKPROF将在输出中列出所有的语句
Explain = username/password	在TRACE文件里对用户的SQL语句运行EXPLAIN PLAN。这个选项可以创建自己的plan_table，这样用户就需要有创建表和创建表所需空间的特权。在TKPROF运行结束时会删除这个表。确保使用分析光标(运行查询)的用户的用户名/密码，从而确保由正确的用户进行解释。查看Metalink note:199081.1以了解更多信息
insert = filename	这个选项生成脚本来创建表并为每个所跟踪的SQL语句存储TRACE文件统计
record = filename	这个选项将生成一个保存用户所有SQL语句的文件
Sys = yes|no	这个选项可以在输出结果里不显示请求递归SQL语句的用户(由SYS用户执行)。默认值为YES。递归的SQL通常包括由内部调用和表的维护，比如在进行一个插入操作时将扩展添加到表中
sort = parameters	有大量的排序选项可用：FCHCPU(获取的CPU时间)、FCHDSK(获取的硬盘读取)、FCHCU和FCHQRY(获取的内存读取)、FCHROW(取出的行数)、EXEDSK(执行期间的磁盘读取数)；EXECU和EXEQRY(执行期间的内存读取数)、EXEROW(执行时处理的行数)、EXECPU(执行的CPU时间)、PRSCPU(分析CPU)和PRSCNT(分析时间)
waits=yes/no	任何等待事件的记录概要
aggregate=yes/no	如果值为NO，则TKPROF不会组合相同SQL文本的多个用户
table=schema.table	TKPROF在将执行计划写入到输出文件之前临时放置它们的表

 

 

 

注意tkprof的结果是不包含绑定变量值的，同时也不包括真正的sql执行顺序