潛水珽的異想世界

前言:
很多時候,會聽到USER抱怨他的程式跑的很慢,這時候DBA該怎麼處理呢?
這篇文章會教導大家,如何去透過OS processes去查目前session的等待事件以及狀態。

開始動手:
在trace end user process所執行的資訊,必須完成已下參數的設定前置作業:

timed_statistics=TRUE
max_dump_file_size='3M'

如果是要改自己當前session的parameter可以用alter system set parameter_name=value scope=XXX;來更改,
如果是要改end user的狀態呢?可以透過Oracle所提供的程式包(Package)來達到,請參考下列例子:

select * from v$process
where SPID=OS_Process_ID;              --找出對應的SID

select SID,SERIAL#,USERNAME from v$session
where sid=XXX;                    --找出對應的SERIAL#

exec sys.dbms_system.set_pool_param_in_session( -
        sid => 1234, -
        serial# => 56789, -
        parnam => 'timed_statistics', -
        bval => true);            --修改timed_statistics參數
        
exec sys.dbms_system.set_int_param_in_session( -     
        sid => 1234, -     
        serial# => 56789, -     
        parnam => ‘MAX_DUMP_FILE_SIZE’, -     
        intval => 2147483647);        --修改max_dump_file_size參數


接下來Enable sql trace level,有三種方式,只要擇一即可:
方法1:使用DBMS_SUPPORT package procedures

exec dbms_support.start_trace_in_session( -     
        sid => 1234, -     
        serial# => 56789, -     
        waits => true, -     
        binds => true);            -- Enable ‘level 12’ trace in session 1234 with serial# 56789

-- Let the session execute SQL script or
-- program for some amount of time
 
 

exec dbms_support.stop_trace_in_session( -     
        sid => 1234, -     
        serial# => 56789);        -- To turn off the tracing


方法2:使用DBMS_SYSTEM package procedure

exec dbms_system.set_ev( 1234, 56789, 10046, 8, ‘’);    -- Enable trace at level 8 for session 1234 with serial# 56789

-- Let the session execute SQL script or
-- program for some amount of time

exec dbms_system.set_ev( 1234, 56789, 10046, 0, ‘’);    -- To turn off the tracing

方法3:使用oradebug工具

oradebug setospid 12345;                  -- 12345 is the OS process id for the session

oradebug unlimit;

oradebug event 10046 trace name context forever, level 8;

-- Let the session execute SQL script
-- or program for some amount of time

oradebug event 10046 trace name context off;        -- To turn off the tracing

註:SQL Trace Level的說明:

以下是事件的有效trace級別：
Level 0  tracing被關閉。這相當於設置sql_trace=false。
Level 1  標準SQL trace資訊（SQL_TRACE=TRUE）。這是默認級別。
Level 4  SQL trace資訊加綁定變數值。

Level 8  SQL trace資訊加等待事件資訊。
Level 12 SQL trace 資訊，等待事件資訊，和綁定變數值。

接下來我們來看一下trace中有紀錄哪些東西:

$ cat kitty1_ora_15625.trc|more

Dump file /oratest/admin/KITTY/udump/kitty1_ora_15625.trc
Oracle9i Enterprise Edition Release 9.2.0.7.0 - 64bit Production
With the Partitioning and Real Application Clusters options
JServer Release 9.2.0.7.0 - Production
ORACLE_HOME = /oratest/ora92
System name:    SunOS
Node name:      RSDB-1
Release:        5.9
Version:        Generic_118558-28
Machine:        sun4u
Instance name: KITTY1
Redo thread mounted by this instance: 1
Oracle process number: 27
Unix process pid: 15625, image: oracle@RSDB-1 (TNS V1-V3)

*** 2008-08-08 13:34:19.770
*** SESSION ID:(51.560) 2008-08-08 13:34:19.704
WAIT #3: nam='library cache lock' ela= 205 p1=18713957672 p2=18575198696 p3=1301
APPNAME mod='sessionservice.exe' mh=0 act='' ah=0
=====================
PARSING IN CURSOR #3 len=332 dep=0 uid=40 oct=6 lid=40 tim=16438399519279 hv=2260989432
ad='5c185168'
UPDATE DBSTF.S0009_SESSION SET LASTACCESS = :p1 WHERE ((SESSIONKEY = :p2) AND (PERSONID =
:p3) AND (LASTACCESS = :p4) AND ((:p5 = :"SYS_B_0" AND LOGINTYPE IS NULL) OR (LOGINTYPE =
:p6)) AND (EMPNO = :p7) AND ((:p8 = :"SYS_B_1" AND LOGINID IS NULL) OR (LOGINID = :p9))
AND ((:p10 = :"SYS_B_2" AND USERIP IS NULL) OR (USERIP = :p11)))
END OF STMT
PARSE #3:c=10000,e=70902,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=16438399519193
EXEC #3:c=10000,e=4234,p=0,cr=3,cu=2,mis=0,r=1,dep=0,og=4,tim=16438399523791
XCTEND rlbk=0, rd_only=0
WAIT #3: nam='log file sync' ela= 11 p1=3851 p2=0 p3=0

    =>nam: wait event name
    =>ela: elasped time (micro seconds)
    =>p1:同v$session_wait的P1
    =>p2:同v$session_wait的P2
    =>p3:同v$session_wait的P3

WAIT #3: nam='log file sync' ela= 3051 p1=3851 p2=0 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 1292 p1=1413697536 p2=1 p3=0
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE  '
WAIT #3: nam='row cache lock' ela= 629 p1=11 p2=0 p3=3
WAIT #4: nam='library cache lock' ela= 49 p1=18520981432 p2=18575198696 p3=1301
WAIT #4: nam='library cache lock' ela= 864 p1=18520981432 p2=18575198696 p3=1301
=====================
PARSING IN CURSOR #4 len=116 dep=1 uid=0 oct=3 lid=0 tim=16438399533800 hv=431456802 ad='4
fedc7b8'
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataobj#,o.flags f
rom obj$ o where o.obj#=:1
END OF STMT
PARSE #4:c=10000,e=3053,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=16438399533789
EXEC #4:c=0,e=609,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=16438399534835
FETCH #4:c=0,e=135,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=16438399535094
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=291234 op='TABLE ACCESS BY INDEX ROWID S0009_SESSION '
STAT #3 id=3 cnt=1 pid=2 pos=1 obj=294881 op='INDEX UNIQUE SCAN PK_S0009 '
=====================
PARSING IN CURSOR #3 len=332 dep=0 uid=40 oct=6 lid=40 tim=16438399536255 hv=2260989432
ad='5c185168'
UPDATE DBSTF.S0009_SESSION SET LASTACCESS = :p1 WHERE ((SESSIONKEY = :p2) AND (PERSONID =
:p3) AND (LASTACCESS = :p4) AND ((:p5 = :"SYS_B_0" AND LOGINTYPE IS NULL) OR (LOGINTYPE =
:p6)) AND (EMPNO = :p7) AND ((:p8 = :"SYS_B_1" AND LOGINID IS NULL) OR (LOGINID = :p9)) AN
D ((:p10 = :"SYS_B_2" AND USERIP IS NULL) OR (USERIP = :p11)))
END OF STMT
PARSE #3:c=0,e=520,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=16438399536248
EXEC #3:c=0,e=488,p=0,cr=3,cu=2,mis=0,r=1,dep=0,og=4,tim=16438399536970
XCTEND rlbk=0, rd_only=0
WAIT #3: nam='log file sync' ela= 2863 p1=3853 p2=0 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 915 p1=1413697536 p2=1 p3=0
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE  '
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=291234 op='TABLE ACCESS BY INDEX ROWID S0009_SESSION '
STAT #3 id=3 cnt=1 pid=2 pos=1 obj=294881 op='INDEX UNIQUE SCAN PK_S0009 '
=====================
PARSING IN CURSOR #3 len=143 dep=0 uid=40 oct=2 lid=40 tim=16438399542719 hv=1573552411 ad
='6e579d08'
INSERT INTO DBSTF.S0009_SESSION(SESSIONKEY, PERSONID, LASTACCESS, LOGINTYPE, EMPNO, LOGINI
D, USERIP) VALUES (:p1, :p2, :p3, :p4, :p5, :p6, :p7)
END OF STMT
PARSE #3:c=0,e=981,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=16438399542710
EXEC #3:c=0,e=1112,p=0,cr=1,cu=7,mis=0,r=1,dep=0,og=4,tim=16438399544068
XCTEND rlbk=0, rd_only=0
WAIT #3: nam='log file sync' ela= 2075 p1=3855 p2=0 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
*** 2008-08-08 13:35:19.712
WAIT #3: nam='SQL*Net message from client' ela= 58515770 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #3 len=332 dep=0 uid=40 oct=6 lid=40 tim=16438458064128 hv=2260989432 ad
='5c185168'
UPDATE DBSTF.S0009_SESSION SET LASTACCESS = :p1 WHERE ((SESSIONKEY = :p2) AND (PERSONID =
:p3) AND (LASTACCESS = :p4) AND ((:p5 = :"SYS_B_0" AND LOGINTYPE IS NULL) OR (LOGINTYPE =
:p6)) AND (EMPNO = :p7) AND ((:p8 = :"SYS_B_1" AND LOGINID IS NULL) OR (LOGINID = :p9)) AN
D ((:p10 = :"SYS_B_2" AND USERIP IS NULL) OR (USERIP = :p11)))
END OF STMT
PARSE #3:c=0,e=753,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=16438458064116
EXEC #3:c=0,e=1569,p=0,cr=3,cu=2,mis=0,r=1,dep=0,og=4,tim=16438458065969
XCTEND rlbk=0, rd_only=0
WAIT #3: nam='log file sync' ela= 2429 p1=3867 p2=0 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
*** 2008-08-08 13:36:19.692
WAIT #3: nam='SQL*Net message from client' ela= 58576460 p1=1413697536 p2=1 p3=0
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE  '
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=291234 op='TABLE ACCESS BY INDEX ROWID S0009_SESSION '
STAT #3 id=3 cnt=1 pid=2 pos=1 obj=294881 op='INDEX UNIQUE SCAN PK_S0009 '
=====================
PARSING IN CURSOR #3 len=332 dep=0 uid=40 oct=6 lid=40 tim=16438516647974 hv=2260989432 ad
='5c185168'
UPDATE DBSTF.S0009_SESSION SET LASTACCESS = :p1 WHERE ((SESSIONKEY = :p2) AND (PERSONID =
:p3) AND (LASTACCESS = :p4) AND ((:p5 = :"SYS_B_0" AND LOGINTYPE IS NULL) OR (LOGINTYPE =
:p6)) AND (EMPNO = :p7) AND ((:p8 = :"SYS_B_1" AND LOGINID IS NULL) OR (LOGINID = :p9)) AN
D ((:p10 = :"SYS_B_2" AND USERIP IS NULL) OR (USERIP = :p11)))
END OF STMT
PARSE #3:c=0,e=651,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=16438516647958
EXEC #3:c=0,e=1576,p=0,cr=3,cu=2,mis=0,r=1,dep=0,og=4,tim=16438516649823
XCTEND rlbk=0, rd_only=0
WAIT #3: nam='log file sync' ela= 3031 p1=3879 p2=0 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 17 p1=1413697536 p2=1 p3=0
*** 2008-08-08 13:37:19.682
WAIT #3: nam='SQL*Net message from client' ela= 58584011 p1=1413697536 p2=1 p3=0

END