oracle sql trace与10046浅谈

最新推荐文章于 2022-03-07 16:47:35 发布

congchu6378

最新推荐文章于 2022-03-07 16:47:35 发布

阅读量161

点赞数

什么是sql_trace？
首先我们先看一下什么是sql_trace,顾名思义就是在一个或者多个sql语句在执行时的运行状态，官方文档是这么解释

文档也写的很清楚了，是一个基础的sql性能诊断工具，sql_trace工具可以评估sql语句的执行效率，并且通过TKPROF工具生成易读统计报表，
因为直接生成到trace目录中的信息我们看起来不太直观，所以这里是oracle推荐两个工具一先一后辅助而生。我们这里的环境是11g的，所以
比10g的trace 信息存放目录要多一些，看你自己的输出目录了我存放的是/u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace
可以通过 sql 命令启动 SQL_TRACE ，或者在初始化参数里面，查看官方文档，里面有写

查看当前默认的trace文件是哪一个，用sql语句查询，如下：

SELECT d.VALUE

|| '/'

|| LOWER (RTRIM (i.INSTANCE, CHR (0)))

|| '_ora_'

|| p.spid

|| '.trc'

AS "trace_file_name"

FROM (SELECT p.spid

FROM v$mystat m, v$session s, v$process p

WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,

(SELECT t.INSTANCE

FROM v$thread t, v$parameter v

WHERE v.NAME = 'thread'

AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,

(SELECT VALUE

FROM v$parameter

WHERE NAME = 'user_dump_dest') d;

SQL> SELECT d.VALUE
2 || '/'
|| LOWER (RTRIM (i.INSTANCE, CHR (0)))
|| '_ora_'
|| p.spid
|| '.trc'
AS "trace_file_name"
FROM (SELECT p.spid
FROM v$mystat m, v$session s, v$process p
WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,
(SELECT t.INSTANCE
FROM v$thread t, v$parameter v
WHERE v.NAME = 'thread'
AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,
(SELECT VALUE
FROM v$parameter
WHERE NAME = 'user_dump_dest') d;

trace_file_name
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace/xupeng11g_ora_3276808.trc
知道trace信息放哪了
SQL>alter session set sql_trace=true; 开启当前会话级别的操作，关闭为false

或者

SQL>alter system set sql_trace=true;开启这个数据库层面的很少用到，这样会生成大量的trace信息，没必要而且对数据库运行压力比较大，不推荐

我们用示例来看一下
SQL> alter session set sql_trace=true;
Session altered.

SQL> select * from t;
71176 rows selected.

关闭SQL_TRACE

SQL> alter session set sql_trace=false;

我们去查看trace文件信息，主要包扩了 Parse/Fetch/Execute三个阶段
trace文件头
Trace file /u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace/xupeng11g_ora_5767668.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 = /u01/app/oracle/product/11.2.0/db_1
System name: AIX
Node name: cecgt
Release: 1
Version: 6
Machine: 00CF2CD34C00
Instance name: xupeng11g
Redo thread mounted by this instance: 1
Oracle process number: 19
Unix process pid: 5767668, image: oracle@cecgt (TNS V1-V3)
主要trace信息
=====================
PARSING IN CURSOR #4 len=15 dep=0 uid=0 oct=3 lid=0 tim=6847984458 hv=1134051363 ad='70000017d784f28' sqlid='89km4qj1thh13'
select * from t
END OF STMT
PARSE #4:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=6847984456
EXEC #4:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=6847984589
FETCH #4:c=0,e=86,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2153619298,tim=6847984795
FETCH #4:c=0,e=37,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847985336
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847990552
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847995856
FETCH #4:c=0,e=35,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848001124
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848006350
FETCH #4:c=0,e=44,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848011101
FETCH #4:c=0,e=36,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848015655
.............................

STAT #4 id=1 cnt=71176 pid=0 pos=1 obj=73439 op='TABLE ACCESS FULL T (cr=5703 pr=0 pw=0 time=48516 us cost=280 size=10469396 ca
rd=66262)'
*** 2014-02-11 11:17:43.546
CLOSE #4:c=0,e=27,dep=0,type=0,tim=7281805082
这个文件的可读性要差很多。对这里面的一些参数做些说明：

PARSING IN CURSOR 部分：

Len: 被解析SQL的长度

Dep: 产生递归SQL的深度

Uid：user id

Otc: Oracle command type 命令的类型

Lid: 私有用户id

Tim：时间戳

Hv： hash value

Ad：SQL address

PARSE,EXEC,FETCH 部分

C: 消耗的CPU time

E：elapsed time 操作的用时

P: physical reads 物理读的次数

Cr: consistent reads 一致性方式读取的数据块

Cu：current 方式读取的数据块

Mis：cursor misss in cache 硬分析次数

R: -rows 处理的行数

Dep: depth 递归SQL的深度

Og： optimizer goal 优化器模式

Tim：timestamp时间戳

STATS 部分：

Id: 执行计划的行源号

Cnt：当前行源返回的行数

Pid：当前行源号的父号

Pos：执行计划中的位置

Obj：当前操作的对象id（如果当前行原始一个对象的话）

Op：当前行源的数据访问操作

这种方式对于很少做优化的DBA来说那就看起来比较费劲了，有的人说看AWR报告我说没有必要，你只需要查看一个或者几个，而AWR报告
是从数据库最初的基线到数据库使用周期的性能的评估报告。我们可以使用前面我推荐给大家的工具tkprof来整理一下凌乱的trace文件
下面我介绍什么是TKPROF？
Tkprof 工具是 Oracle 自带的一个工具，用于处理原始的 trace 文件，它的作用主要是合并汇总 trace 文件中的一些项，规范化文件的格式，使文件更具有可读性

注意：tkprof 工具只能用在处理SQL_TRACE和10046事件（下节内容也会提到它）产生的trace，其他事件如10053不能处理。

我们看一下tkprof如何使用，我们可以查官方文档来看一下使用语法

属于操作系统命令，我们运行一下

Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
filename1 是指定的输入文件，可以是多个文件联起来
filename2 是格式化输出文件
SORT 在输出到输出文件前，先进程排序。如果省去，则按照实际使用的顺序输出到文件中。排序选项有以下多种：
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

PRINT        只列出输出文件的第一个integer 的SQL语句。默认为所有的SQL语句。
AGGREGATE    如果= NO ，则不对多个相同的SQL进行汇总。
INSERT       SQL 语句的一种，用于将跟踪文件的统计信息存储到数据库中。在TKPROF创建脚本后，在将结果输入到数据库中。
SYS         禁止或启用将SYS用户所发布的SQL语句列表到输出文件中。
TABLE       在输出到输出文件前，用于存放临时表的用户名和表名。
EXPLAIN     对每条SQL 语句确定其执行规划。并将执行规划写到输出文件中。

其中比较有用的一个排序选项是fchela，即按照elapsed time fetching来对分析的结果排序（记住要设置初始化参数timed_statistics=true），生成的文件将把最消耗时间的sql放在最前面显示。另外一个有用的参数就是sys，这个参数设置为no可以阻止所有以sys用户执行的sql被显示出来，这样可以减少分析出来的文件的复杂度，便于查看。
到这里我们开始使用tkprof来格式化输出一个trace文件，我们用到上面的参数，看自己的需要了我这里用的不多

$ tkprof xupeng11g_ora_5767668.trc xupengtrace.txt sys=no
TKPROF: Release 11.2.0.1.0 - Development on Tue Feb 11 12:44:23 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
$ ls -ltr
total 8584
-rw-r----- 1 oracle oinstall 27698 Feb 11 11:17 xupeng11g_ora_5767668.trm
-rw-r----- 1 oracle oinstall 405360 Feb 11 11:17 xupeng11g_ora_5767668.trc
-rw-r--r-- 1 oracle oinstall 2706 Feb 11 12:44 xupengtrace.txt
$ more xupengtrace.txt
TKPROF: Release 11.2.0.1.0 - Development on Tue Feb 11 12:44:23 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: xupeng11g_ora_5767668.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 4747 0.00 0.16 0 5703 0 71176
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4752 0.00 0.16 0 5703 0 71176
Misses in library cache during parse: 1 #shared pool 中没有命令，说明做了1 次硬解析
Misses in library cache during execute: 1 也执行了一次sql
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS 递归 SQL 语句
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
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: xupeng11g_ora_5767668.trc
Trace file compatibility: 11.1.0.7
Sort options: default
473 elapsed seconds in trace file.
4912 lines in trace file.
3 unique SQL statements in trace file.
3 SQL statements in trace file.
0 internal SQL statements in trace file.
3 user SQL statements in trace file.
1 session in tracefile.
Sort options: default
Trace file compatibility: 11.1.0.7
Trace file: xupeng11g_ora_5767668.trc
********************************************************************************
3 SQL statements in session.
0 internal SQL statements in session.
3 user SQL statements in session.
Misses in library cache during parse: 0
total 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Fetch 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Parse 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
call count cpu elapsed disk query current rows
473 elapsed seconds in trace file.
4912 lines in trace file.
3 unique SQL statements in trace file.
3 SQL statements in trace file.
0 internal SQL statements in trace file.
3 user SQL statements in trace file.
1 session in tracefile.
Sort options: default
Trace file compatibility: 11.1.0.7
Trace file: xupeng11g_ora_5767668.trc
********************************************************************************
3 SQL statements in session.
0 internal SQL statements in session.
3 user SQL statements in session.
Misses in library cache during parse: 0
total 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Fetch 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Parse 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
call count cpu elapsed disk query current rows

tkprof就可以方便我们查看trace信息了！！！有种高端大气上档次的赶脚，哈哈。
下面我们还要谈谈10046事件，sql_trace其实已经包含了 Parse/Fetch/Execute三个阶段，而 10046 比 SQL_TRACE参数提供更多的控制选项，更详细的内容输出，这个才是我们最终
为什么要选择10046事件做sql调优的原因。而且本人也推荐大家两种方法都测试一下，根据你所需要的吧，这里我不进行过多的分析了！我们继续，
10046 trace

10046 trace帮助我们解析一条/多条SQL、PL/SQL语句的运行状态，这些状态包括：Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、CPU时间、执行计划等等。
10046 为我们揭示了一条/多条SQL 的运行情况，对于以点入手的 SQL调优是很好的辅助工具，10046还能帮助我们分析一些 DDL维护命令的内部工作原理， RMAN、Data Pump Expdp/Impdp等工具的缓慢问题等

10046 TRACE的LEVEL:

不同的Level 对应不同的跟踪级别

1 启用标准的SQL_TRACE功能 ( 默认) 包含了 SQL语句、响应时间、服务时间、处理的行数，物理读和写的数目、执行计划以及其他一些额外信息。到版本10.2中执行计划写入到 trace 的条件是仅当相关游标已经关闭时，且与之相关的执行统计信息是所有执行次数的总和数据。到版本11.1中仅在每次游标的第一次执行后将执行计划写入到trace ，执行统计信息仅仅和这第一次执行相关
4 比level 1时多出绑定变量的 trace
8 比level 1多出等待事件，特别对于9i中指出 latch free等待事件很有用，对于分析全表扫描和索引扫描也很有用
12 比level 1 多出绑定变量和等待事件
16 在11g中为每一次执行生成STAT信息，仅在11.1之后可用
32 比level 1少执行计划
64 和level 1 相比在第一次执行后还可能生成执行计划信息；条件是某个游标在前一次执行的前提下运行耗时变长了一分钟。仅在 11.2.0.2中可用
Level 28 (4 + 8 + 16) 代表同时启用 level 4 、level 8、level 16
level 68 ( 64 + 4 ) 代表同时启用 level 64、level 4

设置方法和sql_trace差不多，一条DDL搞定

session 级别：　alter session set events ’10046 trace name context forever,level X’;

system 级别 : alter system set events ’10046 trace name context forever,level X’;
10046 trace 信息也放在和查看sql_trace一样，我们查看放在哪个trace文件上。

我做在做一个示例
SQL> alter session set events '10046 trace name context forever,level 28';
Session altered.

执行一个事务查询
select * from t；
查看trace文件内容
PARSING IN CURSOR #2 len=15 dep=0 uid=0 oct=3 lid=0 tim=15535564761 hv=1134051363 ad='70000017d784f28' sqlid='89km4qj1thh13'
select * from t
END OF STMT
PARSE #2:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=15535564760
EXEC #2:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=15535564873
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535564964
FETCH #2:c=0,e=141,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2153619298,tim=15535565149
WAIT #2: nam='SQL*Net message from client' ela= 467 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535565662
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535565701
FETCH #2:c=0,e=61,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535565752
WAIT #2: nam='SQL*Net message from client' ela= 5257 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535571040
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535571084
FETCH #2:c=0,e=52,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535571126
WAIT #2: nam='SQL*Net message from client' ela= 5228 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535576386
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535576425
FETCH #2:c=0,e=72,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535576487
WAIT #2: nam='SQL*Net message from client' ela= 5382 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535581907
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535581945
FETCH #2:c=0,e=54,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535581989
WAIT #2: nam='SQL*Net message from client' ela= 5166 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535587185
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535587229
Bind#2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7f9ccfec6bd8 bln=22 avl=04 flg=05
我们可以再一次使用tkprof来格式化输出一个文件，方法已经介绍了。我们可以对比一下sql_trace与10046的区别了，10046更加的完善了，
包括变量、WAIT Time等。推荐大家使用10046 trace我们sql_trace和10046就浅谈到这里。后续我会把oradebug工具也推荐给大家，近期
我在整理一下头绪。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/28883355/viewspace-1079466/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/28883355/viewspace-1079466/

congchu6378

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
oracle sql trace与10046浅谈

什么是sql_trace？首先我们先看一下什么是sql_trace,顾名思义就是在一个或者多个sql语句在执行时的运行状态，官方文档是这么解释文档也写的很清楚了，是一个基础...
复制链接

扫一扫