2013-08-07 星期三 下午
－－－－－－－－－－－－－－SQL跟踪方法－－－－－－－－－－－－－－－－－－－－－－
SQL TRACE
SQL> conn hr/hr
Connected.
SQL> alter session set sql_trace=true;
Session altered.
SQL> select * from t1 where id=100;
ID NAME
---------- ----------
100 T1
SQL> select * from t2 where id=100;
ID NAME
---------- ----------
100 T2
SQL> alter session set sql_trace=false;
Session altered.
－－－==========plan表的使用===============
在同一个会话中执行下面的两个SQL：
explain plan for select * from t1 where id=100
select * from plan_table 这个表是个全局临时表，解释完之后在当前会话查询执行计划表的内容
跟踪文件按照既定的规则，将内容装入到plan_table，再显示在autotrace工具中。
打开最近的跟踪文件进行查看：
*** 2013-08-07 14:07:58.625
*** ACTION NAME:() 2013-08-07 14:07:58.576
*** MODULE NAME:(SQL*Plus) 2013-08-07 14:07:58.576
*** SERVICE NAME:(SYS$USERS) 2013-08-07 14:07:58.576
*** SESSION ID:(352.90) 2013-08-07 14:07:58.576
=====================
PARSING IN CURSOR #2 len=29 dep=0 uid=55 oct=3 lid=55 tim=1343609061110110 hv=2732024291 ad='69447274'
select * from t1 where id=100 －－执行的SQL语句
DML语句就是一个隐式游标，
#2——游标的编号
len——SQL语句的长度，29字节
dep——SQL语句解析的深度，0表示第一层
uid——用户ID，哪个用户执行的SQL，select * from dba_users where user_id=55
oct——oracle command type，当前的类型是3
lid——私有用户。当前用户下执行，UID＝LID
tim——厘秒单位表示的时间戳
hv——hash value——SQL语句的hash value，select * from v$sqlarea where hash_value='2732024291'查询得出
ad——address SQL语句在库缓存中驻留的物理地址 select * from v$sqlarea where address='69447274'查询得出
END OF STMT
－－－－－－－－－－－－－解析阶段－－－－－－－－－－－－
PARSE #2:c=1999,e=23433,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1343609061110094
c——消耗CPU的时间，单位：毫秒
e——逃离时间，整个过程消耗的时间：elapse time = wait time + cpu time
p——物理读次数
cr——consistent read——一致性读
cu——db block gets——当前读
mis——解析的次数，错过库缓存的次数
r——取到的行数
dep——SQL语句的深度
og——optimizer mode优化器的模式 1＝CBO
tim——解析的时间戳
－－－－－－－－－－－－－－－执行阶段－－－－－－－－－－－－－－－－－－－－－－－－－－
EXEC #2:c=0,e=4446,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1343609061168722
－－－－－－－－－－－－－－－取数阶段－－－－－－－－－－－－－－－－－－－－－－－－－－－－
FETCH #2:c=0,e=156,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=1343609061168971 －－扫表
FETCH #2:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1343609061169283 －－扫索引
cr=3 等同于 3 consistent gets
－－－－－－－－－－－－－－－－统计阶段－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=56498 op='TABLE ACCESS BY INDEX ROWID T1 (cr=3 pr=0 pw=0 time=150 us)'
STAT #2 id=2 cnt=1 pid=1 pos=1 obj=56499 op='INDEX UNIQUE SCAN SYS_C006531 (cr=2 pr=0 pw=0 time=129 us)'
id——执行计划中的ID
cnt——执行计划中的Rows
pid——父亲节点
pos——左右位置，pos＝1表示作左孩子，POS＝2表示右孩子
obj——访问的对象，select * from dba_objects where data_object_id in(56498,56499)
op——operation——数据访问的方式
cr——一致性读
pr——物理读
pw——物理写
time——时间
=====================
PARSING IN CURSOR #1 len=29 dep=0 uid=55 oct=3 lid=55 tim=1343609067332993 hv=2555944085 ad='69446bb8'
select * from t2 where id=100
END OF STMT
PARSE #1:c=2000,e=1998,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1343609067332983 －－解析了一次
EXEC #1:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1343609067333143
FETCH #1:c=999,e=326,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=1343609067333690
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1343609067334213
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=56500 op='TABLE ACCESS BY INDEX ROWID T2 (cr=4 pr=0 pw=0 time=318 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=56501 op='INDEX UNIQUE SCAN SYS_C006532 (cr=3 pr=0 pw=0 time=266 us)'
=====================
PARSING IN CURSOR #2 len=33 dep=0 uid=55 oct=42 lid=55 tim=1343609071532155 hv=525901419 ad='0'
alter session set sql_trace=false
END OF STMT
PARSE #2:c=0,e=232,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1343609071532147
EXEC #2:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1343609071532257
SQL> select * from t1 where id=100;
Execution Plan
----------------------------------------------------------
Plan hash value: 1846342996
-------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 6 | 2 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 6 | 2 (0)| 00:00:01 |
|* 2 | INDEX UNIQUE SCAN | SYS_C006531 | 1 | | 1 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID"=100)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3 consistent gets
0 physical reads
0 redo size
462 bytes sent via SQL*Net to client
400 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
=================================
将跟踪文件转华为一个report：可读性强。
[oracle@oracle253 udump]$ tkprof orcl_ora_6110 orcl_ora_6110.txt
TKPROF: Release 10.2.0.4.0 - Production on Wed Aug 7 14:35:13 2013
Copyright (c) 1982, 2007, Oracle. All rights reserved.
－－打开文件
Trace file: orcl_ora_6110.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
********************************************************************************
select *
from
t1 where id=100
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.02 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.02 0 3 0 1
参数说明：
call——调用的类型
count——类型对应的次数
cpu——消耗CPU的时间
elapsed——逃离时间
disk——物理读块次数
query——一致性读块次数
current——当前读次数
rows——返回的行数
----------------------------------------------------
Misses in library cache during parse: 1 解析了一次
Optimizer mode: ALL_ROWS
Parsing user id: 55
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T1 (cr=3 pr=0 pw=0 time=150 us)
1 INDEX UNIQUE SCAN SYS_C006531 (cr=2 pr=0 pw=0 time=129 us)(object id 56499)
********************************************************************************
select *
from
t2 where id=100
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 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T2 (cr=4 pr=0 pw=0 time=318 us)
1 INDEX UNIQUE SCAN SYS_C006532 (cr=3 pr=0 pw=0 time=266 us)(object id 56501)
********************************************************************************
alter session set sql_trace=false
******************************************************************************** 汇总
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS －－非递归调用部分，用户自己执行的SQL语句消耗的统计
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.02 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.00 0 7 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.00 0.03 0 7 0 2
Misses in library cache during parse: 2
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS －－递归调用，由用户SQL引发的底层的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.
********************************************************************************
硬解析：
1、作递归调用，为执行计划准备数据。
2、解析这个SQL语句生成执行计划
-------------------------------------------
将缓存清除掉后再看这个过程：
SQL> conn /as sysdba
Connected.
SQL> alter system flush buffer_cache;
System altered.
SQL> alter system flush shared_pool;
System altered.
SQL> conn hr/hr
Connected.
SQL> alter session set sql_trace=true;
Session altered.
SQL> select * from t1 where id=100;
ID NAME
---------- ----------
100 T1
SQL> select * from t2 where id=100;
ID NAME
---------- ----------
100 T2
SQL> alter session set sql_trace=false;
Session altered.
[oracle@oracle253 udump]$ tkprof orcl_ora_6813 orcl_ora_6813.txt
TKPROF: Release 10.2.0.4.0 - Production on Wed Aug 7 14:42:45 2013
Copyright (c) 1982, 2007, Oracle. All rights reserved.
前面递归调用的文本省略。。。。。
看到很对看不懂的SQL语句的解析过程，这个就是CBO优化器数学模型在运算过程中留下的痕迹。
********************************************************************************
select *
from
t1 where id=100
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.04 13 50 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 3 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.03 0.05 16 53 0 1
disk次数不为0。
Misses in library cache during parse: 1 －－做了硬解析
Optimizer mode: ALL_ROWS
Parsing user id: 55
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T1 (cr=3 pr=3 pw=0 time=10294 us)
1 INDEX UNIQUE SCAN SYS_C006531 (cr=2 pr=2 pw=0 time=9960 us)(object id 56499)
********************************************************************************
select *
from
t2 where id=100
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 1 50 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 4 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.02 5 54 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T2 (cr=4 pr=4 pw=0 time=10313 us)
1 INDEX UNIQUE SCAN SYS_C006532 (cr=3 pr=3 pw=0 time=10239 us)(object id 56501)
********************************************************************************
alter session set sql_trace=false
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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 55
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.04 0.05 14 100 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.02 7 7 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.04 0.07 21 107 0 2
Misses in library cache during parse: 2
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS －－递归调用现在有值了。
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 28 0.00 0.00 0 0 0 0
Execute 30 0.01 0.01 0 0 0 0
Fetch 42 0.00 0.01 14 100 0 26
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100 0.03 0.04 14 100 0 26
Misses in library cache during parse: 13
Misses in library cache during execute: 13
3 user SQL statements in session.
30 internal SQL statements in session.
33 SQL statements in session.
********************************************************************************
可以根据SQL TRACE和 TKPROF工具看到一个SQL语句在底层的消耗，包括CPU和IO的消耗，
这样我们能清晰的看到SQL语句的性能问题。
