Lock分析：systemstate分析row cache lock

我们的文章会在微信公众号IT民工的龙马人生和博客网站( www.htz.pw )同步更新 ，欢迎关注收藏，也欢迎大家转载，但是请在文章开始地方标注文章出处，谢谢！
由于博客中有大量代码，通过页面浏览效果更佳。

Lock分析：systemstate分析row cache lock

案例是一次测试row cache lock的systemstate分析方法，平台为11.2.04

欢迎大家加入ORACLE超级群：17115662 免费解决各种ORACLE问题,以后BLOG将迁移到http://www.htz.pw

1，使用ass来格式化systemstate的

[oracle@11rac1 sql]$ awk -f ass1039.awk /u01/app/oracle/diag/rdbms/power/power1/trace/power1_ora_14290.trcStarting Systemstate 1………………………………………………Ass.Awk Version 1.0.39~~~~~~~~~~~~~~~~~~~~~~Source file : /u01/app/oracle/diag/rdbms/power/power1/trace/power1_ora_14290.trcSystem State 1  (2014-07-16 15:14:42.518)~~~~~~~~~~~~~~   ~~~~~~~~~~~~~~~~~~~~~~~1:                                      [DEAD]2:  waiting for ‘pmon timer’           3:  waiting for ‘rdbms ipc message’    4:  waiting for ‘VKTM Logical Idle Wait’5:  waiting for ‘rdbms ipc message’    6:  waiting for ‘DIAG idle wait’       7:  waiting for ‘rdbms ipc message’    8:  waiting for ‘PING’                 9:  waiting for ‘rdbms ipc message’    10: waiting for ‘DIAG idle wait’       11: waiting for ‘rdbms ipc message’    12: waiting for ‘ges remote message’   13: waiting for ‘gcs remote message’   14: waiting for ‘rdbms ipc message’    15: waiting for ‘GCR sleep’            16: waiting for ‘rdbms ipc message’    17: waiting for ‘rdbms ipc message’    18: waiting for ‘rdbms ipc message’    19: waiting for ‘rdbms ipc message’    20: waiting for ‘smon timer’           21: waiting for ‘rdbms ipc message’    22: waiting for ‘rdbms ipc message’    23: waiting for ‘ASM background timer’ 24: waiting for ‘rdbms ipc message’    25: waiting for ‘rdbms ipc message’    26:                                    27: waiting for ‘wait for unread message on broadcast channel’28:                                    29: waiting for ‘rdbms ipc message’    30: waiting for ‘rdbms ipc message’    31: waiting for ‘rdbms ipc message’    32: waiting for ‘SQL*Net message from client’33: waiting for ‘Space Manager: slave idle wait’34: waiting for ‘rdbms ipc message’    35: waiting for ‘rdbms ipc message’    36: waiting for ‘rdbms ipc message’    37: waiting for ‘rdbms ipc message’    38: waiting for ‘SQL*Net message from client’39: waiting for ‘rdbms ipc message’    40: waiting for ‘Space Manager: slave idle wait’41: waiting for ‘wait for unread message on broadcast channel’42: waiting for ‘Streams AQ: qmn coordinator idle wait’43: waiting for ‘SQL*Net message from client’Cmd: PL/SQL Execute44: waiting for ‘SQL*Net message from client’45: waiting for ‘Streams AQ: qmn slave idle wait’46: waiting for ‘Streams AQ: waiting for time management or cleanup tasks’47: waiting for ‘SQL*Net message from client’Cmd: Select48: waiting for ‘rdbms ipc message’    49: waiting for ‘enq: TX – row lock contention'[Enq TX-00010008-00000629]Cmd: Select50: waiting for ‘row cache lock’       [Rcache object=0x8f0a1990,]Cmd: Select51: waiting for ‘SQL*Net message from client’52:                                    53:                                    58: waiting for ‘class slave wait’     Blockers~~~~~~~~Above is a list of all the processes. If they are waiting for a resourcethen it will be given in square brackets. Below is a summary of thewaited upon resources, together with the holder of that resource.Notes:~~~~~o A process id of ‘???’ implies that the holder was not found in thesystemstate. (The holder may have released the resource before wedumped the state object tree of the blocking process).o Lines with ‘Enqueue conversion’ below can be ignored *unless*other sessions are waiting on that resource too. For more, seehttp://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.html#enqcnv)Resource Holder StateEnq TX-00010008-00000629    47: waiting for ‘SQL*Net message from client’Rcache object=0x8f0a1990,    49: 49: is waiting for 47:Object Names~~~~~~~~~~~~Enq TX-00010008-00000629                                     Rcache object=0x8f0a1990,       cid=13(dc_sequences)         Summary of Wait Events Seen (count>10)~~~~~~~~~~~~~~~~~~~~~~~~~~~No wait events seen more than 10 times——————ooOoo——————For the LATEST version of this utility seehttp://dlsunuk11.uk.oracle.com/Public/Utils.html#assFor additional documentation seehttp://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.htmlSuggested improvements, bugs etc. should be sent to kevin.p.quinn@oracle.comEnd of report. 60404 Lines Processed.[oracle@11rac2 sql]$ awk -f ass1039.awk /u01/app/oracle/diag/rdbms/power/power2/trace/power2_ora_9758.trcStarting Systemstate 1……………………………………………Ass.Awk Version 1.0.39~~~~~~~~~~~~~~~~~~~~~~Source file : /u01/app/oracle/diag/rdbms/power/power2/trace/power2_ora_9758.trcSystem State 1  (2014-07-16 15:15:33.423)~~~~~~~~~~~~~~   ~~~~~~~~~~~~~~~~~~~~~~~1:                                      [DEAD]2:  waiting for ‘pmon timer’           3:  waiting for ‘rdbms ipc message’    4:  waiting for ‘VKTM Logical Idle Wait’5:  waiting for ‘rdbms ipc message’    6:  waiting for ‘DIAG idle wait’       7:  waiting for ‘rdbms ipc message’    8:  waiting for ‘PING’                 9:  waiting for ‘rdbms ipc message’    10: waiting for ‘DIAG idle wait’       11: waiting for ‘rdbms ipc message’    12: waiting for ‘ges remote message’   13: waiting for ‘gcs remote message’   14: waiting for ‘rdbms ipc message’    15: waiting for ‘GCR sleep’            16: waiting for ‘rdbms ipc message’    17: waiting for ‘rdbms ipc message’    18: waiting for ‘rdbms ipc message’    19: waiting for ‘rdbms ipc message’    20: waiting for ‘smon timer’           21: waiting for ‘rdbms ipc message’    22: waiting for ‘rdbms ipc message’    23: waiting for ‘ASM background timer’ 24: waiting for ‘rdbms ipc message’    25: waiting for ‘rdbms ipc message’    26: waiting for ‘wait for unread message on broadcast channel’27:                                    28:                                    29: waiting for ‘rdbms ipc message’    30: waiting for ‘rdbms ipc message’    31: waiting for ‘rdbms ipc message’    32: waiting for ‘SQL*Net message from client’33: waiting for ‘Space Manager: slave idle wait’34: waiting for ‘class slave wait’     35: waiting for ‘rdbms ipc message’    36: waiting for ‘rdbms ipc message’    37: waiting for ‘rdbms ipc message’    38: waiting for ‘rdbms ipc message’    39: waiting for ‘rdbms ipc message’    40: waiting for ‘wait for unread message on broadcast channel’41: waiting for ‘class slave wait’     42: waiting for ‘Streams AQ: qmn coordinator idle wait’43:                                    44: waiting for ‘SQL*Net message from client’45: waiting for ‘Streams AQ: qmn slave idle wait’46: waiting for ‘row cache lock’       [Rcache object=0x8e9a5120,]Cmd: Select47:                                    48: waiting for ‘rdbms ipc message’    49: waiting for ‘Space Manager: slave idle wait’50: waiting for ‘Space Manager: slave idle wait’51:                                    Blockers~~~~~~~~Above is a list of all the processes. If they are waiting for a resourcethen it will be given in square brackets. Below is a summary of thewaited upon resources, together with the holder of that resource.Notes:~~~~~o A process id of ‘???’ implies that the holder was not found in thesystemstate. (The holder may have released the resource before wedumped the state object tree of the blocking process).o Lines with ‘Enqueue conversion’ below can be ignored *unless*other sessions are waiting on that resource too. For more, seehttp://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.html#enqcnv)Resource Holder StateRcache object=0x8e9a5120,    ??? BlockerObject Names~~~~~~~~~~~~Rcache object=0x8e9a5120,       cid=13(dc_sequences)         Summary of Wait Events Seen (count>10)~~~~~~~~~~~~~~~~~~~~~~~~~~~No wait events seen more than 10 times——————ooOoo——————For the LATEST version of this utility seehttp://dlsunuk11.uk.oracle.com/Public/Utils.html#assFor additional documentation seehttp://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.htmlSuggested improvements, bugs etc. should be sent to kevin.p.quinn@oracle.comEnd of report. 43873 Lines Processed.Rcache object=0x8e9a5120,    ??? 

Blocker这里节点2没有发现阻塞者，说明阻塞者不在2节点，在1节点

2，找到row cache lock的session

以row cache lock等待事件来搜索会话的等待情况，如果没有使用ass格式化的情况下，一般我们都是这样来和

    —————————————-SO: 0x9b513658, type: 4, owner: 0x9ce441f0, flag: INIT/-/-/0x00 if: 0x3 c: 0x3proc=0x9ce441f0, name=session, file=ksu.h LINE:12624, pg=0(session) sid: 52 ser: 15 trans: 0x9515a1f0, creator: 0x9ce441f0flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/-flags2: (0x40009) -/-/INCDID: , short-term DID:txn branch: (nil)oct: 3, prv: 0, sql: 0x8e954a20, psql: 0x8f50cfd0, user: 0/SYSksuxds FALSE at location: 0service name: SYS$USERSclient details:O/S info: user: oracle, term: pts/0, ospid: 6268machine: 11rac2 program: sqlplus@11rac2 (TNS V1-V3)application name: sqlplus@11rac2 (TNS V1-V3), hash value=3270042948Current Wait Stack:0: waiting for ‘row cache lock’cache id=0xd, mode=0x0, request=0x5wait_id=6656 seq_num=6657 snap_id=1wait times: snap=0.001217 sec, exc=0.001217 sec, total=0.001217 secwait times: max=3.000000 sec, heur=3 min 6 secwait counts: calls=1 os=1in_wait=1 iflags=0x5a2

找到row cache enqueue的信息，

这里我们可以看到最终的BLOCKER是inst:1,sid:793

这里需要记录一下行号

row cache enqueue*request来搜索，找到离刚开始最近的一行记录

37769         row cache enqueue: count=1 session=0x9b513658 object=0x8e9a5120, request=X

其实我们还可以下面的方式来搜索

以type: 75, owner: 0x9515a1f0来搜索，因为我们知道，row cache enqueue的type是75，并且owner是属于process跟session的owner是一致的。

其中还可以以row cache enqueuesession9b513658来搜索

        SO: 0x8e990c40, type: 75, owner: 0x9515a1f0, flag: INIT/-/-/0x00 if: 0x1 c: 0x1proc=0x9ce441f0, name=row cache enqueues, file=kqr.h LINE:2064, pg=0row cache enqueue: count=1 session=0x9b513658 object=0x8e9a5120, request=Xsavepoint=0x46row cache parent object: address=0x8e9a5120 cid=13(dc_sequences)hash=152264bc typ=11 transaction=(nil) flags=00000000own=0x8e9a51e8[0x8e9a51e8,0x8e9a51e8] wat=0x8e9a51f8[0x8e990ce8,0x8e990ce8] mode=Nstatus=-/-/-/-/-/-/-/-/-request=X release=FALSE flags=ainstance lock=QN 152264bc 374026d7data=00012a05 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 152264bc 8e9a5120 00000000947397a8 00000000 947397a8 00000000 00000005 00000000 26784f80 00007f3c00000000 00000000 00000000 00000000 8e9a5120 00000000 8e9a52f0 000000008e9a52f0 00000000 8e9a5318 00000000 0000000a 152264bc 374026d7 0000000000000101 00000000 0000011d 00000000 99dd8510 00000000 9ce336f0 000000008f4eb538 00000000 98c04f78 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 99f79978 0000000000000001 0000009a 00050001 08910321 8e9a5388 00000000 8e9a5388 000000000730efec 00000000 26784fa0 00007f3c 99f799d0 00000000 99f799d0 0000000000000000 00000000 00000000 00000000 00000000 00000000 99dd8510 0000000098c05018 00000000 8f4eb5d8 00000000 9b554ec8 00000000 00000000 000000028e9a53f8 00000000 8e9a53f8 00000000 00000000 00000000 00000000 000000008e9a5418 00000000 8e9a5418 00000000 8e9a5428 00000000 8e9a5428 0000000099dca9b8 00000000 99dca9b8 00000000 00000000 00004fe7 26784f88 00007f3c00000000 00000000 00000000 00000000 8e9a5468 00000000 8e9a5468 0000000000000000 00000000 00000000 00000000 feb172d0 00007fff 10600160 0900020000000000 00000000 06c25c14 00000000 26784fa0 00007f3c 00000000 00000000f251fa11 00000002 00000000 00000000 8e9a51e8 00000000kssdmh:  so 0x8e990c40 (type 75, "row cache enqueues") may not have children

红色的部分就是row cache enqueue的信息

instance lock=QN 152264bc 374026d7这里是全局锁的信息，如果在本地没有找到阻塞者的时候，我们就要以这个在其它的节点找到。

3，搜索阻塞者

以row cache enqueueobject8e9a5120来搜索

在2节点没有搜索到阻塞者，回到1节点的trace文件搜索

那么我们只能以instance lock=QN 152264bc 374026d7来搜索

这里可以得到下面的2行，分别进入相应的行，找到MODE的

54281         instance lock=QN 152264bc 374026d754922         instance lock=QN 152264bc 374026d7

得到mode的row cache enqueue的信息

        —————————————-SO: 0x8e5c2150, type: 75, owner: 0x951b5128, flag: INIT/-/-/0x00 if: 0x1 c: 0x1proc=0x9cde1780, name=row cache enqueues, file=kqr.h LINE:2064, pg=0row cache enqueue: count=1 session=0x9b4728e8 object=0x8f0a1990, mode=Xsavepoint=0x29row cache parent object: address=0x8f0a1990 cid=13(dc_sequences)hash=152264bc typ=11 transaction=0x951b5128 flags=0000012aown=0x8f0a1a58[0x8e5c21f8,0x8e5c21f8] wat=0x8f0a1a68[0x8e5d5e58,0x8e5d5e58] mode=Xstatus=VALID/UPDATE/-/-/IO/-/-/-/-request=N release=TRUE flags=8instance lock=QN 152264bc 374026d7data=00012a05 0002000c 000f0002 00020001 000002c1 00000000 00000000 0000000002c10000 00000000 00000000 00000000 00000000 646464ce 64646464 6464646400646464 00800000 00000000 00000000 00000000 00000000 000003c1 0000000000000000 00000000 2d2d0000 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 00000000 152264bc 8f0a1990 00000000947397a8 00000000 947397a8 00000000 00000000 00000000 2d95f900 00007f5f00000001 00000000 00000000 00000000 8f0a1990 00000000 8f0a1b60 000000008f0a1b60 00000000 8f0a1b88 00000000 00000008 152264bc 374026d7 0000000000000101 00000000 0000011d 00000000 99cd8068 00000000 9cdcda70 000000008e4f6420 00000000 8e5b8288 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 999b9938 0000000000000001 00095556 00050520 08910321 8f0a1bf8 00000000 8f0a1bf8 0000000000000000 00000000 2d95f920 00007f5f 999b9980 00000000 999b9980 0000000006c25c14 00000000 00000000 00000000 2d95f920 00007f5f 99cd8068 000000008e5b8328 00000000 8e4f64c0 00000000 9c337718 00000000 00000000 000000028f0a1c68 00000000 8f0a1c68 00000000 00000000 00000000 00000000 000000008f0a1c88 00000000 8f0a1c88 00000000 8f0a1c98 00000000 8f0a1c98 000000008f0a1ca8 00000000 8f0a1ca8 00000000 00000000 00000000 2d95f908 00007f5f00000000 00000000 00000000 00000000 8f0a1cd8 00000000 8f0a1cd8 0000000000000000 00000000 00000000 00000000 5e2f04e8 00007fff 10600160 0000010003000001 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000001 00000108 00000000 8f0a1a58 00000000kssdmh:  so 0x8e5c2150 (type 75, "row cache enqueues") may not have children

以9b4728e8*type: 4来搜索会话的信息，可以看到会话正在等待TX的等待事件

    —————————————-SO: 0x9b4728e8, type: 4, owner: 0x9cde1780, flag: INIT/-/-/0x00 if: 0x3 c: 0x3proc=0x9cde1780, name=session, file=ksu.h LINE:12624, pg=0(session) sid: 795 ser: 15 trans: 0x951b5128, creator: 0x9cde1780flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/-flags2: (0x9) -/-/INCDID: , short-term DID:txn branch: (nil)oct: 3, prv: 0, sql: 0x8e4f5860, psql: 0x8f112090, user: 0/SYSksuxds FALSE at location: 0service name: SYS$USERSclient details:O/S info: user: oracle, term: pts/1, ospid: 6441machine: 11rac1 program: sqlplus@11rac1 (TNS V1-V3)application name: sqlplus@11rac1 (TNS V1-V3), hash value=985707405Current Wait Stack:0: waiting for ‘enq: TX – row lock contention‘

关于enq的等待，见enqueue

------------------作者介绍-----------------------
姓名：黄廷忠
现就职：Oracle中国高级服务团队
曾就职：OceanBase、云和恩墨、东方龙马等
电话、微信、QQ：18081072613
个人博客: (http://www.htz.pw)
CSDN地址: (https://blog.csdn.net/wwwhtzpw)
博客园地址: (https://www.cnblogs.com/www-htz-pw)