奇怪的enq TX – row lock contention等待事件
Nov152013
某客户有30多套数据库要整合，在调研客户需求的时候，客户说有几套库负载比较大，在检查之后发现，这几套库根本就不忙，但是其中有一套库引起了我的注意，下面是这个库的DB time趋势图。
很奇怪的是，客户的库在11月8号之后，DB time成直线上升，这很奇怪，11月8号之前DB time都很低，为什么在11月8号之后，DB time就一直没降下来？出于对客户负责和好奇，追查了一下到底是什么在作怪。取了最后时间点的AWR报告，下面是AWR简要信息。
再看下这个时间段的负载信息。
从负载信息看，这个库负载很低，DB time怎么会如此之高，看下等待事件就清楚了。
其他等待事件都不严重，只有这个行级锁，占总体等待时间的98.9%，基本可以断定就是这个行级锁在作祟，怎么定位是哪个会话或哪个SQL导致的行级锁呢？如果不会查的话有个最简单的方法，就是使用ADDM工具，生成该时段的ADDM报告，一目了然。在看ADDM报告之前，先看下这个报告按执行时间排序的SQL。
从上面的信息基本就可以断定就第二条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也不敢杀掉这个会话，他拿去找开发人员了。
奇怪的enq TX – row lock contention等待事件：等您坐沙发呢！
发表评论
