您的位置:首页 > 数据库

一次数据库相关操作卡住的排查--enq: TX - row lock contention

2015-08-24 16:45 381 查看
问题描述:某日客户来电某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
内容来自用户分享和网络整理,不保证内容的准确性,如有侵权内容,可联系管理员处理 点击这里给我发消息
标签:  enq TX - row lock co