匪夷所思：罕見的 Oracle 全域性事務鎖等待事件分析
這是在某客戶現場的一次即時分析，這個問題困擾了使用者一段時間，資料庫體現為嚴重的效能問題，導致應用出現大範圍超時以及會話激增等問題，多次嘗試 kill session 都無法徹底解決問題，重啟後系統恢復正常。
拿到故障時刻的 AWR 報告，可以發現問題時刻，資料庫的主要等待為：
Global transaction acquire instance locks和 enq: TX - row lock contention。
| Event |
Waits |
Time(s) |
Avg wait (ms) |
% DB time |
Wait Class |
| Global transaction acquire instance locks |
5,342 |
5,343 |
1000 |
74.09 |
Configuration |
| enq: TX - row lock contention |
5 |
1,437 |
287308 |
19.92 |
Application |
| DB CPU |
331 |
4.59 |
|||
| direct path read |
37,708 |
72 |
2 |
0.99 |
User I/O |
| log file sync |
7,817 |
12 |
2 |
0.16 |
Commit |
其中 TX – row lock contention 等待十分常見，這個等待事件造成應用的阻塞也很容易理解，但是Global transaction acquire instance locks並不是常見等待，從字面上理解，是全域性事務在嘗試獲取例項鎖。這個等待在等待時間佔比上，消耗了將近75%的DB TIME。
當然資料庫中TOP 5中最嚴重的等待不一定是問題的根源，分析問題時刻的 ASH 資訊，在問題時刻，最先出現的是全域性事務獲取鎖的等待，隨後開始出現行鎖等待：
SQL> select to_char(sample_time, 'hh24miss'), session_id, event, blocking_session 2 from dba_hist_active_sess_history 3 where sample_time >= to_date('201810180652', 'yyyymmddhh24mi') 4 and sample_time <= to_date('201810180700', 'yyyymmddhh24mi') 5 and instance_number = 1 6 order by 1, 2;
首先出現問題的是會話 763，其處於Global transaction acquire instance locks等待中，該會話並未顯示被其他會話阻塞。之後開始出現了行鎖等待，這些等待enq: TX - row lock contention的會話，其阻塞物件都是會話763。
顯然在本次故障中，雖然最終導致大範圍業務掛起的是enq: TX - row lock contention等待，但是最終問題的根源是Global transaction acquire instance locks等待。
幾乎與此同時，後臺告警日誌出現大量的報錯：
Thu Oct 18 06:53:33 2018 opiodr aborting process unknown ospid (26428) as a result of ORA-24756 Thu Oct 18 06:53:36 2018 Errors in file /trace/orcl1_pmon_30688.trc: ORA-24756: transaction does not exist Errors in file /trace/orcl1_pmon_30688.trc: ORA-24756: transaction does not exist Errors in file /trace/orcl1_pmon_30688.trc: ORA-24756: transaction does not exist Errors in file /trace/orcl1_pmon_30688.trc: ORA-24756: transaction does not exist
資料庫中出現該等待的時間點 06:52，再考慮到等待在報錯前會經歷一個超時，因此資料庫中的等待與告警日誌中的 ORA-24756 錯誤有密切的關係。
以 ORA-24756 作為關鍵字查詢 MOS，可以找到與當前現象非常接近的文章：
PMON cleanup fails with ORA-24756: transaction does not exist (文件 ID 2299927.1)。
文件中描述的報錯現象與當前問題一致，且資料庫版本也很接近。 Oracle認為這個錯誤是由於PMON程序在清理不存在的事務時出現了卡住的現象 。
Oracle給出了幾個比較類似的bug，但是這些bug的狀態不是不可重現就是已中止，因此類似的問題並沒有明確的結論：
Bug 20676168 - PMON GOT CONTINUOUS ORA-24756 DURING SHUTDOWN <<<<<<<<<< Closed, Could Not Reproduce Bug 16317766 - EXADATA : ORA-24756: TRANSACTION DOES NOT EXIST <<<<<<<<<<<< Suspended, Req'd Info not Avail Bug 9757979 - PMON CLEANUP FAILS WITH ORA-24756: TRANSACTION DOES NOT EXIST <<<<<<<<<<< Closed, Could Not Reproduce
無論是Global transaction acquire instance locks等待還是後臺alert日誌中不斷出現的ORA-24756錯誤，問題都指向Oracle的鎖和全域性事務處理。
而從11g以後，RAC的全域性事務的處理由 後臺程序GTXn 來自動維護。該程序是否啟動受初始化引數 global_txn_processes 的控制，該引數預設值為1，也就是在資料庫啟動的時候會預設啟動GTXn程序。
詢問客戶近期是否進行過應用和資料庫的調整，可以確認的是客戶的應用程式並未發生任何變化，在之前也未出現過類似的問題，不過在出現問題之前， 資料庫做過主庫和Data Guard備庫之間的切換演練，而切換演練完成後，恢復正常業務時，就出現了這次故障。顯然這次切換演練的操作是被懷疑的重點 。
在詳細檢查了alert告警日誌後發現，在DATA GUARD演練後切換回主庫時，GTXn程序未啟動：
Thu Oct 18 02:36:18 2018 alter database commit to switchover to physical standby with session shutdown ALTER DATABASE COMMIT TO SWITCHOVER TO PHYSICAL STANDBY [Process Id: 4366] (orcl1) . Switchover: Primary controlfile converted to standby controlfile succesfully. Switchover: Complete - Database shutdown required Completed: alter database commit to switchover to physical standby with session shutdown Thu Oct 18 02:45:27 2018 . RFS[8]: Assigned to RFS process 3216 RFS[8]: Identified database type as 'physical standby': Client is ARCH pid 11990 Thu Oct 18 03:11:13 2018 alter database open AUDIT_TRAIL initialization parameter is changed to OS, as DB is NOT compatible for database opened with read-only access This instance was first to open Beginning standby crash recovery. Serial Media Recovery started . Thu Oct 18 03:11:13 2018 SMON: enabling cache recovery Dictionary check beginning Dictionary check complete Database Characterset is ZHS16GBK No Resource Manager plan active Starting background process GTX0 Thu Oct 18 03:11:14 2018 GTX0 started with pid=51, OS id=5041 replication_dependency_tracking turned off (no async multimaster replication found) Physical standby database opened for read only access. Completed: alter database open . Thu Oct 18 04:57:19 2018 alter database commit to switchover to primary with session shutdown ALTER DATABASE SWITCHOVER TO PRIMARY (orcl1) Maximum wait for role transition is 15 minutes. Switchover: Media recovery is still active Role Change: Canceling MRP - no more redo to apply . Switchover: Complete - Database mounted as primary Completed: alter database commit to switchover to primary with session shutdown Thu Oct 18 04:57:39 2018 alter database open This instance was first to open Picked broadcast on commit scheme to generate SCNs . Thu Oct 18 04:57:44 2018 QMNC started with pid=41, OS id=22585 LOGSTDBY: Validating controlfile with logical metadata LOGSTDBY: Validation complete Completed: alter database open . Thu Oct 18 06:53:33 2018 opiodr aborting process unknown ospid (26428) as a result of ORA-24756 Thu Oct 18 06:53:36 2018 Errors in file /trace/orcl1_pmon_30688.trc: ORA-24756: transaction does not exist Errors in file /trace/orcl1_pmon_30688.trc: . Starting background process GTX0 Thu Oct 18 09:51:20 2018 GTX0 started with pid=36, OS id=32470 Starting background process RCBG Thu Oct 18 09:51:20 2018
從上面節選的部分alert日誌可以看到，在2點36分，主庫執行了SWITCHOVER操作，開始切換演練。
● 在 3點11分 ，資料庫開啟，alert中提示，當前資料庫為物理備庫，為只讀開啟模式，在隨後的日誌中標紅的部分，顯示此時後臺程序GTX0程序啟動。
● 在 4點57分 ，資料庫再次執行SWITCHOVER切換，此時資料庫並未完全SHUTDOWN，而是直接轉換為MOUNT模式，並於4點57分44秒完成了資料庫的OPEN過程。但是這個時間段的alert中並未發現GXTn程序的啟動。
● 而在alert中發現GTX0程序再次出現，是故障之後例項1重啟時刻的 9點51分。
顯然，問題已經非常明確，在資料庫由物理備庫切換為主庫的過程中，GTXn程序沒有啟動，這導致了Oracle無法處理分散式事務的鎖問題，因此前臺會話出現Global transaction acquire instance locks等待，而後臺PMON也無法正常的清理會話和事務。
由於例項2在SWITCHOVER切換過程中是被SHUTDOWN後重新啟動的，因此例項2上的GTXn程序是正常啟動的，這也是應用切換到例項2上不在出現故障的原因。
如果要避免類似的問題產生，一方面在進行DATA GUARD的切換演練後，在主庫切換到PRIMARY模式後，再執行一次資料庫重啟的操作，確保所有必要的程序都會啟動。另一方面，對於應用程式，如果確實需要修改其他資料庫中的表，應該通過建立其他資料庫連線的方式來實現，避免在資料庫中通過資料庫鏈的方式直接更新遠端表。
這個案例給我們的警示是：
資料庫的工作非常緊密，不同版本的變化也不斷向前，瞭解資料庫不同版本的新特性，在進行變更時進行詳細的檢查確認，才能確保資料庫安全穩定執行，少出問題。
原文釋出時間為：2018-11-11
本文作者：楊廷琨