Oracle 事件跟踪优化SQL实例之（一）—SQL_TRACE功能

2023年11月21日 420点热度 0人点赞 0条评论

一、SQL_TRACE的功能分析
- 1、SQL_TRACE功能：
- 2、SQL_TRACE使用方法：
二、sql_trace内容跟踪1—对当前会话启用sql_trace跟踪
三、sql_trace内容跟踪2—对其他会话启用sql_trace跟踪
四、案例分析
- 1、查看跟踪文件
- 2、精简信息
五、案例分析2

Oracle 事件跟踪优化SQL实例之（一）——SQL_TRACE功能

一、SQL_TRACE的功能分析

1、SQL_TRACE功能：

Oracle这个功能主要是为了追踪SQL的执行过程，分析SQL的性能，资源消耗情况。

--查看SQL是如何操作处理数据
--查看SQL在执行过程中产生了的等待事件
--查看SQL的执行过程资源消耗
--查看SQL的实际执行计划
--查看SQL的递归语句
--如果要探索SQL如何执行的可以详细看看

2、SQL_TRACE使用方法：

使用SQL_TRACE对其它会话进行跟踪。

如果对当前会话进行跟踪只需alter session set sql_trace=true;即可，如果对其它会话进行跟踪还需要设置另外一些参数。

alter session set sql_trace=true;
select * from test;

二、sql_trace内容跟踪1—对当前会话启用sql_trace跟踪

1、查看当前会话的跟踪文件

（1）方法1：

oradebug setmypid
oradebug tracefile_name
获得：/oracle/app/oracle/diag/rdbms/mesorcl/mesorcl/trace/mesorcl_ora_12438.trc

（2）方法2：通过下述语句获取当前session的trc跟踪文件：

select * from v$diag_info where name like 'Default Trace File';

2、执行sql跟踪

alter session set sql_trace=true;

3、执行sql语句

select * from test;

4、查看上述tracefile_name获取到的文件

less /oracle/app/oracle/diag/rdbms/mesorcl/mesorcl/trace/mesorcl_ora_12438.trc

三、sql_trace内容跟踪2—对其他会话启用sql_trace跟踪

1、获取需要跟踪的会话ID及serial#

--获取当前会话sid:

select distinct sid from v$mystat;

--获取已知sid的serial#

select sid,serial# from v$session where sid in (144,12);

2、关于为什么需要sid和serial#同时定位一个会话？

SID NUMBER：    Sessionidentifier   就是会话标识
SERIAL# NUMBER：是用来标识唯一一个会话操作对象的，保证这个会话发出的命令可以正确的应用到对应的会话对象上。

一个会话的结束和另一个会话开始都使用了同一个SID，区分这是2个不同的会话。

如果只是看SID我们不能分辨出是谁登录了会话操作了各自的对象，而serial可以分辨出不同会话的命令正确应用到对应的对象上，区分这是2个不同的客户端登录的会话。

3、获取其他会话的跟踪

--获取需要跟踪会话A输出到的跟踪文件x.trc
--获取会话A的sid和serial#（通过v$mystat和v$session获得）
--在跟踪者（一般是sys）的会话B下打开跟踪
--在会话A下执行各种sql命令
--在跟踪者（一般是sys）的会话B下关闭跟踪
--查看x.trc内容

4、查看跟踪

（1）获取需要跟踪会话的跟踪文件

oradebug setmypid
oradebug tracefile_name
或：
select * from v$diag_info where name like 'Default Trace File';

获得：/oracle/app/oracle/diag/rdbms/mesorcl/mesorcl/trace/mesorcl_ora_12438.trc

（2）获取其他会话的sid和serial#

15:52:57 TEST@mesorcl>select sid,serial# from v$session where sid=223;

  SID       SERIAL#
---------- ----------
   223      11933

（3）打开跟踪

SYS@mesorcl>execute sys.dbms_system.set_sql_trace_in_session(223,11933,true);

（4）被监控的会话执行sql

16:17:30 TEST@mesorcl>select count(*) from test;
16:18:15 TEST@mesorcl>select * from test where id=1;

（5）关闭跟踪

SYS@mesorcl>execute sys.dbms_system.set_sql_trace_in_session(223,11933,false);

（6）查看跟踪

注意：

less /oracle/app/oracle/diag/rdbms/mesorcl/mesorcl/trace/mesorcl_ora_12438.trc

四、案例分析

1、查看跟踪文件

*** 2023-11-21 16:05:41.372
CLOSE #139637997544800:c=6,e=6,dep=0,type=0,tim=1700553941372792
PARSE #139637996959904:c=31,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700553941372941
EXEC #139637996959904:c=21,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700553941372990
FETCH #139637996959904:c=60,e=60,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1700553941373131
FETCH #139637996959904:c=11,e=11,p=0,cr=3,cu=0,mis=0,r=3,dep=0,og=1,plh=1357081020,tim=1700553941373283

*** 2023-11-21 16:05:45.660
CLOSE #139637996959904:c=8,e=8,dep=0,type=3,tim=1700553945660826
PARSE #139637996959904:c=20,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700553945660923
EXEC #139637996959904:c=19,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700553945660958
FETCH #139637996959904:c=33,e=34,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1700553945661035
FETCH #139637996959904:c=9,e=9,p=0,cr=3,cu=0,mis=0,r=3,dep=0,og=1,plh=1357081020,tim=1700553945661202

*** 2023-11-21 16:06:03.958
CLOSE #139637996959904:c=11,e=11,dep=0,type=3,tim=1700553963958698
PARSE #139637996959904:c=39,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700553963958828
EXEC #139637996959904:c=19,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700553963958867
FETCH #139637996959904:c=34,e=33,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1700553963958944
FETCH #139637996959904:c=20,e=19,p=0,cr=3,cu=0,mis=0,r=3,dep=0,og=1,plh=1357081020,tim=1700553963959148

使用的是139637996959904号游标，PARSE #139637996959904解析-> EXEC #139637996959904执行-> FETCH #139637996959904 取操作-> CLOSE #139637996959904关闭游标

这个原始trace文件内容比较多，不是很好看，需要花很多时间来斟酌，如果想详细了解SQL整个执行过程的话可以慢慢研究一下。下面我们来看用tkprof工具汇总的精简版report

2、精简信息

[oracle@qdmes219:/oracle/app/oracle/diag/rdbms/mesorcl/mesorcl/trace]$tkprof mesorcl_ora_8617.trc test2.log sys=no

sys=no参数表示过滤掉sys用户生成的递归语句，这样可以精简出比较好看的报告

TKPROF: Release 11.2.0.4.0 - Development on Tue Nov 21 16:19:14 2023

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

Trace file: mesorcl_ora_8617.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
********************************************************************************

SQL ID: 7b2twsn8vgfsc Plan Hash: 1950795681

select count(*) 
from
test

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 2 0.00 0.00 0 6 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 6 0 1

Misses in library cache during parse: 1  --这条语句也做了1次硬解析
Optimizer mode: ALL_ROWS
Parsing user id: 107 
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=6 pr=0 pw=0 time=44 us)
4 4 4 TABLE ACCESS FULL TEST (cr=6 pr=0 pw=0 time=34 us cost=3 size=0 card=4)

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

SQL ID: f5ug8jqf4msr1 Plan Hash: 1357081020

select * 
from
test where id=1


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

Misses in library cache during parse: 1   --这条语句也做了1次硬解析
Optimizer mode: ALL_ROWS
Parsing user id: 107 
Number of plan statistics captured: 1

Rows (1st)   Rows (avg) Rows (max)        Row Source Operation  --这个行源操作，就是SQL实际的执行过程
----------  ---------- ---------- ---------------------------------------------------
1               1        1          TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=25 us cost=3 size=9 card=1)


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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.00 0 13 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.00 0 13 0 2

Misses in library cache during parse: 2  --一共做了2次硬解析


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: mesorcl_ora_8617.trc
Trace file compatibility: 11.1.0.7
Sort options: default

0 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.
40 lines in trace file.
172 elapsed seconds in trace file.

五、案例分析2

1、创建大表（35w）

create table test4 as select * from dba_objects;
insert into test4 select * from test4;
insert into test4 select * from test4;
select count(*) from test4;

COUNT(*)
----------
349908

2、跟踪分析

（1）启动sql_trace跟踪

alter session set sql_trace=true;

（2）查询数据

select count(*) from (select * from test4 order by object_id) a,(select * froml test4 order by object_id) b where a.object_id=b.object_id;

（3）关闭sql_trace跟踪

alter session set sql_trace=false;

（4）查看当前会话跟踪文件

select name,value from v$diag_info where name='Default Trace File';

（5）分析日志

*** 2023-11-23 08:42:44.144
CLOSE #140128552815512:c=34,e=34,dep=0,type=0,tim=1700700164144111
=====================
PARSING IN CURSOR #140128552815512 len=136 dep=0 uid=107 oct=3 lid=107 tim=1700700164144382 hv=3110610344 ad='17188bce0' sqlid='acfumcuwqh9d8'
select count(*) from (select * from test4 order by object_id) a,(select * from test4 order by object_id) b where a.object_id=b.object_id
END OF STMT
PARSE #140128552815512:c=141,e=140,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4197062170,tim=1700700164144380
EXEC #140128552815512:c=64,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4197062170,tim=1700700164144494
FETCH #140128552815512:c=304304,e=304305,p=0,cr=10056,cu=0,mis=0,r=1,dep=0,og=1,plh=4197062170,tim=1700700164448882
STAT #140128552815512 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=10056 pr=0 pw=0 time=304306 us)'
STAT #140128552815512 id=2 cnt=1399632 pid=1 pos=1 obj=0 op='HASH JOIN (cr=10056 pr=0 pw=0 time=686872 us cost=3750 size=33488338 card=1288013)'
STAT #140128552815512 id=3 cnt=349908 pid=2 pos=1 obj=97599 op='TABLE ACCESS FULL TEST4 (cr=5028 pr=0 pw=0 time=34855 us cost=1376 size=5456607 card=419739)'
STAT #140128552815512 id=4 cnt=349908 pid=2 pos=2 obj=97599 op='TABLE ACCESS FULL TEST4 (cr=5028 pr=0 pw=0 time=32651 us cost=1376 size=5456607 card=419739)'
FETCH #140128552815512:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4197062170,tim=1700700164450275

说明：使用的是4号游标，这个游标号是可以重用的，这个游标指向的是我们执行的SQL产生的递归语句（红色部分），它是把对象属性写入数据字典中进行登记，好为以后的应用做语法语义校验的

PARSING IN CURSOR部分
len=136                代表每个跟踪事件的长度，以字节为单位。
                         -"len"
                         -"len"记录了SQL Trace在跟踪过程中获取的每个事件的数据长度，包括SQL语句、查询结果、统计信息等。
                         这些事件的长度信息可以用于分析跟踪日志的大小、优化跟踪的开销，以及确定跟踪过程中是否存在特定的数据交换或通信问题。
dep=1                  表示SQL语句中的深度，指示SQL语句的嵌套层级——递归的SQL深度，1层递归
uid=107                 表示用户ID，标识执行该SQL语句的用户——用户id 107代表test用户
oct=3                  表示Oracle会话的字符编码类型。——oracle commend type命令类型
lid=107                 表示语言ID，标识会话所使用的语言类型。——私有用户id 107也代表test用户
tim=1360643355379273   表示当前时间戳——也就是语句的开始时间，可以获取解析SQL语句所花费的时间，单位为微秒——时间戳
hv=1384619666          表示哈希值（Hash Value），用于标识语句在共享池中的位置——have value  SQL的哈希值
ad='7f537b20'          表示Address，即语句的物理地址，用于在共享池中查找语句的位置——SQL address  SQL的地址

STAT部分
id=1                   表示统计信息的标识符或索引；——执行计划的行源号，每一层都有一个号，从上往下1/2/3/4排列
cnt=1                  表示统计信息的计数值；——当前行源号返回的行数
pid=0                  表示与该统计信息相关联的父对象的标识符，通常用于标识对象之间的层级关系；
                       ——行源号的父号，如果当前行源号是4父号就是3  是1父号就是0，这也标识了执行计划的执行顺序4 -> 3 -> 2 -> 1
obj=74154              表示与该统计信息相关联的对象的标识符或名称；——当前操作的对象id

（6）耗费时间计算：

PARSING IN CURSOR的时间戳：1700700164144382 

FECH获取后的时间戳：1700700164450275

两者的时间差为：1700700164450275-1700700164144382/1000/1000=0.305893s

有此方式，也可以计算出STAT部分的等待时间/或者直接查看TIME时间也可以获取。

具体参数的含义可能因Oracle数据库的版本和配置而有所不同。根据具体的版本和文档，还可以获得更详细的参数含义和用途。

需要注意的是，解析过程中的统计信息可以提供有关SQL语句解析性能的相关指标，如解析次数、解析时间等。

这些统计信息对于性能分析和优化非常有价值，可以帮助识别潜在的性能问题并采取相应的调整措施。

3、参数整体含义

（1）第一部分整体trace概览含义

PARSING IN CURSOR #47019101509648 len=24 dep=0 uid=0 oct=3 lid=0 tim=1477908470545403 hv=911793802 ad='74c73648' sqlid='f6hhpzwv5jrna'

cursor	cursor number
len	sql 语句长度
dep	sql 语句递归深度
uid	user id
oct	oracle command type
lid	privilege user id
tim	timestamp，时间戳
hv	hash id
ad	sql address 地址, 用在 v$sqltext
sqlid	sql id

（2）第二部分SQL具体执行过程以及CPU等性能指标含义

PARSE #47019101509648:c=33995,e=65940,p=14,cr=62,cu=0,mis=1,r=0,dep=0,og=1,plh=3383998547,tim=1477908470545401
EXEC #47019101509648:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1477908470545479
FETCH #47019101509648:c=0,e=510,p=6,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3383998547,tim=1477908470546076
FETCH #47019101509648:c=0,e=36,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3383998547,tim=1477908470546841

c	CPU 消耗的时间
e	Elapsed time
p	number of physical reads 物理读的次数
cr	number of buffers retrieved for CR reads 逻辑读的数据块
cu	number of buffers retrieved in current mode (current 模式读取的数据块)
mis	cursor missed in the cache 库缓存中丢失的游标, 硬解析次数
r	number of rows processed 处理的行数
dep	递归深度
og	optimizer mode 【1：all_rows, 2：first_rows, 3：rule, 4：choose】
plh	plan hash value
tim	timestamp 时间戳

（3）第三部分执行过程中发生的等待含义

WAIT #47019101509648: nam='SQL*Net message from client' ela= 644 driver id=1650815232 #bytes=1 p3=0 obj#=87106 tim=1477908470546764

nam	an event that we waited for 等待事件
ela	此操作消耗的时间
p3	block 块号
trm	timestamp 时间戳

（4）第四部分游标执行计划含义

STAT #47019101509648 id=1 cnt=4 pid=0 pos=1 obj=87106 op='TABLE ACCESS FULL DEPT (cr=7 pr=6 pw=0 time=498 us cost=3 size=80 card=4)'

cnt	当前行源返回的行数
pid	parent id of this row source 当前行源的父结点 id
pos	position in explain plan 执行计划的位置
obj	object id of row source (if this is a base object)
op	the row source access operation

上述逻辑读为7，物理读为6，消耗时间为498us，消耗3，返回记录大小80B，记录数4

本作品采用知识共享署名 4.0 国际许可协议进行许可