sql 跟踪
目录
1 sql跟踪
sql 跟踪可以清晰看到一条或多条语句资源消耗情况：如CPU、逻辑读、物理读的情况
sql语句清晰看到一条或多条语句是parse/execute/fetch在等问题
也可以清晰语句具体的等待事件是什么，了解是SQL层面的问题还是软件本身问题
了解create table,drop、exp内部的原理
sql 跟踪有许多个级别
0：表示禁用
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 4、level8
Level 28 (4 + 8 + 16) 代表 同时启用 level 4 、level 8、level 16
level 68 ( 64 + 4 ) 代表 同时启用 level 64、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
