使用AWK分析Oracle系統鎖定、Hang狀態

 

在早期Oracle版本中，由於技術不成熟等原因，資料庫鎖定和僵死狀態還是時有發生的。對待這些問題，老先生們的處理策略無外乎是“重啟”和“考究”兩種策略。所謂“重啟”，透過強制的重啟伺服器或者資料庫，將軟硬體偶然出現的鎖定僵死狀態重置，是一種最簡單的處理辦法。但是，如果是應用程式層面潛在的缺陷、資料庫的Bug或者諸如大規模事務回滾的情況，重啟大法的作用是很有限的。況且，一些關鍵業務系統，重啟資料庫是需要很高階別的審批流程的。這個時候，就需要進行“考究”，仔細研究故障點進行精準分析。

 

“考究”的過程是非常複雜的。傳統方法是將資料庫記憶體狀態全部dump到Trace檔案中，從其中觀察到各個程式之間複雜的互動關係，最後定位到資料庫鎖定的原因。

 

由於Oracle的負責性，Trace文字檔案通常成千上萬行，進行讀取也是非常消耗精力的事情。資料庫故障在任何企業都是大事故，每分每秒都意味著巨大的經濟損失，早一分鐘定位錯誤，解決問題，是有著重大意義的。

 

Linux體系對於正規表示式、文字處理是有很強的積澱的。AWK/SED命令就可以處理比較負責的文字分析問題。於是，行業中推出了結合awk命令使用的ass109.awk命令程式，實現快速的系統trace檔案分析。

 

下面透過一個比較簡單的會話間鎖定測試，來演示awk命令處理思路。具體ass109.awk指令碼在網路上下載比較方便，就不累列本文。

 

1、測試環境準備

 

實驗環境選擇Oracle 11gR2，版本為11.2.0.4。

 

 

SQL> select * from v$version;

 

BANNER

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

Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

PL/SQL Release 11.2.0.4.0 - Production

CORE    11.2.0.4.0 Production

TNS for Linux: Version 11.2.0.4.0 - Production

NLSRTL Version 11.2.0.4.0 – Production

 

 

實驗場景找一個比較簡單的就好，雙Session共同更新相同記錄，構成鎖定狀態。

 

 

--Session 1

SQL> create table t as select object_id from dba_objects;

Table created

 

SQL> select sid from v$mystat where rownum<2;

 

       SID

----------

       319

 

SQL> delete t where object_id=1000;

1 row deleted

 

 

--Session 2

SQL> select sid from v$mystat where rownum<2;

 

       SID

----------

       479

 

SQL> delete t where object_id=1000;

(Hang住)

 

 

319和479會話處在鎖定等待狀態。

 

2、資料庫狀態Trace

 

下面就需要將系統狀態System State，筆者選擇使用oradebug工具來進行處理。

 

 

[oracle@testlife trace]$ sqlplus /nolog

 

SQL*Plus: Release 11.2.0.4.0 Production on Fri Oct 14 20:01:13 2016

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

 

SQL> conn / as sysdba

Connected.

SQL> oradebug setmypid

Statement processed.

SQL> oradebug dump systemstate 10;

Statement processed.

SQL> oradebug tracefile_name;

/u01/app/oracle/diag/rdbms/testdb/testdb/trace/testdb_ora_8344.trc

 

 

定位到Trace File所在的目錄，確認檔案生成。同時，確定ass109處理檔案也在該目錄下。

 

 

[oracle@testlife trace]$ ls -l | grep testdb_ora_8344.trc

-rw-r-----  1 oracle oinstall 1021451 Oct 14 20:01 testdb_ora_8344.trc

[oracle@testlife trace]$ ls -l | grep ass109.awk

-rw-r--r--  1 root   root       34549 Oct 14 19:25 ass109.awk

 

 

3、分析處理

 

使用awk分析trace檔案極其簡單，分析結果直接就輸出在螢幕中。

 

 

[oracle@testlife trace]$ awk -f ass109.awk testdb_ora_8344.trc

 

Starting Systemstate 1

............................

Ass.Awk Version 1.0.9 - Processing testdb_ora_8344.trc

 

System State 1

~~~~~~~~~~~~~~~~

1:                                     

2:  0: waiting for 'pmon timer'        

3:  0: waiting for 'rdbms ipc message' 

4:  0: waiting for 'VKTM Logical Idle Wait'

5:  0: waiting for 'rdbms ipc message' 

6:  0: waiting for 'DIAG idle wait'    

7:  0: waiting for 'rdbms ipc message' 

8:  0: waiting for 'DIAG idle wait'    

9:  0: waiting for 'rdbms ipc message' 

10: 0: waiting for 'rdbms ipc message' 

11: 0: waiting for 'rdbms ipc message' 

12: 0: waiting for 'rdbms ipc message' 

13: 0: waiting for 'smon timer'        

14: 0: waiting for 'rdbms ipc message' 

15: 0: waiting for 'rdbms ipc message' 

16: 0: waiting for 'rdbms ipc message' 

17:                                     

18:                                    

19: 0: waiting for 'rdbms ipc message' 

20: 0: waiting for 'Streams AQ: qmn coordinator idle wait'

21: 0: waiting for 'rdbms ipc message' 

22: 0: waiting for 'Streams AQ: qmn slave idle wait'

23: 0: waiting for 'Streams AQ: waiting for time management or cleanup tasks'

24: 0: waiting for 'Space Manager: slave idle wait'

25: 0: waiting for 'SQL*Net message from client'

26: 0: waiting for 'SQL*Net message from client'

27: 0: waiting for 'enq: TX - row lock contention'[Enqueue TX-00060002-00000611]

28:                                    

Blockers

~~~~~~~~

 

        Above is a list of all the processes. If they are waiting for a resource

        then it will be given in square brackets. Below is a summary of the

        waited upon resources, together with the holder of that resource.

        Notes:

        ~~~~~

         o A process id of '???' implies that the holder was not found in the

           systemstate.

 

                    Resource Holder State

Enqueue TX-00060002-00000611    26: 0: waiting for 'SQL*Net message from client'

 

Object Names

~~~~~~~~~~~~

Enqueue TX-00060002-00000611                                  

 

18642 Lines Processed.

 

 

分析結果很簡單，也很容易看懂。分析重點是從process入手，將當前系統中所有對應的Process資訊逐個整理出來，將對應的等待事件wait event理出來。最後，將存在Block的情況整理列出來。

 

從上面的結果看，可以發現資源Enqueue TX-00060002-00000611被26號會話持有，該會話卻處在等待使用者資訊輸入狀態。而上面的Process列表中，對於這個資源27號程式是等待持有的。

 

那麼，我們直到了26和27直接有問題，如何定位究竟哪個會話呢？注意：這個26和27對應的就是v$process中資料庫內部的程式編號PID。

 

 

 

SQL> select * from v$process where pid in (26,27);

 

ADDR                    PID SPID                    

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

00000001339FDBD0         26 7505                    

00000001339FEC88         27 8317                    

 

 

 

SQL> select sid, serial#, paddr, event from v$session where paddr in ('00000001339FDBD0','00000001339FEC88');

 

       SID    SERIAL# PADDR            EVENT

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

       319         21 00000001339FDBD0 SQL*Net message from client

       479         43 00000001339FEC88 enq: TX - row lock contention

 

 

正確定位到319和479會話。

 

3、結論

 

資料庫資源相互鎖定在應用領域非常常見，例如資源釋放問題、會話操作失誤和事務回滾等，都會引起或大或小的資源鎖定。透過awk命令配合ass109.awk命令檔案，可以比較方便的讓我們快速定位問題，解決問題。