当前位置： 首页 > Oracle, oracle 10g > 正文

奇怪的enq TX – row lock contention等待事件

Nov152013
作者：dbdream   发布：2013-11-15 22:23   分类：Oracle, oracle 10g     抢沙发  

某客户有30多套数据库要整合，在调研客户需求的时候，客户说有几套库负载比较大，在检查之后发现，这几套库根本就不忙，但是其中有一套库引起了我的注意，下面是这个库的DB time趋势图。

00001

很奇怪的是，客户的库在11月8号之后，DB time成直线上升，这很奇怪，11月8号之前DB time都很低，为什么在11月8号之后，DB time就一直没降下来？出于对客户负责和好奇，追查了一下到底是什么在作怪。取了最后时间点的AWR报告，下面是AWR简要信息。

00002

 再看下这个时间段的负载信息。

00003

00004从负载信息看，这个库负载很低，DB time怎么会如此之高，看下等待事件就清楚了。

00005其他等待事件都不严重，只有这个行级锁，占总体等待时间的98.9%，基本可以断定就是这个行级锁在作祟，怎么定位是哪个会话或哪个SQL导致的行级锁呢？如果不会查的话有个最简单的方法，就是使用ADDM工具，生成该时段的ADDM报告，一目了然。在看ADDM报告之前，先看下这个报告按执行时间排序的SQL。

00006

00007
从上面的信息基本就可以断定就第二条SQL导致的这个行级锁，那么看看ADDM怎么说。

FINDING 1: 99% impact (79450 seconds)
-------------------------------------
发现 SQL 语句正处于行锁定等待。

   RECOMMENDATION 1: Application Analysis, 99% benefit (79450 seconds)
      ACTION: 在 TABLE "JY_PJBJ_BD.EVAL_ASSEMBLY_ITEM" (对象 ID 为 53130)
         中检测到了严重的行争用。使用指定的阻塞 SQL 语句在应用程序逻辑中跟踪行争
用的起因。
         RELEVANT OBJECT: database object with id 53130
      RATIONALE: SQL_ID 为 "f3r68rck9au8f" 的 SQL 语句在行锁上被阻塞。
         RELEVANT OBJECT: SQL statement with SQL_ID f3r68rck9au8f
         update EVAL_ASSEMBLY_ITEM set EVAL_DETAIL_ID=:1, EVAL_INFO_ID=:2,
         ASSEMBLY_ID=:3, ASSEMBLY_NAME=:4, ASSEMBLY_CODE=:5, ASSEMBLY_HOUR=:6,
         ASSEMBLY_EVAL_HOUR=:7, DESCRIPTION=:8, DEL_FLAG=:9, CREATED_BY=:10,
         CREATED_DATE=:11, UPDATED_BY=:12, UPDATED_DATE=:13, REMARK=:14,
         EVAL_NUM=:15, STATUS=:16, SERIAL_NO=:17, SYSTEM_COMP_CODE=:18,
         SELF_CONFIG_FLAG=:19, SUM_ASSEMBLY_ITEM=:20, REPAIR_CODE=:21,
         REPAIR_NAME=:22, UNIT_MAN_HOUR_PRICE=:23, CHG_COMP_SET_CODE=:24,
         CHG_COMP_SET_NAME=:25, ASSEMBLY_PRICE=:26, AUDIT_REPAIR_FEE=:27,
         OPERATION_FLAG=:28 where ID=:29
      RATIONALE: SQL_ID 为 "d7mwhs29jzz56" 的 SQL 语句在行锁上被阻塞。
         RELEVANT OBJECT: SQL statement with SQL_ID d7mwhs29jzz56
         delete from EVAL_ASSEMBLY_ITEM where
         id='8a8085ef4111d4e2014201bf0d8a14f7'

   SYMPTOMS THAT LED TO THE FINDING:
      SYMPTOM: 等待类别 "应用程序" 消耗了大量数据库时间。 (99% impact [79450 sec
onds])

 

通过SQL_ID可以看出，正式那两条SQL导致的行级锁，可为什么从11月8号开始，DB time会无限上升的趋势呢？当时怀疑肯定有个SQL从11月8号开始就持有了行级锁，查下当前未提交的事务。

SQL> SELECT addr,START_TIME  FROM V$TRANSACTION ORDER BY 2;

ADDR             START_TIME
---------------- --------------------
0000000161C04590 09/06/13 19:01:59
0000000161941078 11/03/13 17:46:20
0000000161C3FA68 11/04/13 07:57:19
00000001619468F8 11/04/13 08:04:27
0000000161B751E0 11/04/13 16:16:14
0000000161969F98 11/05/13 17:23:15
00000001619483F8 11/07/13 13:00:24
00000001619796B8 11/07/13 16:17:45
0000000161B973D0 11/08/13 10:51:56
0000000161961AD8 11/10/13 09:26:37
0000000161B79B00 11/10/13 14:18:00
0000000161980A38 11/10/13 15:30:15
0000000161B997F8 11/11/13 09:52:29
000000016195AFF8 11/12/13 08:24:14
0000000161BC0C08 11/12/13 08:31:59
0000000161961238 11/12/13 16:36:52
0000000161B9E430 11/13/13 09:34:23
0000000161BD3150 11/13/13 09:34:52
0000000161C53C00 11/13/13 09:35:19
00000001619534F8 11/13/13 10:51:02
0000000161968498 11/13/13 10:58:13
0000000161C450A8 11/13/13 11:41:32
000000016196F818 11/13/13 14:08:16
0000000161B60868 11/13/13 14:22:32
0000000161C69590 11/13/13 14:23:45
0000000161B76E38 11/13/13 14:23:51
0000000161C288C0 11/13/13 14:23:56
0000000161BDAF00 11/13/13 14:24:28

 

可以看到，从11月8号上午10点钟左右，有个事务一直没有结束，看下到底是谁？

SQL> SELECT SID,SERIAL#,SQL_ID,PREV_SQL_ID,USERNAME,MODULE,OSUSER,MACHINE FROM  V$SESSION WHERE TADDR='0000000161B973D0';

 SID SERIAL# SQL_ID PREV_SQL_ID   USERNAME   MODULE           OSUSER   MACHIN
---- ------- ------ ------------- ---------- ---------------- -------- ------
 210   37408       d7mwhs29jzz56 JY_PJBJ_BD JDBC Thin Client weblogic JY-app

 

果然是它，这个DELETE操作从11月8号开始就没完成，那么是SQL运行太慢还是没提交呢？显然是没有提交了。因为SQL_ID字段是空的，在V$SESSION视图中SQL_ID表示当前正在运行的SQL，如果SQL运行完了，就不会在SQL_ID字段显示，而是在PREV_SQL_ID字段，PREV_SQL_ID字段表示上一条SQL，很显然，这个会话在做完DELETE操作后没有提交，也没有做其他操作(也可能在做其他操作后，最后做了这个DELETE操作，但还是异常中断的可能性最大)。
再看下其他未完成的事务是什么？

SQL> SELECT SID,SERIAL#,PREV_SQL_ID,USERNAME,MODULE,OSUSER,MACHINE  FROM  V$SESS
ION WHERE TADDR in (SELECT addr FROM V$TRANSACTION);

 SID SERIAL# PREV_SQL_ID   USERNAME   MODULE           OSUSER   MACHIN
---- ------- ------------- ---------- ---------------- -------- ------
  14   60362 bunvx480ynf57 EBYINGDA   JDBC Thin Client weblogic ecargo-app
  21   63753 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  23    1956 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  24      81 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  31    8074 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  36     233 bhapyw6gwxtan GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  39      70 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  45     215 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  57   63780 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  61    8306 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  69   49882 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  72    8100 2p4ks9f42m1g5 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  75   11495 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  91    4693 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
  96   37162 bunvx480ynf57 EBYINGDA   JDBC Thin Client weblogic ecargo-app
 105   57406 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
 106   38897 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
 109   34594 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
 114   37188 6nn3x577fq025 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
 125    4898 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app
 147   33961 bunvx480ynf57 EBYINGDA   JDBC Thin Client weblogic ecargo-app
 161   40150 bunvx480ynf57 EBYINGDA   JDBC Thin Client weblogic ecargo-app
 181   50118 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app-2
 188   59579 bunvx480ynf57 EBYINGDA   JDBC Thin Client weblogic ecargo-app
 196   64303 bunvx480ynf57 EBYINGDA   JDBC Thin Client weblogic ecargo-app
 210   37408 d7mwhs29jzz56 JY_PJBJ_BD JDBC Thin Client weblogic JY-app
 240   57961 bunvx480ynf57 GRPCLAIM   JDBC Thin Client weblogic tyjbapt-app-2

已选择27行。

 

虽然很多未完成的事务，但是仔细看就会发现，大部分都是干bunvx480ynf57活。那么bunvx480ynf57到底是干什么？

SQL> select * from table(dbms_xplan.display_awr('bunvx480ynf57'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------
SQL_ID bunvx480ynf57
--------------------
SELECT 1 FROM DUAL

Plan hash value: 1388734953

-----------------------------------------------------------------
| Id  | Operation        | Name | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------
|   0 | SELECT STATEMENT |      |       |     2 (100)|          |
|   1 |  FAST DUAL       |      |     1 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------


已选择13行。

 

原来是这个啊，这很好理解，在weblogic应用中，默认新会话连接数据库时，weblogic会先发出select 1 from dual操作，然后紧跟着做个ROLLBACK，有经验的程序员都会把这个功能禁止掉，显然当前的这套环境这个功能并没有被禁止，那么在并发很高的情况下回滚率就会非常高。
也可以用这种方法直接看d7mwhs29jzz56是什么东东？

SQL> select * from table(dbms_xplan.display_awr('d7mwhs29jzz56'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------
SQL_ID d7mwhs29jzz56
--------------------
delete from EVAL_ASSEMBLY_ITEM where id='8a8085ef4111d4e2014201bf0d8a14f7'

Plan hash value: 1419020638

--------------------------------------------------------------------------------------------
| Id  | Operation          | Name                  | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | DELETE STATEMENT   |                       |       |       |     2 (100)|          |
|   1 |  DELETE            | EVAL_ASSEMBLY_ITEM    |       |       |            |          |
|   2 |  INDEX UNIQUE SCAN| PK_EVAL_ASSEMBLY_ITEM |     1 |   130 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------


已选择14行。

 

可以看到这个DELETE操作简直是瞬间就可以完成，走的是唯一索引(可能是主键)，而且每次只删除一条记录，而这个事务跑了5天多还没结束，很显然是没有提交或异常中断了，当然我是没有权利杀掉这个SQL的，和客户的DBA解释了下这个过程，并记录下日志，客户的DBA也不敢杀掉这个会话，他拿去找开发人员了。

本文固定链接: https://www.dbdream.com.cn/2013/11/%e5%a5%87%e6%80%aa%e7%9a%84enq-tx-row-lock-contention%e7%ad%89%e5%be%85%e4%ba%8b%e4%bb%b6/ | 信春哥，系统稳，闭眼上线不回滚！

该日志由 dbdream 于2013年11月15日发表在 Oracle, oracle 10g 分类下， 你可以发表评论，并在保留原文地址及作者的情况下引用到你的网站或博客。
原创文章转载请注明: 奇怪的enq TX – row lock contention等待事件 | 信春哥，系统稳，闭眼上线不回滚！
关键字: , ,
【上一篇】
【下一篇】

您可能还会对这些文章感兴趣！

奇怪的enq TX – row lock contention等待事件：等您坐沙发呢！

发表评论

快捷键：Ctrl+Enter