Oracle数据库数据恢复、性能优化来问问AskMaclean - ParnassusData诗檀软件旗下网站

找回密码
注册
搜索
热搜: 活动 交友 discuz
发新帖

2135

积分

446

好友

165

主题
发表于 2012-6-12 11:36:59 | 查看: 2714| 回复: 7
在死锁检测之前 oracle会等 enqueue lock多久?    欢迎大家踊跃讨论!
下载专业ORACLE数据库恢复工具PRM ParnassusData Recovery Manager For Oracle http://www.parnassusdata.com/

Maclean Liu的Oracle技术博客https://blogs.oracle.com/askmaclean/

了解Maclean Liu|向Maclean Liu提问

Oracle ALLSTARS 全明星 QQ群  # QQ群号:23549328 #  
关注Oracle数据库技术,绝不闲聊 。
基于平等讨论的原则,入群必须统一使用10号黑色字体,否则不允许加入或者直接请出群。
价值无需夸大,一切浑然天成。
欢迎有一定基础的Oracle骨友加入,现在入群需要经过Maclean的技术面试,欢迎面试,请加QQ号:47079569 为好友参加面试





2群基础群  # QQ群号:171092051 #
关注Oracle数据库技术,绝不闲聊 。 基于平等讨论的原则,入群必须统一使用10号非黑色字体,否则不允许加入或者直接请出群。 只允许真正有诚意学习Oracle数据库的同学加入,现在入群需要经过Maclean的技术面试,欢迎面试,请加QQ号:47079569 为好友参加面试




发表于 2012-6-12 13:08:42
在11.2.0.2.0上做了实验,步骤如下
会话1,PID=66

  1. [oracle@GG-rac1 ~]$ export ORACLE_SID=sbdb1
  2. [oracle@GG-rac1 ~]$ sqlplus / as sysdba
  3. SQL*Plus: Release 11.2.0.2.0 Production on Tue Jun 12 12:36:30 2012
  4. Copyright (c) 1982, 2010, Oracle.  All rights reserved.

  5. Connected to:
  6. Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
  7. With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
  8. Data Mining and Real Application Testing options
  9. SQL> select pid from v$process where addr=(select paddr from v$session where sid=userenv('SID'));
  10.        PID
  11. ----------
  12.         66
  13. SQL> alter system set "_trace_events"='10000-10999:255:66,67';
  14. System altered.
  15. SQL> update t_clevernby set id=11 where id=1;
  16. 1 row updated.
  17. SQL> update t_clevernby set id=22 where id=2;
  18. update t_clevernby set id=22 where id=2
  19. *
  20. ERROR at line 1:
  21. ORA-00060: deadlock detected while waiting for resource

  22. SQL> commit;
  23. Commit complete.
  24. SQL> oradebug setmypid
  25. Statement processed.
  26. SQL> oradebug dump errorstack 4
  27. Statement processed.
复制代码


会话2,PID=67

  1. [root@GG-rac1 ~]# su - oracle
  2. [oracle@GG-rac1 ~]$ export ORACLE_SID=sbdb1
  3. [oracle@GG-rac1 ~]$ sqlplus / as sysdba
  4. SQL*Plus: Release 11.2.0.2.0 Production on Tue Jun 12 12:36:43 2012
  5. Copyright (c) 1982, 2010, Oracle.  All rights reserved.

  6. Connected to:
  7. Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
  8. With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
  9. Data Mining and Real Application Testing options
  10. SQL> select pid from v$process where addr=(select paddr from v$session where sid=userenv('SID'));
  11.        PID
  12. ----------
  13.         67
  14. SQL> update t_clevernby set id=222 where id=2;
  15. 1 row updated.
  16. SQL> update t_clevernby set id=111 where id=1;
  17. 0 rows updated.
  18. SQL> commit;
  19. Commit complete.
  20. SQL> oradebug setmypid
  21. Statement processed.
  22. SQL> oradebug dump errorstack 4
  23. Statement processed.
复制代码


KSTTrace.rar (842.08 KB, 下载次数: 644)

在66.trc中可以看到

  1. 2012-06-12 12:38:48.672238 :8766BA98:db_trace:ksq.c@7632:ksqgtlctx(): [10704:66:93] ksqgtl: acquire TX-00060021-0000121e mode=X flags=GLOBAL|LONG why="row lock contention"
  2. 2012-06-12 12:38:48.672331 :8766BA99:db_trace:kju.c@1224:kjuef(): [10425:66:93] kjuef: [0x60021][0x121e],[TX][ext 0x7fff,0x0]
  3. 2012-06-12 12:38:48.672433 :8766BA9A:db_trace:ksl2.c@2542:kslwtbctx(): [10005:66:93] KSL WAIT BEG [enq: TX - row lock contention] 1415053318/0x54580006 393249/0x60021 4638/0x121e wait_id=52 seq_num=59 snap_id=1
  4. 2012-06-12 12:38:49.173483 :8766BB0B:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  5. 2012-06-12 12:38:49.674485 :8766BB56:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  6. 2012-06-12 12:38:50.175483 :8766BBA8:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  7. 2012-06-12 12:38:50.175483*:8766BBA9:sql_mon_query:keswx.c@6154:keswxCurPushMonitoring(begin): xsc=0x2adbd5a24b50 monCtx=(nil) estart=1339475928 eid=16777218 ctx=0xff403460 cwh=0x2adbd5a209b8 cpu=0 buffg=9 interb=0 r=0 rb=0 w=0 wb=0
  8. 2012-06-12 12:38:50.175483*:8766BBAA:sql_mon_query:keswx.c@2845:keswxCurPrepare(): Allocate monitor context: xsc=0x2adbd5a24b50 curCtx=0x2adbd5a245a0 pubTabIdxCnt=0
  9. 2012-06-12 12:38:50.175483*:8766BBAB:sql_mon_query:keswx.c@6200:keswxCurPushMonitoring(): clear monitoring flag for xsc=0x2adbd5a24b50
  10. 2012-06-12 12:38:50.175483*:8766BBAC:sql_mon_query:keswx.c@6332:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x2adbd5a24b50
  11. 2012-06-12 12:38:50.676480 :8766BC29:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  12. 2012-06-12 12:38:51.177480 :8766BCB4:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  13. 2012-06-12 12:38:51.678480 :8766BD13:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  14. 2012-06-12 12:38:52.179484 :8766BD74:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  15. 2012-06-12 12:38:52.179484*:8766BD75:sql_mon_query:keswx.c@6154:keswxCurPushMonitoring(begin): xsc=0x2adbd5a24b50 monCtx=0x2adbd5a245a0 estart=1339475928 eid=16777218 ctx=0xff403460 cwh=0x2adbd5a209b8 cpu=0 buffg=0 interb=0 r=0 rb=0 w=0 wb=0
  16. 2012-06-12 12:38:52.179484*:8766BD76:sql_mon_query:keswx.c@6332:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x2adbd5a24b50
  17. 2012-06-12 12:38:52.680480 :8766BDBA:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  18. 2012-06-12 12:38:53.181481 :8766BE17:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  19. 2012-06-12 12:38:53.682478 :8766BEF7:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  20. 2012-06-12 12:38:54.183479 :8766BFB3:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  21. 2012-06-12 12:38:54.183479*:8766BFB4:sql_mon_query:keswx.c@6154:keswxCurPushMonitoring(begin): xsc=0x2adbd5a24b50 monCtx=0x2adbd5a245a0 estart=1339475928 eid=16777218 ctx=0xff403460 cwh=0x2adbd5a209b8 cpu=0 buffg=0 interb=0 r=0 rb=0 w=0 wb=0
  22. 2012-06-12 12:38:54.183479*:8766BFB5:sql_mon_query:keswx.c@6332:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x2adbd5a24b50
  23. 2012-06-12 12:38:54.684474 :8766C03B:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  24. 2012-06-12 12:38:55.185477 :8766C0B6:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  25. 2012-06-12 12:38:55.686473 :8766C0FE:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  26. 2012-06-12 12:38:56.187476 :8766C140:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  27. 2012-06-12 12:38:56.187476*:8766C141:sql_mon_query:keswx.c@6154:keswxCurPushMonitoring(begin): xsc=0x2adbd5a24b50 monCtx=0x2adbd5a245a0 estart=1339475928 eid=16777218 ctx=0xff403460 cwh=0x2adbd5a209b8 cpu=0 buffg=0 interb=0 r=0 rb=0 w=0 wb=0
  28. 2012-06-12 12:38:56.187476*:8766C142:sql_mon_query:keswx.c@6332:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x2adbd5a24b50
  29. 2012-06-12 12:38:56.688470 :8766C1E3:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  30. 2012-06-12 12:38:57.189536 :8766C289:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  31. 2012-06-12 12:38:57.690468 :8766C2F4:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  32. 2012-06-12 12:38:58.191470 :8766C378:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  33. 2012-06-12 12:38:58.191470*:8766C379:sql_mon_query:keswx.c@6154:keswxCurPushMonitoring(begin): xsc=0x2adbd5a24b50 monCtx=0x2adbd5a245a0 estart=1339475928 eid=16777218 ctx=0xff403460 cwh=0x2adbd5a209b8 cpu=0 buffg=0 interb=0 r=0 rb=0 w=0 wb=0
  34. 2012-06-12 12:38:58.191470*:8766C37A:sql_mon_query:keswx.c@6332:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x2adbd5a24b50
  35. 2012-06-12 12:38:58.692488 :8766C3C8:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=50
  36. 2012-06-12 12:38:58.799543 :8766C3CD:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=10
  37. 2012-06-12 12:38:58.799546 :8766C3CE:db_trace:ksl2.c@13718:ksliwat(): [10005:66:93] KSL POST RCVD poster=43 num=3338 loc='ksv2.h LINE:1673 ID:ksvpst: workdone' id1=0 id2=0 name=   type=0 fac#=3 posted=0x1 may_be_posted=1
  38. 2012-06-12 12:38:59.021847 :8766C3F4:db_trace:kju.c@1224:kjuef(): [10425:66:93] kjuef: [0x60021][0x121e],[TX][ext 0x7fff,0x0]
  39. 2012-06-12 12:38:59.021852 :8766C3F5:db_trace:ksl2.c@13590:ksliwat(): [10005:66:93] KSL FACILITY WAIT fac#=3 time_waited_csecs=22
  40. 2012-06-12 12:38:59.021854 :8766C3F6:db_trace:ksl2.c@13718:ksliwat(): [10005:66:93] KSL POST RCVD poster=13 num=270089 loc='kji.h LINE:3275 ID:kjata: wake up enqueue owner' id1=0 id2=0 name=   type=0 fac#=3 posted=0x3 may_be_posted=1
  41. 2012-06-12 12:38:59.021861 :8766C3F7:db_trace:ksl2.c@2676:kslwtectx(): [10005:66:93] KSL WAIT END [enq: TX - row lock contention] 1415053318/0x54580006 393249/0x60021 4638/0x121e wait_id=52 seq_num=59 snap_id=1
  42. 2012-06-12 12:38:59.021863 :8766C3F8:db_trace:ksl2.c@2684:kslwtectx(): [10005:66:93] KSL WAIT END wait times (usecs) - snap=10349422, exc=10349422, tot=10349422
  43. 2012-06-12 12:38:59.021863*:RAC_ENQ:kju.c@2847:kjusuc(): convert request failed with status=[0xF].
  44. 2012-06-12 12:38:59.021888 :8766C3F9:db_trace:ksq.c@8142:ksqgtlctx(): [10704:66:93] ksqgtl: FAILURE: DEADLOCK
复制代码

会话1请求TX-00060021-0000121e未果后进入KSL WAIT,10s后出现ksqgtl: FAILURE: DEADLOCK

请刘大过目,不过有个问题

PID=67的KST Trace不知为何只有12:39:15之后的数据,因此感觉实验结果可能有误

回复 显示全部楼层 道具 举报

发表于 2012-6-12 23:41:49
clevernby 同学用KST  TRACE做了一个很有意思的实验, 值得大家鼓励,  本贴加精。

我个人对于Enqueue Deadlock Detection的一点看法,发表在 http://www.oracledatabase12g.com ... lock-detection.html

回复 显示全部楼层 道具 举报

发表于 2012-6-13 09:30:04
刚才拜读了您的文章感触颇深,但对我的实验结果为10s确有些不解,于是进一步分析了我的KST Trace,发现以下细节,请刘大过目
在process 66的trc中

  1. 2012-06-12 12:38:59.021854 :8766C3F6:db_trace:ksl2.c@13718:ksliwat(): [10005:66:93] KSL POST RCVD poster=13 num=270089 loc='kji.h LINE:3275 ID:kjata: wake up enqueue owner' id1=0 id2=0 name=   type=0 fac#=3 posted=0x3 may_be_posted=1
复制代码

唤醒它的是process 13,这个进程经查是RAC LMD0进程,该进程除了管理全局enqueue、资源访问之外,也负责检测全局enqueue死锁。
查询涉及LMD进程的隐含参数后发现_lm_dd_interval参数为默认的10s.

最后在单实例的11.2.0.2.0数据库上测试,结果果然是3s。

回复 显示全部楼层 道具 举报

发表于 2012-6-13 11:03:45

回复 4# 的帖子

很不错 我支持你的观点, http://www.oracledatabase12g.com ... lock-detection.html 这里补充了关于RAC的死锁检测

回复 显示全部楼层 道具 举报

发表于 2012-6-13 11:15:02
两位高人,能否给个KST Trace的使用说明?没用过这东西呢。

回复 显示全部楼层 道具 举报

发表于 2012-6-13 16:04:41
原帖由 fsm 于 2012-6-13 11:15 发表
两位高人,能否给个KST Trace的使用说明?没用过这东西呢。

KST Trace可参考DSI408第19章
刘大在博客中提到的UTS Trace可参考1402625.1,其中还有介绍event++ syntax.

回复 显示全部楼层 道具 举报

发表于 2012-6-14 07:13:49
原帖由 clevernby 于 2012-6-13 16:04 发表

KST Trace可参考DSI408第19章
刘大在博客中提到的UTS Trace可参考1402625.1,其中还有介绍event++ syntax.

多谢!

回复 显示全部楼层 道具 举报

您需要登录后才可以回帖 登录 | 注册

QQ|手机版|Archiver|Oracle数据库数据恢复、性能优化来问问AskMaclean - ParnassusData诗檀软件旗下网站

GMT+8, 2014-4-17 20:29 , Processed in 0.057777 second(s), 8 queries , Eaccelerator On.

Powered by Discuz! X2.5

© 2001-2012 Comsenz Inc.

回顶部