一次資料庫相關操作卡住的排查--enq: TX - row lock contention

還不算暈發表於2015-08-24
問題描述:某日客戶來電某HR系統排值班表的操作一直HANG住,一直無法完成。
這種問題,主要思路是圍繞檢視此操作因何HANG住。
常見的嚴重的HANG住有DB方面的AUDIT無空間、歸檔空間滿以及主機方面CPU/記憶體使用率高或/根目錄滿等狀況;

在此排查過程中,主機狀態是第一步要查詢的,如磁碟空間/CPU/記憶體使用情況等。
主機無異常後,檢視DB狀態,包括程式狀態。如檢視ALERT日誌、確認能否登陸,查詢一些V$檢視、進行REDO切換等;
在這些基礎的確認後再查詢當前正在發生的等待事件及相關SESSION資訊。

在本次問題中主要等待事件是enq: TX - row lock contention行鎖問題。大致處理思路如下:
1.查詢主機相關狀態是否正常
2.檢視DB狀態
3.檢視當前主要正在發生的等待事件及相關SESSION資訊
4.確認相關等待事件後進一步排查何種原因引起
5.找到原因後進行處理




分析處理過程如下:

1.查詢主機相關狀態是正常的,此處不再多寫輸出。

使用命令有如下:
[oracle@ABCSRV02 ~]$ top
[oracle@ABCSRV02 ~]$ free -m
[oracle@ABCSRV02 ~]$ cat /proc/meminfo
[oracle@ABCSRV02 ~]$ df -h

2.檢視DB狀態

檢視通過監聽連線的程式數
[oracle@ABCSRV02 ~]$ ps -ef|grep LOCAL=NO|wc -l
lsnrctl status
ps -ef|grep smon

sqlplus / as sysdba登陸後查詢瞭如下資訊:
--查詢例項狀態
select to_char(startup_time,'yyyy/mm/dd hh24:mi:ss'),instance_name,status from v$instance;
--查詢DB讀寫狀態
select name,open_mode from v$database;
--查詢資料檔案及表空間狀態是否正常
set linesize 160
set pagesize 1000
col tablespace_name for a22
select tablespace_name,status from dba_tablespaces;
select file#,status from v$datafile;
 select * from v$recover_file;
--進行REDO LOG切換
SQL> alter system switch logfile;
System altered.
此處確認狀態正常。

3.檢視當前主要正在發生的等待事件及相關SESSION資訊

set linesize 200
col event for a25
col username for a10
select g.Inst_id,g.sid,g.serial#,g.event,g.username, g.sql_id
from gv$session g,v$sql s
where g.Wait_class <> 'Idle' and g.sql_hash_value=s.HASH_VALUE;
 
本處查詢到的是TX鎖相關事件,使用如下SQL語句查詢:  
select g.Inst_id,g.sid,g.serial#,g.event,g.username, g.sql_id
from gv$session g,v$sql s
where g.Wait_class <> 'Idle' and g.sql_hash_value=s.HASH_VALUE and g.event like '%T%';
--為了隱私實際查詢的結果進行了一些修改。
   INST_ID        SID    SERIAL# EVENT                                    USERNAME   SQL_HASH_VALUE
---------- ---------- ---------- ---------------------------------------- ---------- --------------
         1       1056        397 enq: TX - row lock contention           ABCHR         1828393250
         1       1058       1981 enq: TX - row lock contention           ABCHR         3151192798
         1       1069       3802 enq: TX - row lock contention           ABCHR          734455977
         1       1075        397 enq: TX - row lock contention           ABCHR         3627991293
         1       1076       4025 enq: TX - row lock contention           ABCHR         3204010047
         1       1084       2990 enq: TX - row lock contention           ABCHR         3636242951
         1       1088       1185 enq: TX - row lock contention           ABCHR         1010386057
         1       1093        685 enq: TX - row lock contention           ABCHR         2969205112


4.確認相關等待事件後進一步排查


查詢到大量enq: TX - row lock contention後,需要查出這些會話等待在哪個會話來釋放enq: TX - row lock contention行鎖資源。
也就是被哪個會話的什麼操作阻塞。
--使用SQL如下:
select blocking_session,sid,serial#,wait_class,seconds_in_wait
from v$session
where blocking_session is not NULL
and sid in('sid');

如下查詢到是SID=1050的會話阻塞了這些SQL;
SQL> select blocking_session,sid,serial#,wait_class,seconds_in_wait
  2  from v$session
  3  where blocking_session is not NULL
and sid in(1056,1058,1069,1075,1076,1084,1088,1093);
  4  
BLOCKING_SESSION        SID    SERIAL# WAIT_CLASS              SECONDS_IN_WAIT
---------------- ---------- ---------- ----------------------- ---------------
            1050       1056        397 Application                       10561
            1050       1058       1981 Application                        4129
            1050       1069       3802 Application                        8549
            1050       1075        397 Application                       10913
            1050       1076       4025 Application                         623
            1050       1084       2990 Application                        6234
            1050       1088       1185 Application                        2549
            1050       1093        685 Application                        8264

8 rows selected.

下一步進行查詢SID=1050的會話在執行什麼操作有何等待事件
SQL> set linesize 200
SQL> select sid,serial#,machine,program,EVENT,SQL_ID,STATUS from v$session where sid in('1050');

       SID    SERIAL# MACHINE              PROGRAM              EVENT                     SQL_ID        STATUS
---------- ---------- -------------------- -------------------- ------------------------- ------------- --------
      1050          8 ABCSRV01            JDBC Thin Client     latch: cache buffers chai 62rv794fswmcy ACTIVE
                                                                ns
可以看到此會話在執行的SQLID為62rv794fswmcy,相關等待事件是:latch: cache buffers chains;
進一步得出此SQL語句的文字及相應執行計劃,以及事務的相關資訊。
--如下SQL語句擷取了部分,並修改了表、列名資訊。語句較長,有多個case when判斷及巢狀多個檢視等複雜查詢;
SQL> select sql_text from v$sqltext where sql_id='62rv794fswmcy' order by PIECE;

SQL_TEXT
----------------------------------------------------------------
update AAAA set ts='2015-08-24 13:14:10',AAAAA = ( cas
e when ( pAAAs = 'AA' or pAAAs = 'AAAAAAAA' ) then 0 else
 ( select AAAA from AAAA where pk_bclbid = AAAA.p
kAAAs ) end ), if_rest = ( case when ( pAAss = 'AAAX' or pk_c

檢視此SQL的執行計劃等資訊--這裡使用了awrsqrpt報告
--從遊標快取中查詢此SQL語句執行計劃資訊:
col plan_table_output for a100
set long 900
set pagesize 100
 select * from table(dbms_xplan.display_cursor('62rv794fswmcy',0,'advanced'));
--生成awrsqrpt報告
SQL> @?/rdbms/admin/awrsqrpt.sql
---此處執行計劃太長,文字型的基本不具有可讀性,參考了awrsqrpt報告中的資訊如下。
Stat Name    Statement Total    Per Execution    % Snap Total
Elapsed Time (ms)     2,686,331           4.69
CPU Time (ms)     2,669,779           24.23
Executions     0           
Buffer Gets     239,883,842           24.78
Disk Reads     0           0.00
Parse Calls     1           0.00
--可以看到此SQL語句目前已經執行了2686秒,Buffer Gets的資料塊個數是239,883,842,2億多個。



進一步查詢此SQL對應的會話資訊:
SQL> select sid,serial#,machine,program,EVENT,SADDR,STATUS from v$session where SADDR in(select SES_ADDR from v$transaction) and sid=1050;

       SID    SERIAL# MACHINE    PROGRAM              EVENT                                    SADDR            STATUS
---------- ---------- ---------- -------------------- ---------------------------------------- ---------------- ----------
      1050          8 ABCSRV01  JDBC Thin Client     SQL*Net more data from client            000000075B9EE930 ACTIVE


SQL> select START_TIME,STATUS,SES_ADDR from v$transaction where ses_addr='000000075B9EE930';

START_TIME           STATUS     SES_ADDR
-------------------- ---------- ----------------
08/24/15 10:37:21    ACTIVE     000000075B9EE930

可以看到此事務從上午10:37開始執行一直到進行處理時的14:30左右還在執行;
經觀察此會話執行的SQL不只上面查出的一條且都執行時間較長,因此判斷是同一事務中的多個大型SQL;
因SQL執行速度較慢且在同一事務中,在全部SQL執行完之前事務不提交也不回滾,導致TX行鎖資源一直得不到釋放。
進而導致其它會話的相關操作都HANG住在等待此會話釋放TX鎖資源。


5.找到問題原因--TX - row lock contention產生原因並進行處理

經與使用者確認,決定KILL此會話;同時聯絡業務部門確認此會話的相關SQL執行的為何種操作並進行修正。
--KILL會話及後續查詢如下:
SQL> col  EVENT for a20
SQL> select sid,serial#,machine,program,EVENT,SADDR,SQL_ID,STATUS from v$session where SADDR in(select SES_ADDR from v$transaction) and sid=1050;

       SID    SERIAL# MACHINE    PROGRAM                   EVENT                SADDR            SQL_ID        STATUS
---------- ---------- ---------- ------------------------- -------------------- ---------------- ------------- ----------
      1050          8 ABCSRV01  JDBC Thin Client          latch free           000000075B9EE930 36mu7qg6cc5yu ACTIVE

SQL> alter system kill session '1050,8';

System altered.

SQL> select sid,serial#,machine,program,EVENT,SADDR,SQL_ID,STATUS from v$session where SADDR in(select SES_ADDR from v$transaction) and sid=1050;

no rows selected

此時還有部分事務在等待TX鎖,稍等後再查詢,之前被阻塞的事務全部完成。

SQL> select sid,serial#,machine,program,EVENT,SQL_ID,STATUS from v$session where SADDR in(select SES_ADDR from v$transaction);

       SID    SERIAL# MACHINE    PROGRAM                   EVENT                SQL_ID        STATUS
---------- ---------- ---------- ------------------------- -------------------- ------------- ----------
      1056        397 ABCSRV01  JDBC Thin Client          enq: TX - row lock c 2u1bpvx9s2ygp ACTIVE
                                                           ontention
SQL> select sid,serial#,machine,program,EVENT,SQL_ID,STATUS,saddr from v$session where SADDR in(select SES_ADDR from v$transaction);

no rows selected

SQL> select START_TIME,STATUS,SES_ADDR from v$transaction;

no rows selected


注意事項:

大事務回滾時可能會產生大量REDO資訊;
同時並行回滾引數設定不當(如過高)也可能導致回滾事務時HANG住,建議使用預設值LOW。
SQL> show parameter fast_start_p

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
fast_start_parallel_rollback         string      LOW
檢視一個引數是否預設值及允許的值
set linesize 200
col NAME for a30
 col value for a30
col isdefault for a10
select * from V$PARAMETER_VALID_VALUES where name='fast_start_parallel_rollback';

       NUM NAME                              ORDINAL VALUE                          ISDEFAULT
---------- ------------------------------ ---------- ------------------------------ ----------
       782 fast_start_parallel_rollback            1 FALSE                          FALSE
       782 fast_start_parallel_rollback            2 LOW                            TRUE
       782 fast_start_parallel_rollback            3 HIGH                           FALSE
SQL> select * from V$PARAMETER_VALID_VALUES where name like '%statistics_level%';

       NUM NAME                              ORDINAL VALUE                          ISDEFAULT
---------- ------------------------------ ---------- ------------------------------ ----------
      1182 statistics_level                        1 BASIC                          FALSE
      1182 statistics_level                        2 TYPICAL                        TRUE
      1182 statistics_level                        3 ALL                            FALSE
---------
Mon Aug 24 14:00:52 2015
Thread 1 advanced to log sequence 81771 (LGWR switch)
  Current log# 3 seq# 81771 mem# 0: /oralog/orcl/redo03.log
Mon Aug 24 14:47:49 2015
SMON: Restarting fast_start parallel rollback
Mon Aug 24 14:47:57 2015
ORA-00060: Deadlock detected. More info in file /u01/app/oracle/admin/orcl/udump/orcl_ora_27174.trc.
Mon Aug 24 14:47:57 2015
Thread 1 advanced to log sequence 81772 (LGWR switch)
Mon Aug 24 14:47:57 2015
Thread 1 advanced to log sequence 81772 (LGWR switch)
  Current log# 1 seq# 81772 mem# 0: /oralog/orcl/redo01.log
Mon Aug 24 14:48:09 2015
Thread 1 advanced to log sequence 81773 (LGWR switch)
  Current log# 2 seq# 81773 mem# 0: /oralog/orcl/redo02.log
Thread 1 cannot allocate new log, sequence 81774
Checkpoint not complete
  Current log# 2 seq# 81773 mem# 0: /oralog/orcl/redo02.log
Mon Aug 24 14:48:44 2015
Thread 1 advanced to log sequence 81774 (LGWR switch)
  Current log# 3 seq# 81774 mem# 0: /oralog/orcl/redo03.log
Mon Aug 24 14:48:55 2015
Thread 1 cannot allocate new log, sequence 81775
Checkpoint not complete
  Current log# 3 seq# 81774 mem# 0: /oralog/orcl/redo03.log

相關文章