奇怪enq: TX - row lock contention行锁等待事件模拟验证

2020-08-27 00:00:00 用户 执行 生产 会话 阻塞

       曾经遇到一个奇怪的问题,用户反映行锁等待严重,前台系统无法使用,我定位到某个会话时,该会话一直持有锁不释放,但是开发反映用户执行的SQL会交给框架去commit数据,不会出现执行完DML操作而不释放的情况,但是事实确实如此,我们怀疑用户虽然执行了SQL,但是异常退出导致用户进程依然存在,导致后续阻塞。今天做个测试,验证这个问题,这里完全重现了生产环境的输出结果,从而验证肯定是阻塞会话没有释放锁导致

排查TX锁长时间等待问题nq: TX - row lock contention

26号会话执行update操作,持有行锁 lmode>0 event like ‘enq%’ - gv$lock

SCOTT@orcl1>select userenv('sid') from dual;

USERENV('SID')

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

            26

Elapsed: 00:00:00.00

SCOTT@orcl1>  update emp1 set ename='test' where empno=7788;

1 row updated.

Elapsed: 00:00:00.01

发生23号的阻塞后,我们在会话26执行一条select的SQL

SCOTT@orcl1>select userenv('sid') from dual;

USERENV('SID')

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

            26

Elapsed: 00:00:00.00

23号会话Delete同一行数据 申请行锁 request>0 ,event like ‘enq%’ - gv$lock

下面我们通过脚本查询当前持有和申请TX锁的会话信息

SYS@orcl2>select

      a.inst_id "INST",a.sid,a.id1,a.id2,a.type,a.request,a.ctime "SECS",

      c.spid "SPID",

      b.OSUSER, b.USERNAME, b.PROCESS,b.MACHINE,b.program,

      case

      when rawtohex(b.SQL_ADDRESS) <> '00'

        then 'CURR'

        else 'PREV'

      end STAT,

     d.sql_text "SQL"

   from

     gv$lock a, gv$session b, gv$process c,gv$sql d

   where

     (a.id1,a.id2) in

        (

            select ID1,ID2 from gv$lock where type = 'TX' and request>0

        )

   and a.inst_id = b.inst_id

   and a.inst_id = c.inst_id

   and a.sid = b.sid

   and b.paddr = c.addr

   and

     case

     when rawtohex(b.SQL_ADDRESS) <> '00'

       then b.SQL_ADDRESS

       else b.PREV_SQL_ADDR

     end

   = d.address

   and

     case

    when b.SQL_HASH_VALUE > 0

       then b.SQL_HASH_VALUE

       else b.PREV_HASH_VALUE

     end

     = d.hash_value

   order by a.id1,a.id2,a.request;

 INST    SID        ID1        ID2 TY  REQUEST       SECS SPID

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

OSUSER     USERNAME   PROCESS                  MACHINE              PROGRAM              STAT

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

SQL

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

    1     26     131086        710 TX        0        754 5000

oracle     SCOTT      4959                     rac1                 sqlplus@rac1 (TNS V1 CURR-V3)

select userenv('sid') from dual

    2     23     131086        710 TX        6        741 4680

oracle     SYS        4679                     rac2                 sqlplus@rac2 (TNS V1 CURR-V3)

delete from scott.emp1  where empno=7788

Elapsed: 00:00:02.15

此时有两行记录

分析:

行:26号会话持有TX锁,查询时执行的SQL为select userenv('sid') from dual

第二行:23号会话申请Tx锁,被阻塞的SQL为delete from scott.emp1  where empno=7788

如果通过gv$session查会话26的SQL_id无法获取之前的update操作的SQL,但是我们可以确认这个事务没有结束,或者用户提交了数据,但是这会话异常关闭,这条SQL依然再执行,会话没有退出。

SYS@orcl2>select status,sql_id from gv$session where sid=26;

STATUS   SQL_ID

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

INACTIVE fjp94552967gh    <<<<<< 该SQL不是update语句

Elapsed: 00:00:00.02

下面我们查询会话26(阻塞者) 的事务信息

SYS@orcl2>select s.sid,s.status,program,(select substr(sql_text,1,80) from v$open_cursor where sql_id=s.sql_id and s.status='ACTIVE') sql_text,t.start_time,t.used_ublk from gv$session s,gv$transaction t  where s.inst_id=t.inst_id and s.taddr=t.addr and s.sid=26;

   SID STATUS   PROGRAM                        SQL_TEXT                                                     START_TIME            USED_UBLK

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

    26 INACTIVE sqlplus@rac1 (TNS V1-V3)                                                                    08/26/20 23:02:58             1

Elapsed: 00:00:00.03

发现26号会话的事务没有结束,而其会话状态为NACTIVE

从测试看我们阻塞者26号会话执行update操作,这个事务没有结束,因为select 不会产生事务,造成后续操作相同行记录被阻塞。

在生产库中遇到的问题很可能是当时操作的用户退出异常,用户进程没有正常退出导致。我们kill会话26就是让Oracle结束事务,从而消除阻塞。

我再通过ASH看看阻塞关系:

SYS@orcl2>select inst_id,session_id,sql_id ,event,blocking_session,count(*) from gv$active_session_history where event like 'enq%' and blocking_session>0 group by inst_id,session_id,sql_id ,event,blocking_session order by count(*) desc;

   INST_ID SESSION_ID SQL_ID        EVENT                                                            BLOCKING_SESSION   COUNT(*)

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

         2         23 gy44zy8p19pfx enq: TX - row lock contention                                                  26       3650

         2       1887                          enq: FU - contention                                                                          1901          5

         1         16                             enq: PE - contention                                                                             12          1

Elapsed: 00:00:00.05

我们看到会话26阻塞会话23已经3650秒,被阻塞的会话23正在执行SQL: gy44zy8p19pfx 下面我们查询会话26的信息,kill该会话。

select sid,serial#,status from gv$session where sid=26;

SYS@orcl2>select inst_id,sid,serial#,status from gv$session where sid=26;

   INST_ID    SID    SERIAL# STATUS

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

         2     26         59 ACTIVE

         1     26         13 INACTIVE

Elapsed: 00:00:00.02

开启一个新会话,生产中我们肯定不会是执行用户的会话,测试需要注意,否则不能“自杀”。

 SYS@orcl1>alter system kill session '26,13';

System altered.

Elapsed: 00:00:00.01

此时行锁问题解决。


相关文章