從dba_hist_active_sess_history裡尋找session間的等待關係

不一樣的天空w發表於2017-02-25
Session


dba_hist_active_sess_history每隔10秒鐘轉儲來自v$active_session_history的活動session資訊（v$active_session_history.IS_AWR_SAMPLE=Y對應的行會被採集到到dba_hist_active_sess_history），作為AWR、ASH的重要補充，dba_hist_active_sess_history是我們drill down的有效資料來源，特別是session之間存在相互牽制的情況下尤為管用。

我們首先製造一下實驗所需的資料，模擬"enq: TX - row lock contention"等待事件

###建立測試表：

create table ad.t1020_1 (id number, c2 varchar2(10)) tablespace ts_pub;

insert into ad.t1020_1 values(1,'A');

insert into ad.t1020_1 values(2,'B');

insert into ad.t1020_1 values(3,'C');

insert into ad.t1020_1 values(4,'D');

commit;

 

###開四個session，更新記錄但不提交，模擬"enq: TX - row lock contention"等待

---session 1:

select * from v$mystat where rownum=1;

       SID STATISTIC#      VALUE

---------- ---------- ----------

      499          0          0

 

exec dbms_session.set_identifier('session 1');

select module,CLIENT_IDENTIFIER from v$session where sid=499;

update ad.t1020_1 set c2='a' where id=1;

 

---session 2:

select * from v$mystat where rownum=1;

       SID STATISTIC#      VALUE

---------- ---------- ----------

      2830          0          0

     

exec dbms_session.set_identifier('session 2');

select module,CLIENT_IDENTIFIER from v$session where sid=2830;

update ad.t1020_1 set c2='b' where id=2;

update ad.t1020_1 set c2='a-session2' where id=1;

 

---session 3:

select * from v$mystat where rownum=1;

       SID STATISTIC#      VALUE

---------- ---------- ----------

      965          0          0

     

exec dbms_session.set_identifier('session 3');

select module,CLIENT_IDENTIFIER from v$session where sid=965;

update ad.t1020_1 set c2='c' where id=3;

update ad.t1020_1 set c2='b-session3' where id=2;

 

---session 4:

select * from v$mystat where rownum=1;

       SID STATISTIC#      VALUE

---------- ---------- ----------

      2375          0          0

     

exec dbms_session.set_identifier('session 4');

select module,CLIENT_IDENTIFIER from v$session where sid=2375;

update ad.t1020_1 set c2='d' where id=4;

update ad.t1020_1 set c2='c-session4' where id=3;

 

持續約20分鐘，生成一份AWR報告







上面三張從AWR報告裡摘出的圖中可以看出Top 3 三條SQL耗時特別長，但CPU和IO消耗為0，初步判斷這三條SQL可能在等待某些資

源，”Enqueue Activity” section裡顯示有較為嚴重的TX Transaction等待。

 

AWR報告提供的資訊量非常有限，下鑽分析還得藉助於dba_hist_active_sess_history

如果v$active_session_history內容已被清理，就需要從dba_hist_active_sess_history裡分析當時的詳細情況，為加快檢索速度，我們把熱點時段的

記錄儲存到一張臨時表

create table chh1020 as select * from dba_hist_active_sess_history where sample_time between to_date('20151020 11:00','yyyymmdd hh24:mi') and to_date('20151020 11:23','yyyymmdd hh24:mi');

 

使用如下語句查詢chh1020表

select t.instance_number,t.sample_time,lpad('-',2*(level-1),'-')||t.client_id,t.session_id,t.BLOCKING_INST_ID,t.blocking_session,t.session_serial#,t.sql_id,t.event,t.session_state,level,connect_by_isleaf,connect_by_iscycle from chh1020 t where sample_time between to_date('20151020 11:00:00','yyyymmdd hh24:mi:ss') and to_date('20151020 11:23:00','yyyymmdd hh24:mi:ss') start with blocking_session is not null and  event like 'enq: TX - row lock contention%' connect by nocycle sample_time=prior sample_time and session_id=prior blocking_session and session_serial#=prior blocking_session_serial# and instance_number=prior blocking_inst_id;

 

其中的"enq: TX - row lock contention"可以替換成任何你所感興趣的event_name，

” sample_time between to_date('20151020 11:00:00','yyyymmdd hh24:mi:ss') and to_date('20151020 11:23:00','yyyymmdd hh24:mi:ss')”可以

替換成更為精確的時間段




其中connect_by_isleaf=1的行所對應的blocking_session是源頭session，也就是我們要重點根治的物件，因為整個row lock持續的時間較長，所以

我們只要觀察某個具體的時間點裡session間的等待關係，正如紅色框裡所標示的，session 2(sid=2830)鎖住了session 3(sid=965)、session

3(sid=965)鎖住了session 4(sid=2375)，session 2(sid=2830)本身又被sid=499的session 鎖定。

顯示格式上採用了逐層縮排的方式以方便區分，縮排最深的行對應的blocking_session便是鎖源session的sid。

session 4的sql_id:2wpkhdbc5708p對應的SQL語句執行時被阻塞：

select sql_text from dba_hist_sqltext where sql_id='2wpkhdbc5708p';

SQL_TEXT

--------------------------------------------------------------------------------

update ad.t1020_1 set c2='c-session4' where id=3

 

session 3的sql_id:cxm2ayurssjqr對應的SQL語句執行時被阻塞：

select sql_text from dba_hist_sqltext where sql_id='cxm2ayurssjqr';

SQL_TEXT

--------------------------------------------------------------------------------

update ad.t1020_1 set c2='b-session3' where id=2

 

session 2的sql_id:a33w9zr1cm1j3對應的SQL語句執行時被阻塞：

SQL> select sql_text from dba_hist_sqltext where sql_id='a33w9zr1cm1j3';

 

SQL_TEXT

--------------------------------------------------------------------------------

update ad.t1020_1 set c2='a-session2' where id=1           

 

session 2的這條SQL被阻塞住了，且阻塞它的sid=499(session 1)，因為session 1對應的sql語句瞬間執行完，所以在dba_hist_active_sess_history

裡無法找到session 1對應的語句(如果v$active_session_history還未被清除，那麼可能會從v$active_session_history裡找到session 1對應的sql語

句)，即便無法找到也能快速將問題定位到ad.t1020_1表的DML語句上。

透過把dba_hist_active_sess_history裡的海量資料有效的關聯起來幫助我們解析出當時的資料庫裡哪些session受到了其它session的影響，藉助於

dba_hist_sqlstat、dba_hist_sqltext、dba_hist_sql_plan等檢視進一步找出當時引發等待事件的源頭SQL語句，為今後的最佳化提供了有力依據。

非enqueue類的等待事件，只要blocking_session_id有值，都能捕捉到，以下是某一次資料庫出現的大量"latch: row cache objects"等待事件時捕捉到session之間相互等待的狀態，關注藍色部分：sid:17040鎖住sid:430，sid:430鎖住sid:11627



關於這個問題的詳細處理過程及原因分析可以參考我的另一篇文章：

select any table許可權可能引發大量latch row cache objects等待事件: http://blog.itpub.net/53956/viewspace-1783814/

雖然問題的癥結不是由於某一個session所引起，但至少在大併發的情況下我們能夠很容易觀察到不同session對於row cache latch是序列持有的


來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/31397003/viewspace-2134274/，如需轉載，請註明出處，否則將追究法律責任。

相關文章