下面是一次测试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.trc
Starting Systemstate 1 ……………………………………………… Ass.Awk Version 1.0.39 ~~~~~~~~~~~~~~~~~~~~~~ Source file : /u01/app/oracle/diag/rdbms/power/power1/trace/power1_ora_14290.trc
System 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 Execute 44: 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: Select 48: waiting for ‘rdbms ipc message’ 49: waiting for ‘enq: TX – row lock contention'[Enq TX-00010008-00000629] Cmd: Select 50: waiting for ‘row cache lock’ [Rcache object=0x8f0a1990,] Cmd: Select 51: 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 resource then it will be given in square brackets. Below is a summary of the waited upon resources, together with the holder of that resource. Notes: ~~~~~ o A process id of ‘???’ implies that the holder was not found in the systemstate. (The holder may have released the resource before we dumped 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, see http://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.html#enqcnv)
Resource Holder State Enq 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 see http://dlsunuk11.uk.oracle.com/Public/Utils.html#ass
For additional documentation see http://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.html
Suggested improvements, bugs etc. should be sent to kevin.p.quinn@oracle.com
End of report. 60404 Lines Processed.
[oracle@11rac2 sql]$ awk -f ass1039.awk /u01/app/oracle/diag/rdbms/power/power2/trace/power2_ora_9758.trc
Starting Systemstate 1 …………………………………………… Ass.Awk Version 1.0.39 ~~~~~~~~~~~~~~~~~~~~~~ Source file : /u01/app/oracle/diag/rdbms/power/power2/trace/power2_ora_9758.trc
System 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: Select 47: 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 resource then it will be given in square brackets. Below is a summary of the waited upon resources, together with the holder of that resource. Notes: ~~~~~ o A process id of ‘???’ implies that the holder was not found in the systemstate. (The holder may have released the resource before we dumped 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, see http://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.html#enqcnv)
Resource Holder State Rcache object=0x8e9a5120, ??? Blocker
Object 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 see http://dlsunuk11.uk.oracle.com/Public/Utils.html#ass
For additional documentation see http://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.html
Suggested improvements, bugs etc. should be sent to kevin.p.quinn@oracle.com
End 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: 0x3 proc=0x9ce441f0, name=session, file=ksu.h LINE:12624, pg=0 (session) sid: 52 ser: 15 trans: 0x9515a1f0, creator: 0x9ce441f0 flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/- flags2: (0x40009) -/-/INC DID: , short-term DID: txn branch: (nil) oct: 3, prv: 0, sql: 0x8e954a20, psql: 0x8f50cfd0, user: 0/SYS ksuxds FALSE at location: 0 service name: SYS$USERS client details: O/S info: user: oracle, term: pts/0, ospid: 6268 machine: 11rac2 program: sqlplus@11rac2 (TNS V1-V3) application name: sqlplus@11rac2 (TNS V1-V3), hash value=3270042948 Current Wait Stack: 0: waiting for ‘row cache lock’ cache id=0xd, mode=0x0, request=0x5 wait_id=6656 seq_num=6657 snap_id=1 wait times: snap=0.001217 sec, exc=0.001217 sec, total=0.001217 sec wait times: max=3.000000 sec, heur=3 min 6 sec wait counts: calls=1 os=1 in_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 enqueue*session*9b513658来搜索
|
SO: 0x8e990c40, type: 75, owner: 0x9515a1f0, flag: INIT/-/-/0x00 if: 0x1 c: 0x1 proc=0x9ce441f0, name=row cache enqueues, file=kqr.h LINE:2064, pg=0 row cache enqueue: count=1 session=0x9b513658 object=0x8e9a5120, request=X savepoint=0x46 row cache parent object: address=0x8e9a5120 cid=13(dc_sequences) hash=152264bc typ=11 transaction=(nil) flags=00000000 own=0x8e9a51e8[0x8e9a51e8,0x8e9a51e8] wat=0x8e9a51f8[0x8e990ce8,0x8e990ce8] mode=N status=-/-/-/-/-/-/-/-/- request=X release=FALSE flags=a instance lock=QN 152264bc 374026d7 data= 00012a05 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 152264bc 8e9a5120 00000000 947397a8 00000000 947397a8 00000000 00000005 00000000 26784f80 00007f3c 00000000 00000000 00000000 00000000 8e9a5120 00000000 8e9a52f0 00000000 8e9a52f0 00000000 8e9a5318 00000000 0000000a 152264bc 374026d7 00000000 00000101 00000000 0000011d 00000000 99dd8510 00000000 9ce336f0 00000000 8f4eb538 00000000 98c04f78 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 99f79978 00000000 00000001 0000009a 00050001 08910321 8e9a5388 00000000 8e9a5388 00000000 0730efec 00000000 26784fa0 00007f3c 99f799d0 00000000 99f799d0 00000000 00000000 00000000 00000000 00000000 00000000 00000000 99dd8510 00000000 98c05018 00000000 8f4eb5d8 00000000 9b554ec8 00000000 00000000 00000002 8e9a53f8 00000000 8e9a53f8 00000000 00000000 00000000 00000000 00000000 8e9a5418 00000000 8e9a5418 00000000 8e9a5428 00000000 8e9a5428 00000000 99dca9b8 00000000 99dca9b8 00000000 00000000 00004fe7 26784f88 00007f3c 00000000 00000000 00000000 00000000 8e9a5468 00000000 8e9a5468 00000000 00000000 00000000 00000000 00000000 feb172d0 00007fff 10600160 09000200 00000000 00000000 06c25c14 00000000 26784fa0 00007f3c 00000000 00000000 f251fa11 00000002 00000000 00000000 8e9a51e8 00000000 kssdmh: so 0x8e990c40 (type 75, "row cache enqueues") may not have children |
红色的部分就是row cache enqueue的信息
instance lock=QN 152264bc 374026d7这里是全局锁的信息，如果在本地没有找到阻塞者的时候，我们就要以这个在其它的节点找到。
3，搜索阻塞者
以row cache enqueue*object*8e9a5120来搜索
在2节点没有搜索到阻塞者，回到1节点的trace文件搜索
那么我们只能以instance lock=QN 152264bc 374026d7来搜索
这里可以得到下面的2行，分别进入相应的行，找到MODE的
|
54281 instance lock=QN 152264bc 374026d7 54922 instance lock=QN 152264bc 374026d7 |
得到mode的row cache enqueue的信息
|
—————————————- SO: 0x8e5c2150, type: 75, owner: 0x951b5128, flag: INIT/-/-/0x00 if: 0x1 c: 0x1 proc=0x9cde1780, name=row cache enqueues, file=kqr.h LINE:2064, pg=0 row cache enqueue: count=1 session=0x9b4728e8 object=0x8f0a1990, mode=X savepoint=0x29 row cache parent object: address=0x8f0a1990 cid=13(dc_sequences) hash=152264bc typ=11 transaction=0x951b5128 flags=0000012a own=0x8f0a1a58[0x8e5c21f8,0x8e5c21f8] wat=0x8f0a1a68[0x8e5d5e58,0x8e5d5e58] mode=X status=VALID/UPDATE/-/-/IO/-/-/-/- request=N release=TRUE flags=8 instance lock=QN 152264bc 374026d7 data= 00012a05 0002000c 000f0002 00020001 000002c1 00000000 00000000 00000000 02c10000 00000000 00000000 00000000 00000000 646464ce 64646464 64646464 00646464 00800000 00000000 00000000 00000000 00000000 000003c1 00000000 00000000 00000000 2d2d0000 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 00000000 152264bc 8f0a1990 00000000 947397a8 00000000 947397a8 00000000 00000000 00000000 2d95f900 00007f5f 00000001 00000000 00000000 00000000 8f0a1990 00000000 8f0a1b60 00000000 8f0a1b60 00000000 8f0a1b88 00000000 00000008 152264bc 374026d7 00000000 00000101 00000000 0000011d 00000000 99cd8068 00000000 9cdcda70 00000000 8e4f6420 00000000 8e5b8288 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 999b9938 00000000 00000001 00095556 00050520 08910321 8f0a1bf8 00000000 8f0a1bf8 00000000 00000000 00000000 2d95f920 00007f5f 999b9980 00000000 999b9980 00000000 06c25c14 00000000 00000000 00000000 2d95f920 00007f5f 99cd8068 00000000 8e5b8328 00000000 8e4f64c0 00000000 9c337718 00000000 00000000 00000002 8f0a1c68 00000000 8f0a1c68 00000000 00000000 00000000 00000000 00000000 8f0a1c88 00000000 8f0a1c88 00000000 8f0a1c98 00000000 8f0a1c98 00000000 8f0a1ca8 00000000 8f0a1ca8 00000000 00000000 00000000 2d95f908 00007f5f 00000000 00000000 00000000 00000000 8f0a1cd8 00000000 8f0a1cd8 00000000 00000000 00000000 00000000 00000000 5e2f04e8 00007fff 10600160 00000100 03000001 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000001 00000108 00000000 8f0a1a58 00000000 kssdmh: 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: 0x3 proc=0x9cde1780, name=session, file=ksu.h LINE:12624, pg=0 (session) sid: 795 ser: 15 trans: 0x951b5128, creator: 0x9cde1780 flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/- flags2: (0x9) -/-/INC DID: , short-term DID: txn branch: (nil) oct: 3, prv: 0, sql: 0x8e4f5860, psql: 0x8f112090, user: 0/SYS ksuxds FALSE at location: 0 service name: SYS$USERS client details: O/S info: user: oracle, term: pts/1, ospid: 6441 machine: 11rac1 program: sqlplus@11rac1 (TNS V1-V3) application name: sqlplus@11rac1 (TNS V1-V3), hash value=985707405 Current Wait Stack: 0: waiting for ‘enq: TX – row lock contention‘ |
关于enq的等待，见enqueue
systemstate分析row cache lock：等您坐沙发呢！