ORACLE 归档空间满导致的enq: TX - row lock contention

  2016年10月10日，客户一预警系统发生会话数飙高，系统响应极慢，后来确诊根源是归档空间满，引起所有redo耗尽，导致会话堆积，下面是处理过程。
 操作系统：HP-UX B.11.31 U ia64
 数据库版本：ORACLE 10.2.0.5 RAC
 按照常规处理思路，首先查看RAC数据库的告警日志：
 实例1的告警日志
Mon Oct 10 19:24:48 EAT 2016
ORACLE Instance orcl1 - Can not allocate log, archival required
.
.
Mon Oct 10 19:26:28 EAT 2016
ORACLE Instance orcl1 - Can not allocate log, archival required
.
.
Mon Oct 10 20:06:21 EAT 2016
Errors in file /oracle/app/oracle/admin/orcl/bdump/orcl1_arc0_22630.trc:
ORA-19504: failed to create file "+SFILEARCHDG01"
ORA-17502: ksfdcre:4 Failed to create file +SFILEARCHDG01
ORA-15041: diskgroup space exhausted
 实例2的告警日志
Mon Oct 10 20:12:52 EAT 2016
Errors in file /oracle/app/oracle/admin/orcl/bdump/orcl2_arc1_8962.trc:
ORA-19504: failed to create file "+SFILEARCHDG01"
ORA-17502: ksfdcre:4 Failed to create file +SFILEARCHDG01
ORA-15041: diskgroup space exhausted
ARC1: Error 19504 Creating archive log file to '+SFILEARCHDG01'
ARCH: Archival stopped, error occurred. Will continue retrying
Mon Oct 10 20:12:52 EAT 2016
ORACLE Instance orcl2 - Archival Error
Mon Oct 10 20:12:52 EAT 2016
ORA-16038: log 12 sequence# 77053 cannot be archived
ORA-19504: failed to create file ""
ORA-00312: online log 12 thread 2: '+ORCLDG1/orcl/onlinelog/group_12.291.819723519'
ORA-00312: online log 12 thread 2: '+ORCLDG2/orcl/onlinelog/group_12.266.819723541'
 从实例1登录数据库查看ASM磁盘组使用情况
orcl1:[/oracle/app/oracle/admin/orcl/bdump]$asmcmd
ASMCMD> lsdg
State    Type    Rebal  Unbal  Sector  Block       AU  Total_MB  Free_MB  Req_mir_free_MB  Usable_file_MB  Offline_disks  Name
MOUNTED  NORMAL  N      N        1024   4096  1048576   1024000      678           102400          -50861              0 ORCLDG1/
MOUNTED  NORMAL  N      N        1024   4096  1048576   1024000     1389           102400          -50505              0  ORCLDG2/
MOUNTED  EXTERN  N      N        1024   4096  1048576    512000   100210                0          100210              0  ORCLDG3/
MOUNTED  NORMAL  N      N        1024   4096  1048576    307200     9659           102400          -46370              0  ORCLSYSDG01/
MOUNTED  NORMAL  N      N        1024   4096  1048576    204800     1376                0             688              0  SFILEARCHDG01/
 通过查看告警日志和ASM磁盘使用情况及2个节点个告警日志：可以判断是归档空间满、归档异常，redo组耗光后实例hang住了。
 如果查看数据库实例1的等待事件，发现等待事件 enq: TX - row lock contention已经比较严重：
SQL> SELECT INST_ID, EVENT, COUNT(*) CNT, SUM(WAIT_TIME) WT_TM
  2    FROM GV$SESSION_WAIT
  3   GROUP BY INST_ID, EVENT
  4   ORDER BY INST_ID, CNT DESC;
   INST_ID EVENT                                           CNT      WT_TM
---------- ---------------------------------------- ---------- ----------
         1 SQL*Net message from client                     265          0
         1 enq: TX - row lock contention                   132          0
         1 db file sequential read                         107         35
         1 jobq slave wait                                  19          0
         1 rdbms ipc message                                15          4
         1 read by other session                             7          0
         1 wait for a undo record                            5          0
         1 gcs remote message                                4          0
         1 enq: HW - contention                              2          0
         1 log file sequential read                          2          0
         1 db file scattered read                            2          0
         1 buffer busy waits                                 2          0
         1 latch: cache buffers chains                       2         -2
         1 enq: US - contention                              2          0
         1 PX Deq: Txn Recovery Start                        2          0
  按等待事件查看数据库中会话、执行sql的sql_id相关信息，发现等待事件enq: TX - row lock contention全是sql_id为90frgddxc2my0的sql引起的，并且有200多个积压的会话。 
SQL> select * from (
  2  select a.inst_id,
  3  a.sid,
  4  a.sql_id,
  5  a.event,
  6  a.status,
  7  connect_by_isleaf as isleaf,
  8  sys_connect_by_path(sid,'<-') tree,
  9  level as tree_level
 10  from gv$session a
 11  start with a.blocking_session is not null and event like '%enq: TX%'
 12  connect by nocycle a.sid = prior a.blocking_Session
 13  )
 14  where isleaf =1
 15  order by tree_level asc;
INST_ID        SID      SQL_ID        EVENT                                         STATUS       ISLEAF   TREE                                                                          TREE_LEVEL
----------        ----------  -------------   ----------------------------------------            --------         ----------   --------------------------------------------------------------------------------  ----------
         1       1892 90frgddxc2my0 enq: TX - row lock contention   ACTIVE            1        <-1892                                                                         1
SQL> select count(*)
  2    from gv$session
  3   where event='enq: TX - row lock contention'
  4     and inst_id=1
  5     and status='ACTIVE';
  COUNT(*)
----------
       210

  经确定90frgddxc2my0是一个update语句
SQL> select sql_fulltext from v$sql where sql_id='90frgddxc2my0';
SQL_FULLTEXT
--------------------------------------------------------------------------------
UPDATE INTF.OMGALARM A SET A.ALARMACTION = :B3 , A.VERSION = A.RECEIVETIME, A.RE

 查看集群数据库的日志组状态，发现实例2的redo组已经全部用上。
SQL> select * from v$log;
    GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ------------
         1          1      58663 1073741824          2 NO  ACTIVE           1.5122E+13    10-OCT-16
         2          1      58662 1073741824          2 NO  INACTIVE         1.5122E+13    10-OCT-16
         3          1      58661 1073741824          2 NO  INACTIVE         1.5122E+13    10-OCT-16
         4          1      58660 1073741824          2 NO  INACTIVE         1.5122E+13    10-OCT-16
         5          1      58665 1073741824          2 NO  CURRENT          1.5122E+13    10-OCT-16
         6          1      58664 1073741824          2 NO  ACTIVE           1.5122E+13    10-OCT-16
         7          2      77116 1073741824          2 NO  ACTIVE           1.5122E+13    11-OCT-16
         8          2      77117 1073741824          2 NO  ACTIVE           1.5122E+13    11-OCT-16
         9          2      77118 1073741824          2 NO  ACTIVE           1.5122E+13    11-OCT-16
        10          2      77114 1073741824          2 YES ACTIVE           1.5122E+13    10-OCT-16
        11          2      77115 1073741824          2 NO  ACTIVE           1.5122E+13    10-OCT-16
        12          2      77119 1073741824          2 NO  CURRENT          1.5122E+13    11-OCT-16
 到此，通过查询到的信息并结合告警日志，可以肯定：大量并发dml操作，引发归档暴增，耗光归档空间，使用完redo组，导致会话积压，进而集群hang住，应用系统响应缓慢。
 通过观察1节点的告警日志，还发现2个实例的redo切换很频繁，1分钟一次：
  节点1
Mon Oct 10 20:05:19 EAT 2016
Thread 1 cannot allocate new log, sequence 58490
All online logs needed archiving
  Current log# 1 seq# 58489 mem# 0: +ORCLSYSDG01/orcl/onlinelog/group_1.262.819722231
  Current log# 1 seq# 58489 mem# 1: +ORCLGDG02/orcl/onlinelog/group_1.264.819722239
Mon Oct 10 20:05:48 EAT 2016
Thread 1 advanced to log sequence 58490 (LGWR switch)
  Current log# 5 seq# 58490 mem# 0: +ORCLGDG01/orcl/onlinelog/group_5.293.819723461
  Current log# 5 seq# 58490 mem# 1: +ORCLGDG02/orcl/onlinelog/group_5.268.819723471
Mon Oct 10 20:06:18 EAT 2016
ORACLE Instance hnrmdb1 - Can not allocate log, archival required
Mon Oct 10 20:06:18 EAT 2016
Thread 1 cannot allocate new log, sequence 58491
All online logs needed archiving
  Current log# 5 seq# 58490 mem# 0: +ORCLGDG01/orcl/onlinelog/group_5.293.819723461
  Current log# 5 seq# 58490 mem# 1: +ORCLGDG02/orcl/onlinelog/group_5.268.819723471
Mon Oct 10 20:06:20 EAT 2016
Thread 1 advanced to log sequence 58491 (LGWR switch)
  Current log# 6 seq# 58491 mem# 0: +ORCLGDG01/orcl/onlinelog/group_6.292.819723491
  Current log# 6 seq# 58491 mem# 1: +ORCLGDG02/orcl/onlinelog/group_6.267.819723505

 采取的措施是，清理归档空间并增加2个实例的redo组数。
 增加redo组：
SQL> select * from v$logfile;
    GROUP# STATUS  TYPE     MEMBER                                                          IS_
---------- ------- -------  -------------------------------------------------------------   ---
         7 ONLINE           +ORCLDG01/orcl/onlinelog/group_7.275.819721599           NO
         7 ONLINE           +ORCLDG02/orcl/onlinelog/group_7.270.819721609             NO
        12 ONLINE           +ORCLDG01/orcl/onlinelog/group_12.291.819723519            NO
        12 ONLINE           +ORCLDG02/orcl/onlinelog/group_12.266.819723541            NO
        11 ONLINE           +ORCLDG01/orcl/onlinelog/group_11.297.819722567            NO
        11 ONLINE           +ORCLDG02/orcl/onlinelog/group_11.272.819722583            NO
        10 ONLINE           +ORCLDG01/orcl/onlinelog/group_10.288.819722545            NO
        10 ONLINE           +ORCLDG02/orcl/onlinelog/group_10.261.819722555            NO
         9 ONLINE           +ORCLDG01/orcl/onlinelog/group_9.266.819722429           NO
         9 ONLINE           +ORCLDG02/orcl/onlinelog/group_9.262.819722437             NO
         8 ONLINE           +ORCLDG01/orcl/onlinelog/group_8.265.819721623           NO
         8 ONLINE           +ORCLDG02/orcl/onlinelog/group_8.269.819721631             NO
         4 ONLINE           +ORCLDG01/orcl/onlinelog/group_4.294.819723443             NO
         4 ONLINE           +ORCLDG02/orcl/onlinelog/group_4.265.819723451             NO
         3 ONLINE           +ORCLDG01/orcl/onlinelog/group_3.279.819722327           NO
         3 ONLINE           +ORCLDG02/orcl/onlinelog/group_3.271.819722335             NO
         2 ONLINE           +ORCLDG01/orcl/onlinelog/group_2.267.819722257           NO
         2 ONLINE           +ORCLDG02/orcl/onlinelog/group_2.263.819722265             NO
         1 ONLINE           +ORCLDG01/orcl/onlinelog/group_1.262.819722231           NO
         1 ONLINE           +ORCLDG02/orcl/onlinelog/group_1.264.819722239             NO
         6 ONLINE           +ORCLDG01/orcl/onlinelog/group_6.292.819723491             NO
         6 ONLINE           +ORCLDG02/orcl/onlinelog/group_6.267.819723505             NO
         5 ONLINE           +ORCLDG01/orcl/onlinelog/group_5.293.819723461             NO
         5 ONLINE           +ORCLDG02/orcl/onlinelog/group_5.268.819723471             NO

SQL> alter database add logfile '+ORCLDG03' size 1073741824;
Database altered.
SQL> alter database add logfile thread 2 '+ORCLDG03' size 1073741824;
Database altered.
SQL> select * from v$log;
    GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ------------
         1          1      58682 1073741824          2 NO  ACTIVE              1.5122E+13 11-OCT-16
         2          1      58679 1073741824          2 NO  ACTIVE              1.5122E+13 11-OCT-16
         3          1      58680 1073741824          2 NO  ACTIVE              1.5122E+13 11-OCT-16
         4          1      58678 1073741824          2 YES INACTIVE            1.5122E+13 11-OCT-16
         5          1      58677 1073741824          2 YES INACTIVE            1.5122E+13 11-OCT-16
         6          1      58681 1073741824          2 NO  ACTIVE              1.5122E+13 11-OCT-16
         7          2      77128 1073741824          2 NO  INACTIVE            1.5122E+13 11-OCT-16
         8          2      77129 1073741824          2 NO  INACTIVE            1.5122E+13 11-OCT-16
         9          2      77130 1073741824          2 NO  ACTIVE              1.5122E+13 11-OCT-16
        10          2      77126 1073741824          2 NO  INACTIVE            1.5122E+13 11-OCT-16
        11          2      77127 1073741824          2 NO  INACTIVE            1.5122E+13 11-OCT-16
        12          2      77125 1073741824          2 NO  INACTIVE            1.5122E+13 11-OCT-16
        13          1      58683 1073741824          1 NO  CURRENT             1.5122E+13 11-OCT-16
        14          2      77131 1073741824          1 NO  CURRENT             1.5122E+13 11-OCT-16
 增加完redo，查看积压的会话已经有下降了：
SQL> select count(1) from v$session ;
  COUNT(1)
----------
       852
SQL> select count(1) from v$session where status='ACTIVE';
  COUNT(1)
----------
       525
SQL> /
  COUNT(1)
----------
       525
SQL> /
  COUNT(1)
----------
       523
 清理归档空间：
orcl1:[/oracle/app/oracle/admin/orcl/bdump]$asmcmd
ASMCMD> lsdg
State    Type    Rebal  Unbal  Sector  Block       AU  Total_MB  Free_MB  Req_mir_free_MB  Usable_file_MB  Offline_disks  Name
MOUNTED  NORMAL  N      N        1024   4096  1048576   1024000      678           102400          -50861              0  ORCLDG01/
MOUNTED  NORMAL  N      N        1024   4096  1048576   1024000     1389           102400          -50505              0  ORCLDG02/
MOUNTED  EXTERN  N      N        1024   4096  1048576    512000    98144                0           98144              0  ORCLDG03/
MOUNTED  NORMAL  N      N        1024   4096  1048576    307200     9659           102400          -46370              0  ORCLSYSDG01/
MOUNTED  NORMAL  N      N        1024   4096  1048576    204800    13248                0            6624              0  SFILEARCHDG01/
ASMCMD> cd SFILEARCHDG01
ASMCMD> ls
HNRMDB/
ASMCMD> cd ORCL
ASMCMD> ls
ARCHIVELOG/
ASMCMD> cd ARCHIVELOG
ASMCMD> ls
2016_10_10/
2016_10_11/
ASMCMD> rm -r 2016_10_10
You may delete multiple files and/or directories. 
Are you sure? (y/n) y
ORA-15032: not all alterations performed
ORA-15173: entry 'thread_1_seq_58606.367.924907269' does not exist in directory '2016_10_10' (DBD ERROR: OCIStmtExecute)
ASMCMD> lsdg
State    Type    Rebal  Unbal  Sector  Block       AU  Total_MB  Free_MB  Req_mir_free_MB  Usable_file_MB  Offline_disks  Name
MOUNTED  NORMAL  N      N        1024   4096  1048576   1024000      678           102400          -50861              0  ORCLDG01/
MOUNTED  NORMAL  N      N        1024   4096  1048576   1024000     1389           102400          -50505              0  ORCLDG02/
MOUNTED  EXTERN  N      N        1024   4096  1048576    512000    98144                0           98144              0  ORCLDG03/
MOUNTED  NORMAL  N      N        1024   4096  1048576    307200     9659           102400          -46370              0  ORCLSYSDG01/
MOUNTED  NORMAL  N      N        1024   4096  1048576    204800   114264                0           57132              0  SFILEARCHDG01/
ASMCMD> exit
 清理完归档空间，数据库状态恢复正常：
SQL> select count(*)
  2    from gv$session
  3   where event='enq: TX - row lock contention'
  4     and inst_id=1
  5     and status='ACTIVE'
  6  ;
  COUNT(*)
----------
       117
SQL> /
  COUNT(*)
----------
       117
SQL> /
  COUNT(*)
----------
        43
SQL> /
  COUNT(*)
----------
         7
SQL> /
  COUNT(*)
----------
         0
SQL> select count(*) from v$session where status='ACTIVE';
  COUNT(*)
----------
        68
SQL>  select count(*)
  2     from gv$session
  3     where event='enq: TX - row lock contention'
  4       and inst_id=1
  5      and status='ACTIVE'
  6    ;
  COUNT(*)
----------
         0

  本次故障处理过程中，发现大量如下信息：
Wed Oct 12 20:19:41 EAT 2016
SUCCESS: diskgroup SFILEARCHDG01 was mounted
Wed Oct 12 20:19:46 EAT 2016
SUCCESS: diskgroup SFILEARCHDG01 was dismounted
经求证是10g ASM rac才会出现的，oracle采取的策略是在归档目录不适用的时候对其下线，在归档进程需要切换归档的时候，才会将归档的卷组上线。

时间： 2024-09-22 01:59:47

ORACLE 归档空间满导致的enq: TX - row lock contention的相关文章

ORACLE AWR结合ASH诊断分析enq: TX - row lock contention

  公司用户反馈一系统在14:00~15:00(2016-08-16)这个时间段反应比较慢,于是生成了这个时间段的AWR报告,   如上所示,通过Elapsed Time和DB Time对比分析,可以看出在这段时间内服务器并不繁忙.分析Top 5 Timed Events,我们可以看到前五的等待事件     可以看到等待事件enq: TX - row lock contention占了所有等待事件17.3%的比例,猜测有可能是锁等待(enqueue等待)引起的阻塞导致,但是这个还不能下定论,因为

ORACLE等待事件：enq: TX - row lock contention

enq: TX - row lock contention等待事件,这个是数据库里面一个比较常见的等待事件.enq是enqueue的缩写,它是一种保护共享资源的锁定机制,一个排队机制,先进先出(FIFO).enq: TX - row lock contention等待事件,OACLE将其归类为application级别的等待事件.有些场景是因为应用逻辑设计不合理造成的.下面我们看看enq: TX - row lock contention的英文介绍: This wait indicates ti

【故障处理】队列等待之enq: TX - row lock contention

[故障处理]队列等待之enq: TX - row lock contention 1  BLOG文档结构图   2  前言部分 2.1  导读和注意事项 各位技术爱好者,看完本文后,你可以掌握如下的技能,也可以学到一些其它你所不知道的知识,~O(∩_∩)O~: ① enq: TX - row lock contention等待事件的解决 ② 一般等待事件的解决办法 ③ 队列等待的基本知识 ④ ADDM的使用 ⑤ 如何获取历史执行计划 ⑥ 查询绑定变量的具体值 ⑦ 很多有用的查询性能的SQL语句

20161208理解enq TX - row lock contention

[20161208]理解enq TX - row lock contention.txt >SELECT * FROM v$event_name WHERE name = 'enq: TX - row lock contention'; EVENT#   EVENT_ID NAME                          PARAMETER1  PARAMETER2      PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS ------

Oracle中row lock contention的性能故障

这是一套Windows RAC的环境,也是之前处理  解决一则row cache lock引起的性能故障 那套环境.下面记录一下处理的经过: 1 对这一个小时进行AWR的收集和分析,首先,从报告头中看到DB Time达到近500分钟,(DB Time)/Elapsed=8,这个比值偏高: 2 再看TOP 5事件: 看到排在第一位的是enq: TX – row lock contention事件,也就是说系统中在这一个小时里产生了较为严重的行级锁等待事件. Top 5 Timed Events 通

oracle数据库enq: TX - allocate ITL entry性能诊断

朋友公司的某铁路集团医保系统出现性能问题业务不能正常办理,下面是出现性能问题时的awr报告 从等待事件来看主要是出现了多处锁竞争.其中enq: TX - allocate ITL entry等待事件是由于缺省情况下创建的表的INITRANS参数为1,索引的INITRANS参数值为2.当有太多的并发DML操作同时操作相同的数据块或索引块就会出现这个等待事件,可以通过查看Segments by ITL Waits部分的信息来了解出现大量并发DML操作的对象 从下面的信息可以看出消耗时间最长的语句都是

oracle 误杀进程导致rac hang住解决办法

有客户反馈系统hang住,不能归档,需要我们紧急介入分析 节点1日志 出现redo不能归档,redo日志都已经被写满,人工执行了ALTER SYSTEM ARCHIVE LOG CURRENT,数据库就开始把redo全部归档,但是后面产生的redo又不能归档,当redo全部写满之后,数据库有出现大量log file switch (archiving needed)等待  代码如下 复制代码 Tue Sep 24 22:05:37 2013 Thread 1 advanced to log se

【MOS】 Troubleshooting waits for enq: TX - allocate ITL entry(1472175.1)

Troubleshooting waits for 'enq: TX - allocate ITL entry' (文档 ID 1472175.1) In this Document Symptoms Cause Solution   Increase INITRANS   Increase PCTFREE   A Combination of increasing both INITRANS and PCTFREE References APPLIES TO: Oracle Database

[20151208]关于Oracle Row Lock.txt

[20151208]关于Oracle Row Lock.txt --参考链接 https://blogs.oracle.com/askmaclean/entry/know_more_about_oracle_row 大家都知道如何2个用户修改相同的记录,会出现enq: TX – row lock contention,另外一个用户会等待前面的用户修改的提交或者回 滚,如果不提交,该用户会一直等待,除非前面的用户给kill或者执行commit,rollback操作.而我们都知道在Oracle中实现