sql 跟踪

1：启用标准的SQL_TRACE功能 ( 默认) 包含了 SQL语句、响应时间、服务时间、处理的行数，物理读和写的数目、执行计划以及其余一些额外信息。到版本10.2中执行计划写入到 trace 的条件是仅当相关游标已经关闭时，且与之相关的执行统计信息是全部执行次数的总和数据。到版本11.1中仅在每次游标的第一次执行后将执行计划写入到trace ，执行统计信息仅仅和这第一次执行相关

4：比level 1时多出绑定变量的 trace

8 ：比level 1多出等待事件

16：在11g中为每一次执行生成STAT信息，仅在11.1以后可用

32：比level 1少执行计划，在11.1之后可用

64：和level 1 相比在第一次执行后还可能生成执行计划信息；条件是某个游标在前一次执行的前提下运行耗时变长了一分钟。仅在 11.2.0.2中可用

其余补充

level 12（4+8）表明同事启用level 四、level8

Level 28 (4 + 8 + 16) 表明同时启用 level 4 、level 八、level 16

level 68 ( 64 + 4 ) 表明同时启用 level 6四、level 4

最经常使用的跟踪模式level 12

1.1 alter session

开启跟踪

alter session set sql_trace=true，至关level 1；

建议采用10046在指定如，启用

ALTER SESSION SET events '10046 trace name context forever, level 12'；

关闭

ALTER SESSION SET events '10046 trace name context off'；

整个数据库启用跟踪，session级别调整system就能够了。

1.2 DBMS_MONITOR

oracle 10g数据库提供dbms_monitor包，你能够启用和禁用sql跟踪。还有一些扩展的跟踪属性：

client identifier, service name, module name, action name，没有独立会话，采用链接池的模式，就没法指定具体的sessionid

使用dbms_MOINTOR包，你不能直接指定10046事件的级别，替换有三个参数能够配置。默认级别是8

level 4：对应 binds =true
level 8：对应wait=true
level 16：plan_stat=all_executions
level 32: plan_stat=nerver
level 64: 不支持

session level处理

能够确认跟踪哪一个会话的

本会话

SQL> EXEC DBMS_MONITOR.session_trace_enable;
SQL> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable;

其余会话

开启：dbms_monitor.session_trace_enable(session_id => 127,serial_num => 29,waits => TRUE,binds => FALSE,plan_stat => 'first_execution')

plan_stat：默认null相等于first_execution

SELECT sql_trace, sql_trace_waits, sql_trace_binds, sql_trace_plan_stats FROM v$session WHERE sid = 127;

禁用：dbms_monitor.session_trace_disable(session_id => 127,serial_num => 29)

客户端级别

没法经过单一的会话来处理，client_ID能够经过程序或者PL/SQL来指定

PL/SQL:dbms_session.set_identifier(client_id => 'helicon.antognini.ch');

dbms_monitor.client_id_trace_enable(client_id => 'helicon.antognini.ch',waits => TRUE,binds => TRUE,plan_stat => 'first_execution')

client_id来源于：V$SESSION.CLIENT_IDENTIFIER，是区分大小写的

能够经过视图来查看开启的状况

SELECT primary_id AS client_id, waits, binds, plan_stats FROM dba_enabled_traces  WHERE trace_type = 'CLIENT_ID';

禁用：dbms_monitor.client_id_trace_disable(client_id => 'helicon.antognini.ch')

组件级别

service_name 、module_name、action_name能够经过程序或者PL/SQL来指定

PL/SQL:

dbms_application_info.set_module(module_name => 'mymodule',
action_name => 'myaction');

dbms_monitor.serv_mod_act_trace_enable(service_name => 'DBM11203.antognini.ch',module_name => 'mymodule',
action_name => 'myaction',waits => TRUE,binds => TRUE,instance_name => NULL,plan_stat => 'all_executions')

service_name 、module_name、action_name:来源V$SESSION

查询开启的状况
SELECT primary_id AS service_name, qualifier_id1 AS module_name,
 qualifier_id2 AS action_name, waits, binds, plan_stats
 FROM dba_enabled_traces
 WHERE trace_type IN ('SERVICE', 'SERVICE_MODULE', 'SERVICE_MODULE_ACTION');

禁用：dbms_monitor.serv_mod_act_trace_disable(service_name => 'DBM11203.antognini.ch',module_name => 'mymodule',
action_name => 'myaction',instance_name => NULL)

数据库级别

dbms_monitor.database_trace_enable(waits => TRUE,binds => TRUE,instance_name => 'DBM11203',plan_stat => 'first_execution')

查看开启状况

SELECT instance_name, waits, binds, plan_stats FROM dba_enabled_traces WHERE trace_type = 'DATABASE';

禁用：dbms_monitor.database_trace_disable(instance_name => 'DBM11203')

1.3 DBMS_SESSION

在oracle 10g以前，DBMS_MONTITOR是不能使用的，能够采用DBMS_SESSION包来处理，并且有限制只能是本身的会话

BEGIN
dbms_session.session_trace_enable(waits => TRUE,
binds => TRUE,
plan_stat => 'all_executions');
END;
 /

SELECT sql_trace, sql_trace_waits, sql_trace_binds, sql_trace_plan_stats
FROM v$session
WHERE sid = sys_context('userenv','sid');

BEGIN
dbms_session.session_trace_disable;
END;
/

1.4 oradebug模式

oradebug 须要SYSDBA权限，本身平常测试处理比较方便

本会话
CONN sys/password AS SYSDBA;
ORADEBUG SETMYPID;
ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
--输出跟踪文件路径
ORADEBUG TRACEFILE_NAME;
ORADEBUG EVENT 10046 TRACE NAME CONTEXT OFF;

其余会话
--能够指定OS pid对应v$process.spid
ORADEBUG SETOSPID 1234;
--或者指定oracle processid 对应v$process.pid
ORADEBUG SETORAPID 123456;
ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
--输出跟踪文件路径
ORADEBUG TRACEFILE_NAME;
ORADEBUG EVENT 10046 TRACE NAME CONTEXT OFF;

1.5 触发器的模式启用sql 跟踪

针对个别用户的所有会话都要开启跟踪，能够新增一个角色，建立一个登陆的触发器来处理

CREATE ROLE sql_trace;
CREATE OR REPLACE TRIGGER enable_sql_trace AFTER LOGON ON DATABASE
BEGIN
IF (dbms_session.is_role_enabled('SQL_TRACE'))
THEN
EXECUTE IMMEDIATE 'ALTER SESSION SET timed_statistics = TRUE';
EXECUTE IMMEDIATE 'ALTER SESSION SET max_dump_file_size = unlimited';
dbms_session.session_trace_enable;
END IF;
END;

1.6 跟踪文件中时间信息

cpu、实时时间记录到跟踪文件中，都需timed_statistics 设置为true，默认是true。调整的方式

ALTER SESSION SET timed_statistics = TRUE

1.7 跟踪文件限制大小

跟踪文件的大小经过max_dump_file_size这个参数，默认值unlimited，若是是其余值的话，建议调整为默认值

ALTER SESSION SET max_dump_file_size = 'unlimited'

1.8 查找跟踪文件

SELECT
        pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||
        '_ora_' || p.spid || '.trc' AS trace_file
 FROM   v$session s,
        v$process p,
        v$parameter pa
 WHERE  pa.name = 'user_dump_dest'
 AND    s.paddr = p.addr
 AND    s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');

11g之后也能够采用

SELECT value
 FROM v$diag_info
 WHERE name = 'Default Trace File';

oradebug模式的，能够直接采用oradebug tracefile_name;

2 跟踪内容说明

打开跟踪内容，相似如下的输出，仍是不容易查看

PARSING IN CURSOR 到 END OF STMT是sql 文本的内容

PARSE,EXEC,FETCH,CLOSE分别对应是解析、执行、获取、关闭调用

BINGS:对应的是绑定变量

WAIT：表示的具体的等待事件

STAT:表示执行计划

了解详细的细节，能够参考：

3 TKPROF使用

tkprof能够格式化跟踪文件，查看问题的友好性

使用方法:

tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ]

参数详细说明：

tracefile：跟踪文件路径

outputfile：输出的文件路径

explain=user/password 使用哪一个用户连接数据库，发出explain plan

table=schema.tablename 配合explain一块儿使用

print=integer 是整数，只是罗列前多少个sql语句

aggregate=yes|no 相同的sql语句是否须要汇总

insert=filename 罗列SQL语句和数据包含在insert语句中

sys=no 不罗列以sys用户运行的sql语句

record=filename 在跟踪文件中查询非递归的语句到文件中

waits=yes|no 跟踪文件中记录任何等待事件

sort=option 设置0或者如下值

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 kthis_ora_3335.trc kthis_ora_3335.log

增长执行计划输出

tkprof kthis_ora_3335.trc kthis_ora_3335.log sys=no explain=hr/hr

相同sql语句合并并不输出sys用户下的运行的表

tkprof kthis_ora_3335.trc kthis_ora_3335_ag.log aggregate=yes sys=no

只是输出执行的sql语句

tkprof kthis_ora_3335.trc kthis_ora_3335_record.log record=0335record.log

输出排序模式，解析、执行时间、获取时间累加排在最上面

tkprof kthis_ora_3335.trc kthis_ora_3335_ag.log sort=prsela,exeela,fchela

内容说明，如如下内容

SQL ID: 6599sqasxy094 Plan Hash: 2292431634

select *
from
 mzsfxx where kpry=999


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        1      3.88      89.12     317839     317885          0         104
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      3.88      89.12     317839     317885          0         104

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       104        104        104  PARTITION RANGE ALL PARTITION: 1 21 (cr=317885 pr=317839 pw=0 time=27318096 us cost=87923 size=16708926 card=214217)
       104        104        104   TABLE ACCESS FULL MZSFXX PARTITION: 1 21 (cr=317885 pr=317839 pw=0 time=79035643 us cost=87923 size=16708926 card=214217)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                        44        0.03          0.37
  direct path read                             2611        0.41         85.72
  db file scattered read                         13        0.02          0.23
  SQL*Net more data to client                     3        0.00          0.00
  SQL*Net message from client                     1       16.25         16.25
********************************************************************************

parse	解析该游标并生成执行计划的统计信息
execute	执行该游标的统计信息
fetch	获取数据行的统计信息
count	指该游标的相关操做的次数，如parse count：1，该游标被解析了1次
cpu	消耗cpu的时间，单位s
elapsed	实际消耗的时间，单位s
disk	消耗的物理读
query	消耗一致性逻辑读 consistenr logical read=》一个select 查询，query通常没有current
current	当前的逻辑读，current logical read ，针对的是insert、update、delete
row	返回的行数
Misses in library cache during parse	在解析阶段library cache发生了miss，则说明本次解析是硬解析
cr	一致性模式下的逻辑读块数量
pr	从磁盘物理读的块数量
pw	从磁盘物理写的块数量
time	操做中花费时间，采用微妙
cost	评估操做的代价，11.1版本后提供
Size	评估这个操做返回的数据量（字节）
card	评估这个操做返回的行数
times waited	等待事件发生的次数
max. wait	单次等待事件最大等待事件，秒为单位
Total Waited	这个等待事件总的等待事件，秒为单位

最后面还有汇总的信息sys递归的语句(ALL RECURSIVE STATEMENTS)和非递归(ALL NON-RECURSIVE STATEMENTS)

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.04          0          0          0           0
Execute      3      0.00       0.07          2         57          0           2
Fetch        1      3.88      89.12     317839     317885          0         104
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7      3.89      89.24     317841     317942          0         106

Misses in library cache during parse: 2
Misses in library cache during execute: 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       53.75         70.01
  db file sequential read                        44        0.03          0.37
  Disk file operations I/O                        2        0.00          0.00
  direct path read                             2611        0.41         85.72
  db file scattered read                         13        0.02          0.23
  SQL*Net more data to client                     3        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.00          0          0          0           0
Execute    183      0.02       0.35          0          0          0           0
Fetch      244      0.00       0.22         32        564          0         564
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      432      0.03       0.58         32        564          0         564

Misses in library cache during parse: 5
Misses in library cache during execute: 5

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                        32        0.03          0.21

用户执行的语句和内部执行的语句的数量

   4  user  SQL statements in session.
   19  internal SQL statements in session.
   23  SQL statements in session

整体状况说明

 1  session in tracefile.
       4  user  SQL statements in trace file.
      19  internal SQL statements in trace file.
      23  SQL statements in trace file.
      22  unique SQL statements in trace file.
    5664  lines in trace file.
     159  elapsed seconds in trace file.

4 TRCESS使用

可使用命令行工具从一个或多个跟踪文件中抽取一部分的信息，输出的文件还须要经过tkprof来转换查看，使用方式

trcsess [output=<output file name >] [session=<session ID>] [clientid=<clientid>]
[service=<service name>] [action=<action name>] [module=<module name>]
<trace file names>

output：输出文件路径

session：哪一个会话被跟踪，session id为（id,serial#）

clientid:客户端被跟踪

service：服务被跟踪

module：模块被跟踪

<trace_file_name>：跟踪文件以空白来分隔

使用：trcsess output=trcess_3607.trc module="TOAD 11.0.0.116" kthis_ora_3335.trc

5 客户端从服务器端取文件

跟踪文件在服务器上的，获取存在不方便，咱们能够事先经过建立一个函数来获取

建立类型，经过管道表的功能读取指定的跟踪文件

CREATE TYPE hr.t_trace_tab AS TABLE OF VARCHAR2(32767);
/

CREATE OR REPLACE FUNCTION hr.get_trace_file (p_trace_file IN VARCHAR2)
RETURN trace_user.t_trace_tab PIPELINED
AS
l_file UTL_FILE.file_type;
l_text VARCHAR2(32767);
BEGIN
l_file := UTL_FILE.fopen('TRACE_DIR', p_trace_file, 'r', 32767);
BEGIN
LOOP
UTL_FILE.get_line(l_file, l_text);
PIPE ROW (l_text);
END LOOP;
EXCEPTION
WHEN NO_DATA_FOUND THEN
NULL;
END;
UTL_FILE.fclose(l_file);
RETURN;
EXCEPTION
WHEN OTHERS THEN
PIPE ROW ('ERROR: ' || SQLERRM);
IF UTL_FILE.is_open(l_file) THEN
UTL_FILE.fclose(l_file);
END IF;
RETURN;
END;
/

--能够提供给其余的用户来执行
GRANT EXECUTE ON hr.t_trace_tab TO PUBLIC;
GRANT EXECUTE ON hr.get_trace_file TO PUBLIC;
CREATE PUBLIC SYNONYM get_trace_file FOR hr.get_trace_file;

-- Create a directory object to the trace location.
CREATE OR REPLACE DIRECTORY trace_dir AS '/u01/app/oracle/diag/rdbms/gull/gull/trace/';
GRANT READ ON DIRECTORY trace_dir TO HR;

测试执行

EXEC DBMS_MONITOR.session_trace_enable;
 select * from  EMPLOYEES;
 EXEC DBMS_MONITOR.session_trace_disable;
采用sqlplus 缓存到本地文件
SET PAGESIZE 0 FEEDBACK OFF TRIMSPOOL ON TAB OFF
SPOOL C:\tracefile.trc

SELECT * FROM   TABLE(get_trace_file('gull_ora_4322.trc'));

SPOOL OFF
SET PAGESIZE 14 FEEDBACK ON

6 参考

《Troubleshooting-Oracle-Performance-2nd-Edition》

https://oracle-base.com/articles/misc/sql-trace-10046-trcsess-and-tkprof