sql_trace and 10046事件[@more@]

1).trace_file

alter session set tracefile_identifier='mytest' 可以設定目前session的trace file的名字。

alter session set sql_trace=true

2)

[oracle@oracle10g ~]$ 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

explain=user/password 不但會生成sql的實際執行路徑，還會生成sql的執行計劃
sys=yes/no yes(預設情況下)表示在trace檔案輸出所有sys操作，
aggregate=yes|no tkprof工具將所有相同的sql在輸入檔案中做合併

select object_type,count(*)
from
tt group by object_type

---==================================================
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 4 0.02 0.04 0 686 0 39
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.03 0.04 0 686 0 39

Misses in library cache during parse: 0 shared pool命中，表示在軟解析
Optimizer mode: ALL_ROWS 最佳化器模式
Parsing user id: SYS 當前使用者

Rows Row Source Operation
------- ---------------------------------------------------
39 HASH GROUP BY (cr=686 pr=0 pw=0 time=40976 us)
49586 TABLE ACCESS FULL TT (cr=686 pr=0 pw=0 time=132 us)

---==============================================================

parse：sql的分析階段

execute：sql的執行階段

fetch：資料的提取階段

count：表示當前的操作執行了多少次

cpu：當前的操作消耗多少cpu(單位秒)

elapsed：當前的操作一共用時多少(包括cpu時間和等待時間)

disk：當前的物理讀

query：當前操作的一致性讀方式讀取的資料塊數(通常是查詢使用的方式)

current：當前操作的current方式讀取的資料塊數(通常是修改資料使用的方式)

rows：當前操作處理的資料記錄數

rows source operation ：行源操作，表示當前操作的資料訪問方式

cr---consistent read:一致性讀取的方式，相當於query中fetch的數值

pr---physical read:物理讀取的資料塊，相當於disk上fetch的數值

pw---physical write:物理寫

time：當前操作執行的時間

3）直接分析產生的trace檔案

[oracle@oracle10g udump]$ ll
total 12
-rw-r--r-- 1 oracle oinstall 5186 Nov 14 08:18 a1.txt
-rw-r----- 1 oracle oinstall 2048 Nov 14 08:16 oracle10g_ora_3174.trc
[oracle@oracle10g udump]$ more oracle10g_ora_3174.trc
/u01/oracle/admin/oracle10g/udump/oracle10g_ora_3174.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - 64bit Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /u01/oracle/product/10.2.0/db_1
System name: Linux
Node name: oracle10g
Release: 2.6.18-164.el5
Version: #1 SMP Tue Aug 18 15:51:48 EDT 2009
Machine: x86_64
Instance name: oracle10g
Redo thread mounted by this instance: 1
Oracle process number: 18
Unix process pid: 3174, image: oracle@oracle10g (TNS V1-V3)

*** SERVICE NAME:(SYS$USERS) 2012-11-14 08:15:46.432
*** SESSION ID:(1080.9) 2012-11-14 08:15:46.432

上面是作業系統，資料庫的資訊。
=====================
.........................................
=====================
PARSING IN CURSOR #2 len=56 dep=0 uid=0 oct=3 lid=0 tim=1321144680316280 hv=831628736 ad='71ab1080'
select object_type,count(*) from tt group by object_type
END OF STMT
PARSE #2:c=1000,e=255,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1321144680316271
EXEC #2:c=0,e=305,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1321144680316725
FETCH #2:c=29995,e=40757,p=0,cr=686,cu=0,mis=0,r=1,dep=0,og=1,tim=1321144680357571
FETCH #2:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=1321144680358246
FETCH #2:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=1321144680358708
FETCH #2:c=0,e=117,p=0,cr=0,cu=0,mis=0,r=8,dep=0,og=1,tim=1321144680359035
STAT #2 id=1 cnt=39 pid=0 pos=1 obj=0 op='HASH GROUP BY (cr=686 pr=0 pw=0 time=40976 us)'
STAT #2 id=2 cnt=49586 pid=1 pos=1 obj=52376 op='TABLE ACCESS FULL TT (cr=686 pr=0 pw=0 time=132 us)'
=====================
parsing in cursor部分：

len：被分析sql的長度

dep：產生遞迴sql的深度

uid：user id

otc：oracle command type命令的型別

lid：私有使用者的id

tim：時間戳

hv：hash value

ad：sql address

parse，exec，fetch部分

c：消耗的cpu time

e：elapsed time 操作的用時

p：physical read 物理讀的次數

cr：consistent read 一次性方式讀取的資料塊

cu：current 方式讀取的資料塊

mis：cursor miss in cache硬分析次數

r：row處理的行數

dep：depth遞迴sql的深度

og：optimizer goal最佳化器模式

tim：timestamp時間戳

stat部分

id：執行計劃的行原號

cnt：當前行源返回的行數

pid：當前行源號的父號

pos：執行計劃中的位置

obj：當前操作物件的id

op：當前行源的資料訪問操作

4）10046事件

level 1 = sql_trace
level 4 = level 1 + 繫結變數的資訊
level 8 = level 1 + 等待時間資訊
level 12 =level 4 + level 8

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

Session altered.

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

Session altered.

5)對其他會話進行sql_trace

SQL> exec dbms_system.set_sql_trace_in_session(1083,248,true);

PL/SQL procedure successfully completed.

SQL> exec dbms_system.set_sql_trace_in_session(1083,248,false);

PL/SQL procedure successfully completed.

6)對其他會話進行10046

SQL> exec dbms_monitor.session_trace_enable(1083,248,waits=>true,binds=>true);

PL/SQL procedure successfully completed.

SQL> exec dbms_monitor.session_trace_disable(1083,248);

PL/SQL procedure successfully completed.

sql_trace and 10046事件

相關文章