使用logon trigger完成動態的session跟蹤

在之前討論過 關於oracle中session跟蹤的總結，可以參見連結 http://blog.itpub.net/23718752/viewspace-1150568/
基本的session跟蹤方法都做了討論，但是在實際應用中場景可能要複雜一些，比如我們可以對指定的session開診斷事件，如果session中執行的某個環節出現問題，可以根據診斷事件得到比較明細的遞迴sql來逐步檢視排除，知道問題的根源。
但是如果不確定session的情況，因為每次連線進來的session都是不固定的，這樣就很難開診斷事件了。
這個還得從這些天的一個例子說起，開發找到我希望我能夠幫他們查一個問題，開發需要啟動一個job，job會在啟動的過程中做一些資料校驗檢查，然後資料處理，最後退出，但是目前他們碰到的問題是job在啟動的時候就會報錯，而且沒有很詳細的日誌，所以希望我能夠不能幫他們看看，碰到這種問題，一般來說都是友情客串一下，幫他們看看，給點思路，對於更根本的原因還是需要他們自己在調優級別加入一些對應的日誌。
得到的錯誤是一個ORA的錯誤，但是日誌只有簡單的幾行。為了把問題簡化，排除各種場景的干擾，在此我就簡單的模擬了一下這個job，
假設這個job需要做下面的事情
sqlplus -s xxx/xxx@test01 < set feedback off
select count(*) from cat;
create table catt as select *from cat where rownum<2;
drop table catt;
select *from catt;
EOF

簡單的檢視一下這個指令碼，就會發現最後一步的時候，肯定會報錯。因為在倒數第二步中已經把新建的表刪除了。再次檢視肯定會報ORA-00942: table or view does not exist的錯誤。
我們就以這個例子來分析一下，怎麼使用session跟蹤來分析問題。
最開始的想法是透過shell指令碼來不斷的掃描某個使用者下的session，比如job是需要處理使用者test下的資料，在job啟動的過程就會有一些session連結到test使用者，然後做一些操作。我就嘗試透過一個迴圈的指令碼來不斷的掃描使用者test下的session，然後對這些session使用dbms_system.set_sql_trace_in_session來啟動session跟蹤。
理論上是可行的，但是在實際的操作中還是感覺力不從心，主要有下面幾個問題。
一個是我也不知道這個job什麼時候啟動，所以不斷的掃描使用者test下的session就會有些頻繁，而且需要在指令碼中不斷的去比較哪些session是已經存在的session，需要排除，本身這個過程就會消耗不少的資源。
還有一個問題是儘管資源消耗可以接受，但是在掃描的過程中不一定能夠完全捕捉到那個session，怎麼來理解呢，比如某個job在在資料檢查工作的時候使用一個session1,然後在資料處理的時候使用4個session,資料處理的速度可能很快，比如1秒鐘完成，掃描的過程中就不一定能夠完完全全的捕捉到對應的日誌。
最後一個就是關閉session跟蹤的問題，如果開啟了大量的session跟蹤，最後需要關閉的時候就需要保證都能夠關閉跟蹤，否則日誌會越來越多，造成不必要的影響。
所以最開始和同事在除錯的時候，都是我和他坐在一起，我給他說一聲，然後啟動後臺掃描，然後他啟動一下job，我們保持幾秒中的時間間隔，儘管這樣，遺憾的是還是沒有找到相關的日誌。
這種方式太不靈活了，而且除錯起來確實費時費力。
最後考慮了一下這種靈活性，考慮採用logon trigger來做。
我們可以使用如下的程式碼來實現這種複雜的需求，如果有使用者連進來，就開啟10046事件，這樣邏輯就靈活了很多，不用我在後臺做很多無用功來不斷的掃描了,也是按需除錯的一種很好的例子。
CREATE OR REPLACE TRIGGER set_trace_on_logon
AFTER LOGON ON DATABASE
BEGIN
  if (  user not in ('SYS','SYSTEM' )) then
    EXECUTE IMMEDIATE 'alter session set statistics_level=ALL';
    EXECUTE IMMEDIATE 'alter session set max_dump_file_size=UNLIMITED';
    EXECUTE IMMEDIATE 'alter session set tracefile_identifier='''||user||'_10046''';
    EXECUTE IMMEDIATE 'alter session set events ''10046 trace name context forever, level 12''';
  end if; 
END set_10046_trace_on_logon;
/

注意建立trigger的語句需要在sys下執行，如果在其它dba賬戶下執行還是有許可權的限制，在生成遞迴sql的時候就有問題了，生成的日誌中不會有明細的除錯資訊，只會包含這些錯誤和警告。
Skipped error 604 during the execution of N1.SET_TRACE_ON_LOGON 

*** 2015-01-28 06:27:02.751
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=0, mask=0x0)
----- Error Stack Dump -----
ORA-00604: error occurred at recursive SQL level 1
ORA-01031: insufficient privileges
ORA-06512: at line 6

建立了trigger之後，我們再次執行指令碼，就會得到預期的ora錯誤,我們假設最後一步的邏輯很複雜，我們還不能直觀的分析出到底是哪出了錯。
  COUNT(*)
----------
        59
select *from catt
             *
ERROR at line 1:
ORA-00942: table or view does not exist

檢視生成的trace檔案
-rw-r----- 1 ora11g dba    1145 Jan 28 07:05 TEST01_ora_8380_N1_10046.trm
-rw-r----- 1 ora11g dba  126028 Jan 28 07:05 TEST01_ora_8380_N1_10046.trc

如果透過tkprof簡單格式化trace檔案的話，很可能把重要的錯誤資訊也給過濾掉了。我們可以完全自己手工來檢視trace檔案。
在trace檔案中，我們使用關鍵字”err=“或者"ERROR"來查詢一般都能有所收穫。
EXEC #139804991168728:c=1000,e=815,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2853959010,tim=1422457558003768
FETCH #139804991168728:c=0,e=54,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=2853959010,tim=1422457558003877
CLOSE #139804991168728:c=0,e=9,dep=1,type=3,tim=1422457558004037
=====================
PARSE ERROR #139804993076144:len=17 dep=0 uid=36 oct=3 lid=36 tim=1422457558004335 err=942
select *from catt 
WAIT #139804993076144: nam='SQL*Net break/reset to client' ela= 68 driver id=1650815232 break?=1 p3=0 obj#=-1 tim=1422457558004957
WAIT #139804993076144: nam='SQL*Net break/reset to client' ela= 559 driver id=1650815232 break?=0 p3=0 obj#=-1 tim=1422457558005796
WAIT #139804993076144: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1422457558005865
WAIT #139804993076144: nam='SQL*Net message from client' ela= 2665 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1422457558008607
XCTEND rlbk=0, rd_only=1, tim=1422457558008854
CLOSE #139804993076144:c=0,e=15,dep=0,type=0,tim=1422457558009096
CLOSE #139804993033288:c=0,e=15,dep=0,type=0,tim=1422457558009186
透過這些日誌，我們可以很明顯的看到出現瞭解析錯誤，報錯code為942 對應的sql語句是select *from catt

最後的重要步驟就是需要禁用10046事件，然後刪除這個trigger.
CREATE OR REPLACE TRIGGER sys.set_trace_on_logon
AFTER LOGON ON DATABASE
BEGIN
  if (  user not in ('SYS','SYSTEM' )) then
    EXECUTE IMMEDIATE 'alter session set statistics_level=ALL';
    EXECUTE IMMEDIATE 'alter session set max_dump_file_size=UNLIMITED';
    EXECUTE IMMEDIATE 'alter session set tracefile_identifier='''||user||'_10046''';
    EXECUTE IMMEDIATE 'alter session set events ''10046 trace name context forever, level 12''';
  end if; 
END set_10046_trace_on_logon;
/
drop trigger sys.set_trace_on_logon;

透過這個例子，能夠看出來logon trigger的強大作用，在使用中可以揉入更多的驗證規則，在開啟了診斷事件或者開啟日誌的情況下都可以完成session的跟蹤，不管多麼強大的工具能夠完成需求才是根本。