如何分析oracle trace文件

Posted 2023-04-30

Oracle-trace文件分析
如果一个系统的执行效率比较低，一个比较好的方法是通过跟踪用户的会话并且使用tkprof工具使用排序功能格式化输出，从而找出有问题的SQL语句。
例如首先从os上利用top命令找到当前占用cpu资源最高的一个进程的PID号9999；
然后在数据库中根据PID号找到相应的sid和serial#
select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and p.spid='9999';
然后通过exec dbms_monitor.session_trace_enable(sid,serial#)开启trace；
最后利用tkprof察看trace输出。
开启Trace文件输出
可以通过以下方法开启Trace文件输出（需要ALTER SESSION系统权限）:
1) alter session/system set sql_trace=true
2) exec dbms_monitor.session_trace_enable/dbms_monitor.database_trace_enable
3) alter session set events '10046 trace name context forever, level 12'
Trace文件的位置
· 如果使用专用服务器连接，会在USER_DUMP_DEST参数指定的目录中生成跟踪文件。
· 如果使用共享服务器连接，则在BACKGROUND_DUMP_DEST参数指定的目录中生成跟踪文件。
关于专用服务器/共享服务器->http://blog.csdn.net/fw0124/article/details/6898693

对于DEDICATED方式，Oracle11g之前，可以通过如下语句获得Trace文件路径：
select c.value || '/' || d.instance_name || '_ora_' || a.spid || '.trc' trace
from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.paddr
and b.audsid = userenv('sessionid')
and c.name = 'user_dump_dest'；
Oracle11g之后，可以访问v$diag_info来获得Trace文件存放路径：
select * from v$diag_info where name='Default Trace File';
可以使用参数TRACEFILE_IDENTIFIER，为跟踪文件名增加一个可以惟一标识的串。例如：
alter session set tracefile_identifier='my_trace_file';
这样，生成的Trace文件名就会以my_trace_file.trc结尾。

共享服务器模式下，或者需要跟踪某些特定客户端，可以使用DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE。方法是：
a) sqlplus登陆，exec DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE('mytest');
这里mytest是客户端标示符。
*可以通过select * from DBA_ENABLED_TRACES;查看当前的活动trace。
b) 需要被跟踪的客户端连接执行exec DBMS_SESSION.SET_IDENTIFIER ('mytest');
c) 不需要跟踪的时候可以sqlplus登陆，执行exec DBMS_MONITOR.CLIENT_ID_TRACE_DISABLE('mytest');
d) 到USER_DUMP_DEST目录下执行trcsess output=mytest_trc.txt clientid=mytest，会自动合并各个会话的trace文件，生成mytest_trc.txt
e) 利用tkprof来生成分析报告。

利用tkprof工具分析Trace文件
可以利用tkprof工具分析Trace文件，产生一个更加清晰合理的输出结果。tkprof可以在$ORACLE_HOME/bin下面找到。
1）命令格式
命令格式为：
tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ]
参数说明：
tracefile：要分析的trace文件
outputfile：格式化后的文件
explain=user/password@connectstring
table=schema.tablename
上述两个参数是一起使用的，explain指示tkprof要为在跟踪文件中找到的每个SQL语句提供一个执行计划。
这是通过执行SQL语句EXPLAIN PLAN通过连接数据库对在trace文件中出现的每条sql语句查看执行计划，并将之输出到outputfile中。
指定的table名将提供给EXPLAIN PLAN语句。
print=n：只列出最初N个sql执行语句，默认是无限制的，只有在和参数sort一起使用的时候才有意义
insert=filename：会产生一个sql文件，运行此文件可将收集到的数据insert到数据库表中
sys=no：sys用户运行的SQL语句(例如，解析操作阶段对数据字典的递归查询)不输出到输出文件中。
record=filename：可将非嵌套执行的sql语句过滤到指定的文件中去
waits=yes|no：是否统计任何等待事件，默认是yes
aggregate=yes|no：是否将相同sql语句的执行信息合计起来，默认为yes
sort= option：设置排序选项，可以用逗号分隔多个选项。默认是跟踪文件中发现的SQL顺序。具体选项可以查看tkprof的命令帮助输出得到。
例如：
tkprof <tracefile> <outputfile> sys=no sort=prsela,exeela,fchela
prsela elapsed time parsing
exeela elapsed time executing
fchela elapsed time fetching
2）输出结果格式
输出结果中，首先是头部内容。
之后针对每个SQL语句提供如下信息：SQL 语句文本、执行统计、关于解析的信息、执行计划以及等待事件。
执行计划以及等待事件是可选的，只有存储在跟踪文件中才会出现。
例如下面的输出：
********************************************************************************
SQL ID: 0c07h414zr55p
Plan Hash: 1968341081
update emp set sal=2451
where
empno=7782

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.00 0 0 0 0
Execute 2 0.00 3.71 0 3 7 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 3.72 0 3 7 2
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 86 (TONY)
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE EMP (cr=1 pr=0 pw=0 time=0 us)
1 INDEX UNIQUE SCAN EMP_PK (cr=1 pr=0 pw=0 time=0 us cost=0 size=26 card=1)(object id 73464)

Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
0 UPDATE OF 'EMP'
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'EMP_PK' (INDEX
(UNIQUE))
********************************************************************************
执行统计有如下的几列：
count：表示执行的数据库调用数量。
cpu：表示处理数据调用花去的CPU时间，以秒为单位。
elapsed：是处理数据库调用花费的总的时间，以秒为单位，如果这个值比CPU时间高，下一节关于执行统计中的等待事件会提供在等待的资源或同步点。
disk：表示物理读的数据块数量。要当心，这不是物理I/O操作的数量，物理I/O操作数在关于等待事件一节给出。如果这个值大于逻辑读的数量(disk > query +current)，这意味着数据块填充进了临时表空间。
query：是在一致性模式（consistent mode）下从高速缓存逻辑读取的块数量。通常，这类型的逻辑读用作查询。
current：代表在当前模式下从高速缓存逻辑读取的块数量。通常，这类逻辑读被INSERT、DELETE、MERGE以及UPDATE等语句所使用。
rows：代表处理的数据行数量。对于查询来说，这就是获取的行数量。对于INSERT、DELETE、MERGE以及UPDATE 等语句来说，这是所影响的行数量。
关于解析的信息开始两行Misses in library cache during parse和Misses in library cache during execute提供了发生在解析和执行调用阶段的硬解析数量。
如果在执行调用时没有硬解析发生，Misses in library cache during execute这一行将不存在。
接下来是优化器模式以及用于解析SQL语句的用户。
执行计划分为两部分，第一部分称为行源操作(Row Source Operation )，是游标关闭且开启跟踪情况下写到跟踪文件中的执行计划。这意味着如果应用程序不关闭游标而重用它们的话，不会有新的针对重用游标的执行计划写入到跟踪文件中。第二部分，叫做执行计划 (Execution Plan)，是由指定了explain参数的TKPROF生成的。既然这是随后生成的，所以和第一部分不一定完全匹配。万一你看到不一致，前者是正确的。
两个执行计划都通过Rows列提供执行计划中每个操作返回的行数（不是处理的--要注意）。
对于每个行源操作来说，可能还会提供如下的运行时统计：
cr是一致性模式下逻辑读出的数据块数。
pr是从磁盘物理读出的数据块数。
pw是物理写入磁盘的数据块数。
time是以微秒表示的总的消逝时间。要注意根据统计得到的值不总是精确的。实际上，为了减少开销，可能用了采样。
cost是操作的评估开销。这个值只有在Oracle 11g才提供。
size是操作返回的预估数据量(字节数)。这个值只有在Oracle 11g才提供。
card是操作返回的预估行数。这个值只有在Oracle 11g才提供。
输出文件的结尾给出了所有关于跟踪文件的信息。首先可以看到跟踪文件名称、版本号、用于这个分析所使用的参数sort的值。然后，给出了所有会话数量与SQL语句数量。 参考技术A alert日志里面主要看数据库里面发生的一些重大错误。
10046主要看执行sql语句的执行过程，以及相关的绑定变量、等待事件等。
10053主要看执行计划，以及优化器的选择过程。
常见的也就这三种。

SQL_TRACE与tkprof分析

一. SQL_TRACE

当SQL语句出现性能问题时，我们可以用SQL_TRACE来跟踪SQL的执行情况，通过跟踪，我们可以了解一条SQL或者PL/SQL包的运行情况，SQL_TRACE命令会将SQL执行的整个过程输出到一个trace文件中，我们可以读这个trace 文件来了解在这个SQL执行过程中Oracle 都做了哪些操作。

 

可以通过sql命令启动SQL_TRACE，或者在初始化参数里面。

 

SQL>alter session set sql_trace=true;

或者

SQL> alter database set sql_trace=true;

 

这两条命令的区别：

在session级别设置，只对当前session进行跟踪，在实例级别，会对实例上所有的SQL做跟踪，这种方式跟踪的SQL太多，代价是非常大的，所有很少用。

 

如果是在初始化文件里面设置，只需要在参数文件里添加一个sql_trace 参数即可。

 

 

示例：

1 sql命令启动SQL_TRACE

SQL> alter session set sql_trace=true;

Session altered.

2 通过设置trace 文件标识

SQL> alter session set tracefile_identifier=‘andy‘;

Session altered.

 

设置标识的目的就是方便我们查找生成的trace文件。我们只需要在trace目录查找文件名里带有标识的文件即可。 在Oracle 10g中，SQL_TRACE生成的trace文件默认路劲是$ORACLE_BASE/admin/SID/udump.

到了11g，trace 默认路径在：$ORACLE_BASE/diag/rdbms/orcl/orcl/trace目录下.

 

3. 直接用如下SQL直接查出，当前的trace文件名。

SQL> select * from v$diag_info where name like ‘Default%‘;

INST_ID NAME
---------- ----------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
1 Default Trace File
/home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc

4. 进行相关事务操作

SQL> select * from t;

 

5. 关闭SQL_TRACE

SQL> alter session set sql_trace=false;

会话已更改。

 

注意，这里是显示的关闭SQL_TRACE，在session级别，也可以直接退出SQLPLUS来终止SQL_TRACE。

 

——————————————————————————————————————

6. 查看trace 文件（原始查看方式，即不使用tkprof工具查看）

如果想确切的知道SQL 语句的每一步执行是如果操作的，就需要分析原始的trace文件。 这个trace 虽然没有tkprof工具处理之后易读，但是却能够清楚的知道SQL在那个点做了什么，以及SQL是如何工作的，这对与理解SQL语句的执行过程非常有用。

 

直接打开 /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc文件：

 

T[[email protected] ~]$ vi /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc

Trace file /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /home/oracle/app/oracle/product/11.2.0/dbhome_1
System name: Linux
Node name: 11g
Release: 2.6.32-573.el6.x86_64
Version: #1 SMP Thu Jul 23 15:44:03 UTC 2015
Machine: x86_64
Oracle process number: 19
Unix process pid: 24020, image: [email protected] (TNS V1-V3)

。。。。。省略输出

*** 2014-11-17 08:06:08.981
CLOSE #1:c=0,e=14,dep=0,type=1,tim=1416229568981377
=====================
PARSING IN CURSOR #1 len=23 dep=0 uid=0 oct=3 lid=0 tim=1416229568981763 hv=665675061 ad=‘87d2dfb0‘ sqlid=‘ckyh1gcmuut9p‘
select * from dba_users
END OF STMT
PARSE #1:c=0,e=291,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3422547789,tim=1416229568981762
EXEC #1:c=0,e=135,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3422547789,tim=1416229568981961
FETCH #1:c=4000,e=3231,p=0,cr=52,cu=0,mis=0,r=1,dep=0,og=1,plh=3422547789,tim=1416229568985261
FETCH #1:c=0,e=67,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=3422547789,tim=1416229568985934
FETCH #1:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=3422547789,tim=1416229569004724
FETCH #1:c=0,e=83,p=0,cr=1,cu=0,mis=0,r=4,dep=0,og=1,plh=3422547789,tim=1416229569022491
STAT #1 id=1 cnt=35 pid=0 pos=1 obj=0 op=‘HASH JOIN (cr=54 pr=0 pw=0 time=0 us cost=26 size=2664 card=12)‘
STAT #1 id=2 cnt=35 pid=1 pos=1 obj=0 op=‘HASH JOIN (cr=49 pr=0 pw=0 time=0 us cost=24 size=2436 card=12)‘
STAT #1 id=3 cnt=35 pid=2 pos=1 obj=0 op=‘HASH JOIN (cr=34 pr=0 pw=0 time=34 us cost=18 size=2316 card=12)‘
STAT #1 id=4 cnt=35 pid=3 pos=1 obj=0 op=‘HASH JOIN OUTER (cr=19 pr=0 pw=0 time=68 us cost=13 size=2196 card=12)‘
STAT #1 id=5 cnt=35 pid=4 pos=1 obj=0 op=‘HASH JOIN (cr=16 pr=0 pw=0 time=0 us cost=10 size=1740 card=12)‘
STAT #1 id=6 cnt=35 pid=5 pos=1 obj=0 op=‘HASH JOIN (cr=13 pr=0 pw=0 time=136 us cost=8 size=1620 card=12)‘
STAT #1 id=7 cnt=2 pid=6 pos=1 obj=0 op=‘MERGE JOIN CARTESIAN (cr=6 pr=0 pw=0 time=1 us cost=4 size=26 card=1)‘
STAT #1 id=8 cnt=1 pid=7 pos=1 obj=280 op=‘TABLE ACCESS FULL PROFILE$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=13 card=1)‘
STAT #1 id=9 cnt=2 pid=7 pos=2 obj=0 op=‘BUFFER SORT (cr=3 pr=0 pw=0 time=1 us cost=2 size=13 card=1)‘
STAT #1 id=10 cnt=2 pid=9 pos=1 obj=280 op=‘TABLE ACCESS FULL PROFILE$ (cr=3 pr=0 pw=0 time=1 us cost=2 size=13 card=1)‘
STAT #1 id=11 cnt=35 pid=6 pos=2 obj=22 op=‘TABLE ACCESS FULL USER$ (cr=7 pr=0 pw=0 time=102 us cost=3 size=3597 card=33)‘
STAT #1 id=12 cnt=2 pid=5 pos=2 obj=281 op=‘TABLE ACCESS FULL PROFNAME$ (cr=3 pr=0 pw=0 time=1 us cost=2 size=10 card=1)‘
STAT #1 id=13 cnt=2 pid=4 pos=2 obj=297 op=‘TABLE ACCESS FULL RESOURCE_GROUP_MAPPING$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=38 card=1)‘
STAT #1 id=14 cnt=8 pid=3 pos=2 obj=16 op=‘TABLE ACCESS FULL TS$ (cr=15 pr=0 pw=0 time=105 us cost=5 size=80 card=8)‘
STAT #1 id=15 cnt=8 pid=2 pos=2 obj=16 op=‘TABLE ACCESS FULL TS$ (cr=15 pr=0 pw=0 time=14 us cost=5 size=80 card=8)‘
STAT #1 id=16 cnt=9 pid=1 pos=2 obj=292 op=‘TABLE ACCESS FULL USER_ASTATUS_MAP (cr=5 pr=0 pw=0 time=0 us cost=2 size=171 card=9)‘

 

这个文件的可读性要差很多。 对这里面的一些参数做些说明：

 

PARSING IN CURSOR 部分： PARSE,EXEC,FETCH 部分 STATS 部分：

Len: 被解析SQL的长度 C: 消耗的CPU time Id: 执行计划的行源号
Dep: 产生递归SQL的深度 E：elapsed time 操作的用时 Cnt：当前行源返回的行数

Uid：user id P: physical reads 物理读的次数 Pid：当前行源号的父号

Otc: Oracle command type 命令的类型 Cr: consistent reads 一致性方式读取的数据块 Pos：执行计划中的位置

Lid: 私有用户id Cu：current 方式读取的数据块 Obj：当前操作的对象id（如果当前行原始一个对象的话）

Tim：时间戳 Mis：cursor misss in cache 硬分析次数 Op：当前行源的数据访问操作

Hv： hash value R: -rows 处理的行数

Ad：SQL address Dep: depth 递归SQL的深度

Og： optimizer goal 优化器模式

Tim：timestamp时间戳

 

二． TKPROF 工具

 

 

SQL_TRACE 生成最原始的trace文件的可读性比较差，所以通常我们使用tkprof 工具来处理trace文件。 Tkprof 工具是Oracle 自带的一个工具，用于处理原始的trace文件，它的作用主要是合并汇总trace文件中的一些项，规范化文件的格式，使文件更具有可读性。

 

注意：tkprof 工具只能用在处理SQL_TRACE和10046事件产生的trace，其他事件如10053不能处理。

 

Tkprof 是系统级别的，直接在系统下执行即可。先看一下tkprof的帮助文档：

[[email protected] ~]$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename Use ‘schema.tablename‘ with ‘explain=‘ option.
explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.
print=integer List only the first ‘integer‘ SQL statements.
aggregate=yes|no
insert=filename List SQL statements and data inside INSERT statements.
sys=no TKPROF does not list SQL statements run as user SYS.
record=filename Record non-recursive statements found in the trace file.
waits=yes|no Record summary for any wait events found in the trace file.
sort=option Set of zero or more of the following sort options:
prscnt number of times parse was called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor

 

这个帮助对tkprof工具的参数做了说明。

 

2.1 explain=user/password

在trace文件中输入SQL的执行计划，需要注意的是，如果不使用explain，在trace 文件中我们看到的是SQL实际的执行路劲（过程）。 如果使用了explain，tkprof在trace文件中不但输入SQL的实际执行路径(过程)，还会生成该SQL的执行计划。

 

2.2 sys=no

如果设置为yes，在trace 文件中将输入所有的SYS用户的操作，也包含用户SQL语句引发的递归SQL。

如果为no，则不输出这些信息。不过默认情况下是yes，实际上设置为no后，trace文件具有更佳的可读性，因此一般在用tkprof工具时都手工的把该参数设置为no。

2.3 aggregate=yes|no

默认情况下，tkprof工具将所有相同的SQL在输入文件中做合并，如果设置为no，则分别列出每个SQL的信息。一般合并后看起来比较简洁，如果需要查看每一个SQL单独的信息，可以把aggregate设置为no。

 

2.4 用tkprof工具查看中生成的trace文件

[[email protected] ~]$ tkprof /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc andy.txt sys=no

[[email protected] ~]$ vi andy.txt

TKPROF: Release 11.2.0.1.0 - Development on Mon Nov 17 08:25:36 2014

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

Trace file: /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.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

 

********************************************************************************
## 以上文件头信息描述了tkprof的版本信息，以及报告中一些列的含义

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS #非递归SQL语句

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.03 0 54 0 36
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11 0.00 0.03 0 54 0 36

Misses in library cache during parse: 0

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 #shared pool 命中，说明做了0次硬解析。

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.

Misses in library cache during parse: 0

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

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace file: /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc
Trace file compatibility: 11.1.0.7
Sort options: default

1 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 unique SQL statements in trace file.
71 lines in trace file.
1719 elapsed seconds in trace file.

ok,结束。