如何透過dba_hist_active_sess_history分析歷史資料庫效能問題
如何透過dba_hist_active_sess_history分析歷史資料庫效能問題
背景在很多情況下，當資料庫發生效能問題的時候，我們並沒有機會來收集足夠的診斷資訊，比如system state dump或者hang analyze，甚至問題發生的時候DBA根本不在場。這給我們診斷問題帶來很大的困難。那麼在這種情況下，我們是否能在事後收集一些資訊來分析問題的原因呢？在Oracle 10G或者更高版本上，答案是肯定的。本文我們將介紹一種透過dba_hist_active_sess_history的資料來分析問題的一種方法。
適用於
Oracle 10G或更高版本，本文適用於任何平臺。
詳情
在Oracle 10G中，我們引入了AWR和ASH取樣機制，有一個檢視gv$active_session_history會每秒鐘將資料庫所有節點的Active Session取樣一次，而dba_hist_active_sess_history則會將gv$active_session_history裡的資料每10秒取樣一次並持久化儲存。基於這個特徵，我們可以透過分析dba_hist_active_sess_history的Session取樣情況，來定位問題發生的準確時間範圍，並且可以觀察每個取樣點的top event和top holder。下面透過一個例子來詳細說明。
1. Dump出問題期間的ASH資料：
為了不影響生產系統，我們可以將問題大概期間的ASH資料export出來在測試機上分析。
基於dba_hist_active_sess_history建立一個新表m_ash，然後將其透過exp/imp匯入到測試機。在發生問題的資料庫上執行exp:
SQL> conn user/passwd
SQL> create table m_ash as select * from dba_hist_active_sess_history where SAMPLE_TIME between TO_TIMESTAMP ('<time_begin>', 'YYYY-MM-DD HH24:MI:SS') and TO_TIMESTAMP ('<time_end>', 'YYYY-MM-DD HH24:MI:SS');
$ exp user/passwd file=m_ash.dmp tables=(m_ash) log=m_ash.exp.log
然後匯入到測試機：
$ imp user/passwd file=m_ash.dmp log=m_ash.imp.log
2. 驗證匯出的ASH時間範圍:
為了加快速度，我們採用了並行查詢。另外建議採用Oracle SQL Developer來查詢以防止輸出結果折行不便於觀察。
set line 200 pages 1000
col sample_time for a25
col event for a40
alter session set nls_timestamp_format='yyyy-mm-dd hh24:mi:ss.ff';
select /*+ parallel 8 */
t.dbid, t.instance_number, min(sample_time), max(sample_time), count(*) session_count
from m_ash t
group by t.dbid, t.instance_number
order by dbid, instance_number;
INSTANCE_NUMBER MIN(SAMPLE_TIME) MAX(SAMPLE_TIME) SESSION_COUNT
1 2015-03-26 21:00:04.278 2015-03-26 22:59:48.387 2171
2 2015-03-26 21:02:12.047 2015-03-26 22:59:42.584 36
從以上輸出可知該資料庫共2個節點，取樣時間共2小時，節點1的取樣比節點2要多很多，問題可能發生在節點1上。
3. 確認問題發生的精確時間範圍:
參考如下指令碼：
select /*+ parallel 8 */
dbid, instance_number, sample_id, sample_time, count(*) session_count
from m_ash t
group by dbid, instance_number, sample_id, sample_time
order by dbid, instance_number, sample_time;
INSTANCE_NUMBER SAMPLE_ID SAMPLE_TIME SESSION_COUNT
1 36402900 2015-03-26 22:02:50.985 4
1 36402910 2015-03-26 22:03:01.095 1
1 36402920 2015-03-26 22:03:11.195 1
1 36402930 2015-03-26 22:03:21.966 21
1 36402940 2015-03-26 22:03:32.116 102
1 36402950 2015-03-26 22:03:42.226 181
1 36402960 2015-03-26 22:03:52.326 200
1 36402970 2015-03-26 22:04:02.446 227
1 36402980 2015-03-26 22:04:12.566 242
1 36402990 2015-03-26 22:04:22.666 259
1 36403000 2015-03-26 22:04:32.846 289
1 36403010 2015-03-26 22:04:42.966 147
1 36403020 2015-03-26 22:04:53.076 2
1 36403030 2015-03-26 22:05:03.186 4
1 36403040 2015-03-26 22:05:13.296 1
1 36403050 2015-03-26 22:05:23.398 1
注意觀察以上輸出的每個取樣點的active session的數量，數量突然變多往往意味著問題發生了。從以上輸出可以確定問題發生的精確時間在2015-03-26 22:03:21 ~ 22:04:42，問題持續了大約1.5分鐘。
注意: 觀察以上的輸出有無斷檔，比如某些時間沒有采樣。
4. 確定每個取樣點的top n event:
在這裡我們指定的是top 2 event，並且注掉了取樣時間以觀察所有采樣點的情況。如果資料量較多，您也可以透過開啟sample_time的註釋來觀察某個時間段的情況。注意最後一列session_count指的是該取樣點上的等待該event的session數量。
select t.dbid,
t.sample_id,
t.sample_time,
t.instance_number,
t.event,
t.session_state,
t.c session_count
from (select t.*,
rank() over(partition by dbid, instance_number, sample_time order by c desc) r
from (select /*+ parallel 8 */
t.*,
count(*) over(partition by dbid, instance_number, sample_time, event) c,
row_number() over(partition by dbid, instance_number, sample_time, event order by 1) r1
from m_ash t
/*where sample_time >
to_timestamp('2013-11-17 13:59:00',
'yyyy-mm-dd hh24:mi:ss')
and sample_time <
to_timestamp('2013-11-17 14:10:00',
'yyyy-mm-dd hh24:mi:ss')*/
) t
where r1 = 1) t
where r < 3
order by dbid, instance_number, sample_time, r;
SAMPLE_ID SAMPLE_TIME INSTANCE_NUMBER EVENT SESSION_STATE SESSION_COUNT
36402900 22:02:50.985 1 ON CPU 3
36402900 22:02:50.985 1 db file sequential read WAITING 1
36402910 22:03:01.095 1 ON CPU 1
36402920 22:03:11.195 1 db file parallel read WAITING 1
36402930 22:03:21.966 1 cursor: pin S wait on X WAITING 11
36402930 22:03:21.966 1 latch: shared pool WAITING 4
36402940 22:03:32.116 1 cursor: pin S wait on X WAITING 83
36402940 22:03:32.116 1 SGA: allocation forcing component growth WAITING 16
36402950 22:03:42.226 1 cursor: pin S wait on X WAITING 161
36402950 22:03:42.226 1 SGA: allocation forcing component growth WAITING 17
36402960 22:03:52.326 1 cursor: pin S wait on X WAITING 177
36402960 22:03:52.326 1 SGA: allocation forcing component growth WAITING 20
36402970 22:04:02.446 1 cursor: pin S wait on X WAITING 204
36402970 22:04:02.446 1 SGA: allocation forcing component growth WAITING 20
36402980 22:04:12.566 1 cursor: pin S wait on X WAITING 219
36402980 22:04:12.566 1 SGA: allocation forcing component growth WAITING 20
36402990 22:04:22.666 1 cursor: pin S wait on X WAITING 236
36402990 22:04:22.666 1 SGA: allocation forcing component growth WAITING 20
36403000 22:04:32.846 1 cursor: pin S wait on X WAITING 265
36403000 22:04:32.846 1 SGA: allocation forcing component growth WAITING 20
36403010 22:04:42.966 1 enq: US - contention WAITING 69
36403010 22:04:42.966 1 latch: row cache objects WAITING 56
36403020 22:04:53.076 1 db file scattered read WAITING 1
36403020 22:04:53.076 1 db file sequential read WAITING 1
從以上輸出我們可以發現問題期間最嚴重的等待為cursor: pin S wait on X，高峰期等待該event的session數達到了265個，其次為SGA: allocation forcing component growth，高峰期session為20個。
注意:
1) 再次確認以上輸出有無斷檔，是否有某些時間沒有采樣。
2) 注意那些session_state為ON CPU的輸出，比較ON CPU的程式個數與您的OS物理CPU的個數，如果接近或者超過物理CPU個數，那麼您還需要檢查OS當時的CPU資源狀況，比如OSWatcher/NMON等工具，高的CPU Run Queue可能引發該問題，當然也可能是問題的結果，需要結合OSWatcher和ASH的時間順序來驗證。
5. 觀察每個取樣點的等待鏈:
其原理為透過dba_hist_active_sess_history. blocking_session記錄的holder來透過connect by級聯查詢，找出最終的holder. 在RAC環境中，每個節點的ASH取樣的時間很多情況下並不是一致的，因此您可以透過將本SQL的第二段註釋的sample_time稍作修改讓不同節點相差1秒的取樣時間可以比較(注意最好也將partition by中的sample_time做相應修改)。該輸出中isleaf=1的都是最終holder，而iscycle=1的代表死鎖了(也就是在同一個取樣點中a等b，b等c，而c又等a，這種情況如果持續發生，那麼尤其值得關注)。採用如下查詢能觀察到阻塞鏈。
select /*+ parallel 8 */
level lv,
connect_by_isleaf isleaf,
connect_by_iscycle iscycle,
t.dbid,
t.sample_id,
t.sample_time,
t.instance_number,
t.session_id,
t.sql_id,
t.session_type,
t.event,
t.session_state,
t.blocking_inst_id,
t.blocking_session,
t.blocking_session_status
from m_ash t
/*where sample_time >
to_timestamp('2013-11-17 13:55:00',
'yyyy-mm-dd hh24:mi:ss')
and sample_time <
to_timestamp('2013-11-17 14:10:00',
'yyyy-mm-dd hh24:mi:ss')*/
start with blocking_session is not null
connect by nocycle
prior dbid = dbid
and prior sample_time = sample_time
/*and ((prior sample_time) - sample_time between interval '-1'
second and interval '1' second)*/
and prior blocking_inst_id = instance_number
and prior blocking_session = session_id
and prior blocking_session_serial# = session_serial#;
LV ISLEAF ISCYCLE SAMPLE_TIME INSTANCE_NUMBER SESSION_ID SQL_ID EVENT SESSION_STATE BLOCKING_INST_ID BLOCKING_SESSION BLOCKING_SESSION_STATUS
1 0 0 22:04:32.846 1 1259 3ajt2htrmb83y cursor: WAITING 1 537 VALID
2 1 0 22:04:32.846 1 537 3ajt2htrmb83y SGA: WAITING UNKNOWN
注意為了輸出便於閱讀，我們將等待event做了簡寫，下同。從上面的輸出可見，在相同的取樣點上(22:04:32.846)，節點1 session 1259在等待cursor: pin S wait on X，其被節點1 session 537阻塞，而節點1 session 537又在等待SGA: allocation forcing component growth，並且ASH沒有采集到其holder，因此這裡cursor: pin S wait on X只是一個表面現象，問題的原因在於SGA: allocation forcing component growth
6. 基於第5步的原理來找出每個取樣點的最終top holder:
比如如下SQL列出了每個取樣點top 2的blocker session，並且計算了其最終阻塞的session數(參考blocking_session_count)
select t.lv,
t.iscycle,
t.dbid,
t.sample_id,
t.sample_time,
t.instance_number,
t.session_id,
t.sql_id,
t.session_type,
t.event,
t.seq#,
t.session_state,
t.blocking_inst_id,
t.blocking_session,
t.blocking_session_status,
t.c blocking_session_count
from (select t.*,
row_number() over(partition by dbid, instance_number, sample_time order by c desc) r
from (select t.*,
count(*) over(partition by dbid, instance_number, sample_time, session_id) c,
row_number() over(partition by dbid, instance_number, sample_time, session_id order by 1) r1
from (select /*+ parallel 8 */
level lv,
connect_by_isleaf isleaf,
connect_by_iscycle iscycle,
t.*
from m_ash t
/*where sample_time >
to_timestamp('2013-11-17 13:55:00',
'yyyy-mm-dd hh24:mi:ss')
and sample_time <
to_timestamp('2013-11-17 14:10:00',
'yyyy-mm-dd hh24:mi:ss')*/
start with blocking_session is not null
connect by nocycle
prior dbid = dbid
and prior sample_time = sample_time
/*and ((prior sample_time) - sample_time between interval '-1'
second and interval '1' second)*/
and prior blocking_inst_id = instance_number
and prior blocking_session = session_id
and prior
blocking_session_serial# = session_serial#) t
where t.isleaf = 1) t
where r1 = 1) t
where r < 3
order by dbid, sample_time, r;
SAMPLE_TIME INSTANCE_NUMBER SESSION_ID SQL_ID EVENT SEQ# SESSION_STATE BLOCKING_SESSION_STATUS BLOCKING_SESSION_COUNT
22:03:32.116 1 1136 1p4vyw2jan43d SGA: 1140 WAITING UNKNOWN 82
22:03:32.116 1 413 9g51p4bt1n7kz SGA: 7646 WAITING UNKNOWN 2
22:03:42.226 1 1136 1p4vyw2jan43d SGA: 1645 WAITING UNKNOWN 154
22:03:42.226 1 537 3ajt2htrmb83y SGA: 48412 WAITING UNKNOWN 4
22:03:52.326 1 1136 1p4vyw2jan43d SGA: 2150 WAITING UNKNOWN 165
22:03:52.326 1 537 3ajt2htrmb83y SGA: 48917 WAITING UNKNOWN 8
22:04:02.446 1 1136 1p4vyw2jan43d SGA: 2656 WAITING UNKNOWN 184
22:04:02.446 1 537 3ajt2htrmb83y SGA: 49423 WAITING UNKNOWN 10
22:04:12.566 1 1136 1p4vyw2jan43d SGA: 3162 WAITING UNKNOWN 187
22:04:12.566 1 2472 SGA: 1421 WAITING UNKNOWN 15
22:04:22.666 1 1136 1p4vyw2jan43d SGA: 3667 WAITING UNKNOWN 193
22:04:22.666 1 2472 SGA: 1926 WAITING UNKNOWN 25
22:04:32.846 1 1136 1p4vyw2jan43d SGA: 4176 WAITING UNKNOWN 196
22:04:32.846 1 2472 SGA: 2434 WAITING UNKNOWN 48
注意以上輸出，比如第一行，代表在22:03:32.116，節點1的session 1136最終阻塞了82個session. 順著時間往下看，可見節點1的session 1136是問題期間最嚴重的holder，它在每個取樣點都阻塞了100多個session，並且它持續等待SGA: allocation forcing component growth，注意觀察其seq#您會發現該event的seq#在不斷變化，表明該session並未完全hang住，由於時間正好發生在夜間22:00左右,這顯然是由於自動收集統計資訊job導致shared memory resize造成，因此可以結合Scheduler/MMAN/MMNL的trace以及dba_hist_memory_resize_ops的輸出進一步確定問題。
注意：
1) blocking_session_count 指某一個holder最終阻塞的session數，比如 a <- b<- c （a被b阻塞,b又被c阻塞），只計算c阻塞了1個session，因為中間的b可能在不同的阻塞鏈中發生重複。
2) 如果最終的holder沒有被ash取樣(一般因為該holder處於空閒)，比如 a<- c 並且b<- c (a被c阻塞，並且b也被c阻塞)，但是c沒有采樣，那麼以上指令碼無法將c統計到最終holder裡，這可能會導致一些遺漏。
3) 注意比較blocking_session_count的數量與第3步查詢的每個取樣點的總session_count數，如果每個取樣點的blocking_session_count數遠小於總session_count數，那表明大部分session並未記載holder，因此本查詢的結果並不能代表什麼。
4) 在Oracle 10g中，ASH並沒有blocking_inst_id列，在以上所有的指令碼中，您只需要去掉該列即可。因此10g的ASH一般只能用於診斷單節點的問題。
其他關於ASH的應用
除了透過ASH資料來找holder以外，我們還能用它來獲取很多資訊(基於資料庫版本有所不同)：
比如透過PGA_ALLOCATED列來計算每個取樣點的最大PGA，合計PGA以分析ora-4030/Memory Swap相關問題；
透過TEMP_SPACE_ALLOCATED列來分析臨時表空間使用情況；
透過IN_PARSE/IN_HARD_PARSE/IN_SQL_EXECUTION列來分析SQL處於parse還是執行階段;
透過CURRENT_OBJ#/CURRENT_FILE#/CURRENT_BLOCK#來確定I/O相關等待發生的物件
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/29209863/viewspace-2128009/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 【DBA】如何通過dba_hist_active_sess_history分析資料庫歷史效能問題資料庫
- 如何透過SQLyog分析MySQL資料庫MySql資料庫
- 分析發生在過去的資料庫效能問題資料庫
- 如何透過一條資料庫語句做資料分析資料庫
- 資料庫Server效能問題分析案例一資料庫Server
- Oracle技術支援是如何分析資料庫效能問題的Oracle資料庫
- 資料庫歷史資料有效管理資料庫
- 透過socket訪問資料庫(轉)資料庫
- memlock過低導致的資料庫效能問題資料庫
- Fabric 1.0原始碼分析(21)Ledger #historydb（歷史資料庫）原始碼資料庫
- 如何透過holer從外網訪問本地的資料庫？資料庫
- 透過addm分析io問題
- 透過vmstat的簡單分析資料庫操作資料庫
- 透過歷史記錄執行本地模型模型
- 資料庫效能問題解決過程1例子資料庫
- 誤刪出資料檔案，透過dbca無法刪除資料庫問題資料庫
- 透過連線資料庫來動態的生成樹的問題資料庫
- 如何透過.dbf檔案還原資料庫資料庫
- openGauss資料庫分析問題資料庫
- 資料庫索引分裂 問題分析資料庫索引
- 透過等待看資料庫資料庫
- 【TRACE】如果通過10046跟蹤資料庫效能問題資料庫
- 直接透過ODBC API訪問SQL資料庫 (轉)APISQL資料庫
- 改寫資料庫歷史的中國人資料庫
- 如何使用AWR報告來診斷資料庫效能問題資料庫
- 如何分析報表效能問題
- 透過sqlplus連線資料庫伺服器很慢的問題SQL資料庫伺服器
- 資料庫學習筆記1(資料管理歷史)資料庫筆記
- 巧用閃回資料庫來檢視歷史資料資料庫
- webwork問題：經過研究表明，ww標籤庫也是透過request獲得資料的Web
- MongoDB資料庫效能分析MongoDB資料庫
- 監視資料庫映象的歷史記錄資料庫
- 如何透過資料分析來支援TPM模式的決策？模式
- 一種透過延遲事務提升資料庫效能的方法資料庫
- 透過預熱來最佳化PG資料庫的SQL效能資料庫SQL
- 從AdventureWorks學習資料庫建模——保留歷史資料資料庫
- 測了一下 透過 DBCA 透過模板 複製資料庫（資料庫架構及資料）資料庫架構
- 透過SQL_ID檢視SQL歷史執行資訊SQL