前往小程序，Get更优阅读体验！
立即前往
文档建议反馈控制台
首页
学习
活动
专区
工具
TVP
最新优惠活动
文章/答案/技术大牛
发布
首页
学习
活动
专区
工具
TVP最新优惠活动
返回腾讯云官网
社区首页 >专栏 >SQL调优和诊断工具之SQL Trace （10046 Event）介绍

SQL调优和诊断工具之SQL Trace （10046 Event）介绍

作者头像
SQLplusDB
发布于 2022-08-19 21:41:35
6100
发布于 2022-08-19 21:41:35
举报
文章被收录于专栏：Oracle数据库技术Oracle数据库技术

概述

为了诊断SQL性能或者其他方面的问题，有时我们需要跟踪SQL语句和的执行过程，这时我们可以启用SQL Trace （10046 Event）来收集语句的执行过程和各种相关信息。

本章将介绍SQL Trace （10046 Event）的基本内容和一些有用的信息。

基本的取得方法

首先，让我们看一下，在会话级别取得10046 Trace的基本方法：

代码语言：javascript
复制
SQL>connect username/password


SQL>----设置Trace名的标识符，以便更容易找到Trace文件----
SQL>alter session set tracefile_identifier='10046';


SQL>----设置一些环境变量，以便更加准确的出力Trace内容----
SQL>alter session set timed_statistics = true;
SQL>alter session set statistics_level=all;
SQL>alter session set max_dump_file_size = unlimited;


SQL>alter session set events '10046 trace name context forever, level 12';


SQL>----执行调查对象sql----
SQL>select * from dual;

可以用以下命令关闭trace:

代码语言：javascript
复制
SQL>alter session set events '10046 trace name context off';

需要注意的是，在11g之前，由于执行计划信息STAT的记录方式不同，可能因为游标没有被关掉或者是在跟踪PL/SQL执行的时候，而丢失一些重要的信息，例如执行计划，统计时间等，因此，为了避免这种情况，可以通过退出当前session来关闭Trace。

代码语言：javascript
复制
例：
SQL>exit

SQL Trace （10046 ）的设置等级

对于Event 10046可以设置的等级以及各等级对应的出力信息介绍如下：

代码语言：javascript
复制
1 - 标准的SQL跟踪信息 ( SQL_TRACE 默认设置)
4 - 1的信息加上绑定变量信息 [ bind=true ]
8 - 1的信息加上等待信息 [ wait=true ]
16 - 对于SQL每次执行都记录执行计划信息STAT [ plan_stat=all_executions ]
32 - 不记录执行计划信息STAT [ plan_stat=never ]
64 - 自动判断是否记录执行计划信息STAT [ plan_stat=adaptive ]

※上面括号内为sql_trace对应的设置方法：

代码语言：javascript
复制
例如：
alter session set events 'sql_trace wait=false, bind=true';'

※等级16和32在11g以后有效，等级64在11.2.0.2以后有效。

※等级64自动判断是否记录执行计划信息，基本上只针对大于1分钟的高消费SQL记录不同执行计划信息。

根据收集信息不同，可以将以上的等级累加，如等级12=4 + 8，记录的内容即为：标准的SQL跟踪信息+绑定变量信息+等待信息

特定场景下打开跟踪的方法

跟踪已经存在的会话

如果需要跟踪一个已经存在session，可以用 oradebug连接到session上，并发起10046 trace。

1.首先，找出目标session的OS的进程ID(spid):

代码语言：javascript
复制
select p.PID,p.SPID,s.SID
from v$process p,v$session s
where s.paddr = p.addr
and s.sid = &SESSION_ID
/

※SPID 是操作系统的进程标识符（os pid）; PID 是Oracle的进程标识符(ora pid)

2.然后，根据spid或者PID用以下命令初始化跟踪：

代码语言：javascript
复制
connect / as sysdba
ALTER SESSION SET tracefile_identifier = '10046';
oradebug setospid <SPID> ；--或者 oradebug setorapid <PID>；
oradebug unlimit
oradebug event 10046 trace name context forever,level 12；

3.跟踪过程完成以后，通过以下命令关闭oradebug跟踪：

代码语言：javascript
复制
oradebug event 10046 trace name context off；

限定范围跟踪

DBMS_MONITOR在Oracle 10g版本以后，退出了DBMS_MONITOR程序包，用于限定跟踪范围。

下面将对这个程序包中主要的几个方法进行介绍。

查看设定

对于通过DBMS_MONITOR程序包设定的Trace，可以通过DBA_ENABLED_TRACES视图来查看。

代码语言：javascript
复制
SQL> desc DBA_ENABLED_TRACES
Name
-------------------
TRACE_TYPE ：Trace的类型，如：CLIENT_ID、SERVICE、SERVICE_MODULE、SERVICE_MODULE_ACTION、DATABASE
PRIMARY_ID ：client identifier 或 service name
QUALIFIER_ID1 ：module name
QUALIFIER_ID2 ：action name
WAITS ：是否收集等待信息
BINDS ：是否收集绑定变量信息
PLAN_STATS ：执行计划统计
INSTANCE_NAME ：实例名

参考：

代码语言：javascript
复制
    Database Reference
    >DBA_ENABLED_TRACES
    https://docs.oracle.com/database/121/REFRN/GUID-DAD89975-BFBE-458B-B887-342153C83313.htm#REFRN23395

针对特殊操作取得SQL Trace （10046 ）

DBMS_MONITOR有很多的方法，例如通过serv_mod_act_trace_enable方法可以针对某特殊动作进行跟中。

例：

在调查MMON 进程Auto-Purge Slave Action操作相关的问题时，可以通过如下方法针对Auto-Purge Slave Action操作取得10046 trace。

代码语言：javascript
复制
--设定前确认
SQL> select trace_type, primary_id, qualifier_id1, waits, binds from DBA_ENABLED_TRACES;
no rows selected

--设定10046 trace
SQL> exec dbms_monitor.serv_mod_act_trace_enable -
(service_name=>'SYS$BACKGROUND',-
module_name=>'MMON_SLAVE',-
action_name=>'Auto-Purge Slave Action',-
waits => true, -
binds => true);
> > > > >
PL/SQL procedure successfully completed.

--设定后确认
SQL> set line 180
SQL> col PRIMARY_ID format a20
SQL> col QUALIFIER_ID1 format a20
SQL> col QUALIFIER_ID1 format a20
SQL> select trace_type, primary_id, qualifier_id1, waits, binds
from DBA_ENABLED_TRACES; 2

TRACE_TYPE PRIMARY_ID QUALIFIER_ID1 WAITS BINDS
--------------------- -------------------- -------------------- ----- -----
SERVICE_MODULE_ACTION SYS$BACKGROUND MMON_SLAVE TRUE TRUE

--解除10046 trace
SQL> execute dbms_monitor.serv_mod_act_trace_disable-
(service_name=>'SYS$BACKGROUND',-
module_name=>'MMON_SLAVE',-
action_name=>'Auto-Purge Slave Action');> > 

PL/SQL procedure successfully completed.
--设定后确认
SQL> select trace_type, primary_id, qualifier_id1, waits, binds
from DBA_ENABLED_TRACES; 2
no rows selecte
SQL>

DBMS_MONITOR的其他方法和信息，可参考以下文档：

代码语言：javascript
复制
    Database PL/SQL Packages and Types Reference
    >99 DBMS_MONITOR

    Database SQL Tuning Guide
    >18 Performing Application Tracing

跟踪某个特定的SQL ID

Oracle 11g以后的版本，可以通过以下的方法来跟踪某个特定的SQL ID。

代码语言：javascript
复制
--启用10046Trace
alter system set events 'sql_trace[sql: <sql_id> | <sql_id> | <sql_id> ]';
--禁用10046Trace
alter system set events 'sql_trace[sql: <sql_id> | <sql_id> | <sql_id> ] off';

具体取得方法对某个<SQL_ID：sql:gcaxax8tgmjvt>进行跟踪：

代码语言：javascript
复制

SQL> alter session set tracefile_identifier='10046';
SQL> alter session set max_dump_file_size = unlimited;
---启用Trace
SQL> ALTER SESSION SET EVENTS 'sql_trace [sql:gcaxax8tgmjvt] bind=true,wait=true';
SQL> --<操作执行> --
---停止Trace
SQL> ALTER SESSION SET EVENTS 'sql_trace [sql:gcaxax8tgmjvt] off';

对多个SQL ID如<SQL_ID：sql:gcaxax8tgmjvt>进行跟踪：

代码语言：javascript
复制
SQL> alter session set tracefile_identifier='10046';
SQL> alter session set max_dump_file_size = unlimited;
---启用Trace
SQL> ALTER SESSION SET EVENTS 'sql_trace [sql:gcaxax8tgmjvt| g2mjrzx0w5ysv ]';
SQL> --<操作执行> --
---停止Trace
SQL> ALTER SESSION SET EVENTS 'sql_trace[sql:gcaxax8tgmjvt| g2mjrzx0w5ysv ] off';

SQL Trace （10046 ） 的整形

可以通过tkprof 命令对SQL Trace （10046）进行整形，以便查看。

tkprof 的命令详细如下：

代码语言：javascript
复制
$ 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

Trace （10046 ） 的取得例

以下是一个非常简单的的SQL Trace （10046 ） 的取得例子，供参考。

取得SQL Trace （10046 ）

代码语言：javascript
复制
--取得SQL Trace （10046 ）
[oracle@db12102 ~]$ sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Sun Aug 21 11:30:51 2016
Copyright (c) 1982, 2014, Oracle. All rights reserved.

Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

SQL> alter session set tracefile_identifier='10046';
Session altered.

SQL> alter session set timed_statistics = true;
Session altered.

SQL> alter session set statistics_level=all;
Session altered.

SQL> alter session set max_dump_file_size = unlimited;
Session altered.

SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.

SQL> select * from dual;
D
-
X

SQL> alter session set events '10046 trace name context off';
Session altered.

SQL> show parameter diagnostic_dest

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
diagnostic_dest string /u01/app/oracle
SQL>

```

SQL Raw Trace （10046 ）

以下为SQL Raw Trace （10046 ）的输出内容。

代码语言：javascript
复制
[oracle@db12102 trace]$ cat ora12102_ora_26882_10046.trc
Trace file /u01/app/oracle/diag/rdbms/ora12102/ora12102/trace/ora12102_ora_26882_10046.trc
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/12.1.0/dbhome_1
System name: Linux
Node name: db12102
Release: 2.6.18-308.el5
Version: #1 SMP Fri Jan 27 17:17:51 EST 2012
Machine: x86_64
Instance name: ora12102
Redo thread mounted by this instance: 1
Oracle process number: 7
Unix process pid: 26882, image: oracle@db12102 (TNS V1-V3)




*** 2016-08-21 11:32:14.640
*** SESSION ID:(237.46022) 2016-08-21 11:32:14.640
*** CLIENT ID:() 2016-08-21 11:32:14.640
*** SERVICE NAME:(SYS$USERS) 2016-08-21 11:32:14.640
*** MODULE NAME:(sqlplus@db12102 (TNS V1-V3)) 2016-08-21 11:32:14.640
*** CLIENT DRIVER:(SQL*PLUS) 2016-08-21 11:32:14.640
*** ACTION NAME:() 2016-08-21 11:32:14.640


WAIT #47885029118040: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=449 tim=1471746734640573


*** 2016-08-21 11:32:25.255
WAIT #47885029118040: nam='SQL*Net message from client' ela= 10614226 driver id=1650815232 #bytes=1 p3=0 obj#=449 tim=1471746745255088
CLOSE #47885029118040:c=0,e=11,dep=0,type=1,tim=1471746745255243
=====================
PARSING IN CURSOR #47885029112104 len=18 dep=0 uid=0 oct=3 lid=0 tim=1471746745259301 hv=942515969 ad='89d59510' sqlid='a5ks9fhw2v9s1'
select * from dual
END OF STMT
PARSE #47885029112104:c=2000,e=4010,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=272002086,tim=1471746745259299
WAIT #47885029112104: nam='Disk file operations I/O' ela= 42 FileOperation=8 fileno=0 filetype=8 obj#=449 tim=1471746745259450
EXEC #47885029112104:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1471746745259525
WAIT #47885029112104: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=449 tim=1471746745259575
FETCH #47885029112104:c=0,e=78,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=272002086,tim=1471746745259708
STAT #47885029112104 id=1 cnt=1 pid=0 pos=1 obj=142 op='TABLE ACCESS FULL DUAL (cr=3 pr=0 pw=0 time=60 us cost=2 size=2 card=1)'
WAIT #47885029112104: nam='SQL*Net message from client' ela= 310 driver id=1650815232 #bytes=1 p3=0 obj#=449 tim=1471746745262481
FETCH #47885029112104:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=272002086,tim=1471746745262552
WAIT #47885029112104: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=449 tim=1471746745262591


*** 2016-08-21 11:32:39.983
WAIT #47885029112104: nam='SQL*Net message from client' ela= 14720836 driver id=1650815232 #bytes=1 p3=0 obj#=449 tim=1471746759983492
CLOSE #47885029112104:c=0,e=10,dep=0,type=0,tim=1471746759983595
=====================
PARSING IN CURSOR #47885029160720 len=55 dep=0 uid=0 oct=42 lid=0 tim=1471746759983811 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #47885029160720:c=0,e=144,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1471746759983790
WAIT #47885029160720: nam='Disk file operations I/O' ela= 36 FileOperation=8 fileno=0 filetype=8 obj#=449 tim=1471746759983906
EXEC #47885029160720:c=0,e=210,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1471746759984142

TKPROF整形

代码语言：javascript
复制
[oracle@db12102 trace]$ tkprof ora12102_ora_26882_10046.trc 10046.out


TKPROF: Release 12.1.0.2.0 - Development on Sun Aug 21 11:35:57 2016


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




TKPROF整形结果[oracle@db12102 trace]$ cat 10046.out


TKPROF: Release 12.1.0.2.0 - Development on Sun Aug 21 11:35:57 2016


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


Trace file: ora12102_ora_26882_10046.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: a5ks9fhw2v9s1 Plan Hash: 272002086


select *
from
dual




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


Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS FULL DUAL (cr=3 pr=0 pw=0 time=60 us cost=2 size=2 card=1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 14.72 14.72
***************************************************************************
…
***************************************************************************
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 2 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 3 0 1


Misses in library cache during parse: 1


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 14.72 25.33
Disk file operations I/O 2 0.00 0.00




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: ora12102_ora_26882_10046.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.
52 lines in trace file.
14 elapsed seconds in trace file.
本文参与?腾讯云自媒体分享计划，分享自微信公众号。
原始发表：2021-05-17，如有侵权请联系?cloudcommunity@tencent.com 删除
sql
oracle

本文分享自 SQL和数据库技术 微信公众号，前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与?腾讯云自媒体分享计划? ，欢迎热爱写作的你一起参与！

sql
oracle
评论
登录后参与评论
0 条评论
热度
最新
登录 后参与评论
推荐阅读
LV.
文章
0
获赞
0
领券

腾讯云开发者

扫码关注腾讯云开发者

扫码关注腾讯云开发者

领取腾讯云代金券

热门产品

热门推荐

更多推荐

Copyright ? 2013 - 2024 Tencent Cloud. All Rights Reserved. 腾讯云 版权所有?

深圳市腾讯计算机系统有限公司 ICP备案/许可证号：粤B2-20090059?深公网安备号 44030502008569

腾讯云计算（北京）有限责任公司 京ICP证150476号 | ?京ICP备11018762号 | 京公网安备号11010802020287

问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档

Copyright ? 2013 - 2024 Tencent Cloud.

All Rights Reserved. 腾讯云 版权所有

登录 后参与评论
http://www.vxiaotou.com