記一次通過v$active_session_history來分析問題的案例
關於：v$active_session_history是oracle中一個最重要的檢視之一，該檢視每秒一次記錄當前資料庫中的活動程序相關的資訊，可以用於問題的分析和診斷；同時awr還會將部分v$active_session_history中的部分記錄保留到dba_hist_active_session_history（10秒一次），我們常用的ash報告就源於此。 通過v$active_session_history 檢視，可以看到資料庫中的活動程序在做什麼操作，以及是否有發生阻塞等情況，在分析和解決問題的時候可以從中獲取較多的資訊。
以下案例是通過v$active_session_history分析當前某個生產庫問題發生的異常。
首先是應用監控發現某個例項異常，應用伺服器上有連線報錯，從報錯看是連線db出現的問題。
dba接到報警後，檢查相關的資料庫，發現當前已經恢復正常，確認應用恢復正常後，開始進行異常時間段的分析。
這個問題需要從兩個方面分析：
1、是應用負載增加，已有連線無法滿足，應用在不斷建立新的連線
2、db中出現異常，程序出現阻塞，新的事務無法重用現有連線，導致db中不斷新建連線
針對這個問題，我們首先分析了連線日誌，發現異常時間段確實有大量的新建連線。
但需要進一步分析是應用導致的還是db內部異常導致的。從應用負載看，並沒有明顯增加，問題集中在db當時是否出現異常等待。這個時候就需要從v$active_session_history分析（通常需要在發生異常後備份一次v$active_session_history，原因是v$ash的大小有限，如果不備份的話，後續分析時可能已經無法找到對應時間點的資料）。
1、首先需要確認異常的時間段 selectcount(*),sample_id,sample_time fromv$active_session_history ash where ash.sample_time between $1 and $2 group bysample_id,sample_time order by sample_id; COUNT(*) SAMPLE_ID SAMPLE_TIME 16 267491028 10-10月-17??01.40.01.180?下午 18 267491029 10-10月-17??01.40.02.192?下午 22 267491030 10-10月-17??01.40.03.195?下午 22 267491031 10-10月-17??01.40.04.209?下午 45 267491032 10-10月-17??01.40.05.221?下午 75 267491033 10-10月-17??01.40.06.233?下午 90 267491034 10-10月-17??01.40.07.246?下午 112 267491035 10-10月-17??01.40.08.259?下午 136 267491036 10-10月-17??01.40.09.296?下午 161 267491037 10-10月-17??01.40.10.309?下午 186 267491038 10-10月-17??01.40.11.322?下午 214 267491039 10-10月-17??01.40.12.336?下午 251 267491040 10-10月-17??01.40.13.350?下午 287 267491041 10-10月-17??01.40.14.364?下午 319 267491042 10-10月-17??01.40.15.379?下午 353 267491043 10-10月-17??01.40.16.393?下午 374 267491044 10-10月-17??01.40.17.408?下午 414 267491045 10-10月-17??01.40.18.423?下午 447 267491046 10-10月-17??01.40.19.440?下午 476 267491047 10-10月-17??01.40.20.456?下午 521 267491048 10-10月-17??01.40.21.472?下午 562 267491049 10-10月-17??01.40.22.489?下午 583 267491050 10-10月-17??01.40.23.507?下午 616 267491051 10-10月-17??01.40.24.552?下午 631 267491052 10-10月-17??01.40.25.570?下午 666 267491053 10-10月-17??01.40.26.589?下午 684 267491054 10-10月-17??01.40.27.609?下午 696 267491055 10-10月-17??01.40.28.629?下午 732 267491056 10-10月-17??01.40.29.649?下午 756 267491057 10-10月-17??01.40.30.672?下午 16 267491058 10-10月-17??01.40.31.693?下午 12 267491059 10-10月-17??01.40.32.707?下午 15 267491060 10-10月-17??01.40.33.719?下午
從面查詢的資訊中可以明顯看到活動程序在不斷的增加
2、確認異常時間段是否有異常的等待 select count(*),event from v$active_session_history ash where ash.sample_id between267491028 and 267491060 group by event having count(*)>100 COUNT(*) EVENT 322 10058 enq: TX - index contention
3、分析阻塞程序當前的操作（注：阻塞程序不一定都是活動程序，如果非活動程序的話，可能無法從v$active_session_history中查詢） 查詢4993程序在異常時間段內的操作，該程序未被其他程序阻塞（blocking_session為空），異常時間段內該程序的操作如下： selectash.sample_id,ash.sql_id,event,current_obj#,ash.current_file#,ash.current_block#,ash.session_state，ash.time_waited from v$active_session_history ash where sample_id between267491028 and 267491060 and sql_id = '38t8ff3k7t6g7' and SESSION_ID = 4993 order by time_waited; SAMPLE_ID SQL_ID EVENT CURRENT_OBJ# CURRENT_FILE# CURRENT_BLOCK# SESSION_STATE TIME_WAITED 267491047 38t8ff3k7t6g7 224704 467 817769 ON CPU 0 267491054 38t8ff3k7t6g7 224704 490 1801532 ON CPU 0 267491050 38t8ff3k7t6g7 db file sequential read 224704 473 2058359 WAITING 222 267491034 38t8ff3k7t6g7 db file sequential read 224704 289 2561727 WAITING 229 267491037 38t8ff3k7t6g7 db file sequential read 224704 146 2872842 WAITING 244 267491052 38t8ff3k7t6g7 db file sequential read 224704 489 1789069 WAITING 259 267491043 38t8ff3k7t6g7 db file sequential read 224704 215 2928079 WAITING 260 267491035 38t8ff3k7t6g7 db file sequential read 224704 271 2630866 WAITING 282 267491046 38t8ff3k7t6g7 db file sequential read 224704 311 3216267 WAITING 1710 267491031 38t8ff3k7t6g7 db file sequential read 224704 281 2558211 WAITING 1749 267491042 38t8ff3k7t6g7 db file sequential read 224704 515 1070381 WAITING 1764 267491048 38t8ff3k7t6g7 db file sequential read 224704 822 2498767 WAITING 1778 267491039 38t8ff3k7t6g7 db file sequential read 224704 822 2512572 WAITING 1847 267491032 38t8ff3k7t6g7 db file sequential read 224704 472 2053998 WAITING 2380
從上圖可以看到該語句是在做相同的insert操作，只是耗時比較久，io讀取都耗費在object_id為224704的物件上,這個物件就是表T_PUB_OVER_TIME_REC的主鍵 SQL> select object_namefrom dba_objects where object_id=224704; OBJECT_NAME -------------------------------------------------------------------------------- PK_OVER_TIME_REC_ID
SQL> selecttable_name,d.uniqueness from dba_indexes d where index_name='PK_OVER_TIME_REC_ID'; TABLE_NAME UNIQUENESS ---------------------------------------- T_PUB_OVER_TIME_REC UNIQUE
4、分析異常 ：為什麼insert操作中會在主鍵索引上有如此大量的io讀取呢？ 首先要先了解在insert的時候為什麼會需要讀取索引塊：一個是正常的insert到對應的索引塊，另外一個就是索引分裂。 在insert操作的時候，在表和索引上的插入不是完全一致的，主要的原因就是索引的結構導致的，插入的索引值是有序的，需要從根節點開始尋找，找到對應的塊再插入，這個問題後續大家可以自行研究一下，但不會耗費太多的資源。 另外一種就是可能引發異常的情況，索引分裂引發的大量的io讀取，這個一般是在大量空塊的索引在做分裂的時候平衡二叉樹遍歷空塊導致的。 針對這個問題，需要去分析一下PK_OVER_TIME_REC_ID（單列索引）上是否有大量的空塊，實際上我們直接比對索引和表的大小就可以得出結論，表和索引幾乎已經1:1了，正常來說這種單列索引會比表小很多的，因此這個索引中空塊的問題是比較嚴重的，詳細的資訊可以通過analyzee等命令去分析索引塊的實際情況，但需要注意對於大索引來說會耗費比較多的時間和資源，不建議在生產庫直接執行。 SQL> select bytes/1024/1024 from dba_segments wheresegment_name='T_PUB_OVER_TIME_REC'; BYTES/1024/1024 --------------- 1249 SQL> select bytes/1024/1024 from dba_segments wheresegment_name='PK_OVER_TIME_REC_ID'; BYTES/1024/1024 --------------- 1193
5、問題解決方案
這個問題從oracle官方沒找到過明確的答覆和最終的解決方案，臨時方案是重建空塊過多的索引，但該方案不能從根本上解決問題，經過一段時間執行後問題會重複發生，比較理想的解決方案是應用修改資料刪除的方案，使用分割槽等。