【DBA】如何通過dba_hist_active_sess_history分析資料庫歷史效能問題

xysoul_雲龍發表於2017-07-08

如何通過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#
 order siblings by dbid, sample_time;

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的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/29487349/viewspace-2141745/,如需轉載,請註明出處,否則將追究法律責任。

相關文章