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,结束。

时间: 12-16

SQL_TRACE与tkprof分析的相关文章

Oracle SQL Trace 和 10046 事件

一. 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> alte

经典10046剖析案例-3

执行计划+Hint+统计信息+并行+绑定变量+sql跟踪和10046事件+10053事件总结 执行计划 1.执行计划中的rows表示CBO从一个行源预期获取的记录数,这个行源可能是一个表,也可能是一个索引. 2.rows值对CBO做出正确的执行计划至关重要,如果CBO获取的rows值不准确(通常是没收集统计信息或统计信息过旧导致),在计算执行成本时就会出现偏差,从而制定出错误的执行计划. 3.收集统计信息 exec dbms_stats.gather_table_stats('username'

10046 trace详解(1)

10046 trace帮助我们解析一条/多条SQL.PL/SQL语句的运行状态,这些状态包括:Parse/Fetch/Execute三个阶段中遇到的等待事件.消耗的物理和逻辑读.CPU时间.执行计划等,它为我们揭示了一条.多条SQL的运行情况,对SQL调优是一个非常好的辅助工具,同时还能帮我们分析一些DDL维护命令的内部工作原理,RMAN.Data Pump Expdp/impdp等工具缓慢问题. 记得进公司面试时提到这个一样问题,查看SQL执行计划有哪此方法,10046.PL/SQL F5快捷

03 Files

本章提要-----------------------------------------------组成 oracle 的 8 种主要文件(包括 instance 和 database)instance: parameter file, trace file, alert filedatabase: data file, temp file, control file, redo log file, password file简单概述:parameter file: instance 参数初始

Oracle性能分析3:TKPROF简介

tkprof它是Oracle它配备了一个命令直插式工具,其主要作用是将原始跟踪文件格文本文件的类型,例如,最简单的方法,使用下面的: tkprof ly_ora_128636.trc ly_ora_128636.txt tkprof带有非常多參数,在多数情况下,使用这些參数对你的分析将非常有帮助. tkprof參数 假设不带不论什么參数执行tkprof,它将打印出完整的參数列表,并带有简单的描写叙述.以下是对參数的说明: explain 为每一个SQL语句提供一个运行计划. 该參数须要指定用户.

Oracle性能分析3:TKPROF介绍

tkprof是Oracle自带的一个命令行工具,主要作用是将原始的跟踪文件转换为格式化的文本文件,最简单的使用方式如下: tkprof ly_ora_128636.trc ly_ora_128636.txt tkprof带有很多参数,在多数情况下,使用这些参数对你的分析将很有帮助. tkprof参数 如果不带任何参数运行tkprof,它将打印出完整的参数列表,并带有简单的描述.下面是对参数的说明: explain 为每个SQL语句提供一个执行计划.该参数需要指定用户.密码,也可以指定数据库连接串

SQL_TRACE使用案例

SQL_TRACE主要是为了追踪SQL的执行过程,分析SQL的性能,资源消耗情况. 它可以查看SQL是如何操作处理数据.在执行过程中产生了哪些等待事件,查看sql在执行过程中的资源消耗.可以查看sql的递归语句,是sql的实际执行计划. (1)开启跟踪 跟踪自己的会话很简单 SQL>alter session set tracefile_identifier='mysession'; ---给当前会话一个标示,便于查找跟踪生成的文件 Alter session set sql_trace= tr

ORACLE中seq$表更新频繁的分析

在分析ORACLE的AWR报告时,发现SQL ordered by Executions(记录了按照SQL的执行次数排序的TOP SQL.该排序可以看出监控范围内的SQL执行次数)下有一个SQL语句执行非常频繁,一个小时执行了上万次: update seq$ set increment$=:2, minvalue=:3, maxvalue=:4, cycle#=:5, order$=:6, cache=:7, highwater=:8, audit$=:9, flags=:10 where ob

读懂sql_trace

TKPROF: Release 11.2.0.1.0 - Development on 星期一 11月 3 21:39:41 2014 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. Trace file: c:\orcl_ora_4075.trc Sort options: default **************************************************