System State Dump Evaluation with ass.awk
By Martin | December 10th, 2008 | Category: 10g, 11g, 9iR2, MetaLink, Oracle Database, Real Application Clusters | No Comments »I have found out that there is an Oracle Support utility called ass.awk, which can be used to analyze and format a System State dump. It is contained in LTOM, which can be downloaded from MetaLink.
The AWK script is called ass109.awk and can be used in this manner:
[oracle@ora-vm1 ~]$ awk -f ass109.awk mddb1_diag_12345.trc System State ASS: Starting Systemstate 1 .............................................................................. ..... Ass.Awk Version 1.0.9 - Processing mddb1_diag_12345.trc System State 1 ~~~~~~~~~~~~~~~~ 1: 2: waiting FOR 'pmon timer' wait 3: LAST wait FOR 'ksdxexeotherwait' 4: waiting FOR 'rdbms ipc message' wait 5: waiting FOR 'rdbms ipc message' wait 6: waiting FOR 'ges remote message' wait 7: waiting FOR 'gcs log flush sync' wait 8: waiting FOR 'gcs log flush sync' wait 9: waiting FOR 'rdbms ipc message' wait 10: waiting FOR 'rdbms ipc message' wait 11: waiting FOR 'enq: CF - contention' [Enqueue CF-00000000-00000000] wait 12: waiting FOR 'rdbms ipc message' wait 13: waiting FOR 'buffer busy waits' (2,a9,3b) wait 14: waiting FOR 'rdbms ipc message' wait 15: waiting FOR 'rdbms ipc message' wait 16: waiting FOR 'buffer busy waits' (2,a9,3b) wait 17: waiting FOR 'rdbms ipc message' wait 18: 19: 20: waiting FOR 'rdbms ipc message' wait 21: waiting FOR 'log file sync' wait 22: waiting FOR 'ASM background timer' wait 23: waiting FOR 'rdbms ipc message' wait 24: waiting FOR 'log file sync' wait 25: waiting FOR 'class slave wait' wait 26: waiting FOR 'SQL*Net message from client' wait 27: waiting FOR 'SQL*Net message from client' wait 28: waiting FOR 'enq: CF - contention' [Enqueue CF-00000000-00000000] wait 29: waiting FOR 'enq: CF - contention' [Enqueue CF-00000000-00000000] wait 30: waiting FOR 'Streams AQ: qmn coordinator idle wait' wait 31: waiting FOR 'SQL*Net message from client' wait 32: waiting FOR 'SQL*Net message from client' wait Cmd: SELECT 33: waiting FOR 'log file sync' wait 34: waiting FOR 'Streams AQ: qmn slave idle wait' wait 35: FOR 'Streams AQ: waiting for time management or cleanup tasks' wait 36: waiting FOR 'log file sync' wait 37: waiting FOR 'SQL*Net message from client' wait Cmd: SELECT 38: waiting FOR 'SQL*Net message from client' wait 39: waiting FOR 'SQL*Net message from client' wait 40: waiting FOR 'PX Deq: Execution Msg' wait 41: waiting FOR 'log file sync' wait 42: waiting FOR 'log file sync' wait 43: waiting FOR 'enq: CF - contention' [Enqueue CF-00000000-00000000] wait Cmd: SELECT 44: waiting FOR 'SQL*Net message from client' wait 45: waiting FOR 'SQL*Net message from client' wait 46: waiting FOR 'SQL*Net message from client' wait 47: waiting FOR 'SQL*Net message from client' wait 48: waiting FOR 'SQL*Net message from client' wait 49: waiting FOR 'log file sync' wait 50: waiting FOR 'SQL*Net message from client' wait 51: waiting FOR 'SQL*Net message from client' wait Cmd: SELECT 52: waiting FOR 'row cache lock' [Rcache object=0xa5414098,] wait Cmd: SELECT 53: waiting FOR 'SQL*Net message from client' wait 54: waiting FOR 'SQL*Net message from client' wait 55: FOR 'Streams AQ: waiting for messages in the queue' wait 56: waiting FOR 'SQL*Net message from client' wait 57: waiting FOR 'SQL*Net message from client' wait 58: waiting FOR 'log file sync' wait Cmd: INSERT 59: waiting FOR 'jobq slave wait' wait 60: waiting FOR 'jobq slave wait' wait 61: waiting FOR 'SQL*Net message from client' wait 62: waiting FOR 'SQL*Net message from client' wait 63: waiting FOR 'SQL*Net message from client' wait 65: waiting FOR 'SQL*Net message from client' wait Cmd: SELECT 66: waiting FOR 'SQL*Net message from client' wait 67: LAST wait FOR 'SQL*Net message from client' 68: waiting FOR 'SQL*Net message from client' wait 69: waiting FOR 'SQL*Net message from client' wait 70: waiting FOR 'SQL*Net message from client' wait 71: waiting FOR 'SQL*Net message from client' wait 72: waiting FOR 'SQL*Net message from client' wait 73: waiting FOR 'SQL*Net message from client' wait 74: waiting FOR 'SQL*Net message from client' wait Cmd: SELECT 75: waiting FOR 'SQL*Net message from client' wait Cmd: SELECT 76: waiting FOR 'SQL*Net message from client' wait 77: waiting FOR 'log file sync' wait 78: waiting FOR 'SQL*Net message from client' wait 80: waiting FOR 'SQL*Net message from client' wait Cmd: SELECT 82: waiting FOR 'SQL*Net message from client' wait 84: waiting FOR 'log file sync' wait 86: waiting FOR 'SQL*Net message from client' wait 93: waiting FOR 'SQL*Net message from client' wait 94: waiting FOR 'SQL*Net message from client' 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. Resource Holder State Enqueue CF-00000000-00000000 12: waiting FOR 'rdbms ipc message' Rcache object=0xa5414098, ??? Blocker Object Names ~~~~~~~~~~~~ Enqueue CF-00000000-00000000 Rcache object=0xa5414098, |
With this information, you can investigate further into the System state dump by looking at rcache object 0xa5414098. The “State Objects” are a hierarchical structure. Every state object has an adress “SO: 0xa6a5955c” and an owner, which is the parent entry. In this case, you can construct a hierarchical tree of state objects and find dependencies.
SO: 0xa6a5995c, TYPE: 2, owner: (nil), flag: INIT/-/-/0x00 (process) Oracle pid=52, calls cur/top: 0x9d62eb1c/0x9d5ccfcc, flag: (0) - INT error: 0, CALL error: 0, sess error: 0, txn error 0 (post info) LAST post received: 0 0 163 LAST post received-location: kqrbtm LAST process TO post me: a6a4e1dc 1 6 LAST post sent: 0 0 24 LAST post sent-location: ksasnd LAST process posted BY me: a6a4e1dc 1 6 (latch info) wait_event=0 bits=0 Process GROUP: DEFAULT, pseudo proc: 0xa6baf79c O/S info: USER: oracle, term: UNKNOWN, ospid: 29032 OSD pid info: Unix process pid: 29032, image: oracle@ora-vm1 Short stack dump: ksdxfstk()+19<-ksdxcb()+1321<-sspuser()+102<-__kernel_vsyscall()+16 SO: 0xa4123d20, TYPE: 4, owner: 0xa6a5995c, flag: INIT/-/-/0x00 (SESSION) sid: 955 trans: (nil), creator: 0xa6a5995c, flag: (41) USR/- BSY/-/-/-/-/- DID: 0001-0034-00002227, short-term DID: 0001-0034-00002228 txn branch: (nil) oct: 3, prv: 0, SQL: 0x8fee9d44, psql: 0x8fee9f00, USER: 23/DBSNMP service name: SYS$USERS O/S info: USER: oracle, term: , ospid: 28849, machine: ora-vm1 program: emagent@ora-vm1(TNS V1-V3) application name: emagent@ora-vm1(TNS V1-V3), hash VALUE=2420928497 waiting FOR 'row cache lock' blocking sess=0x(nil) seq=127 wait_time=0 seconds since wait started=0 cache id=d, mode=0, request=5 Dumping SESSION Wait History FOR 'row cache lock' COUNT=1 wait_time=1337230 cache id=d, mode=0, request=5 FOR 'row cache lock' COUNT=1 wait_time=2930561 cache id=d, mode=0, request=5 FOR 'row cache lock' COUNT=1 wait_time=2929106 cache id=d, mode=0, request=5 FOR 'row cache lock' COUNT=1 wait_time=2933326 SO: 0x9d5ccfcc, TYPE: 3, owner: 0xa6a5995c, flag: INIT/-/-/0x00 (CALL) sess: cur a4123d20, rec a4123d20, usr a4123d20; depth: 0 ---------------------------------------- SO: 0x9d51b1a0, TYPE: 3, owner: 0x9d5ccfcc, flag: INIT/-/-/0x00 (CALL) sess: cur a4123d20, rec a417f990, usr a4123d20; depth: 1 ---------------------------------------- SO: 0x9d69d7f0, TYPE: 3, owner: 0x9d51b1a0, flag: INIT/-/-/0x00 (CALL) sess: cur a417f990, rec a417f990, usr a4123d20; depth: 2 ---------------------------------------- SO: 0x9d5e547c, TYPE: 3, owner: 0x9d69d7f0, flag: INIT/-/-/0x00 (CALL) sess: cur a417f990, rec a417f990, usr a4123d20; depth: 3 ---------------------------------------- SO: 0x9d62eb1c, TYPE: 3, owner: 0x9d5e547c, flag: INIT/-/-/0x00 (CALL) sess: cur a417f990, rec a417f990, usr a4123d20; depth: 4 ---------------------------------------- SO: 0x9fedf748, TYPE: 40, owner: 0x9d62eb1c, flag: INIT/-/-/0x00 (trans) flg = 0x21, flg2 = 0x80000, prx = 0x0, ros = 2147483647 bsn = 0x395 bndsn = 0x395 spn = 0x395 efd = 34 parent xid: 0x0000.000.00000000 env: (scn: 0x0000.00000000 xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 0sch: scn: 0x0000.00000000) cev: (spc = 0 arsp = 0 ubk tsn: 0 rdba: 0x00000000 useg tsn: 0 rdba: 0x00000000 hwm uba: 0x00000000.0000.00 col uba: 0x00000000.0000.00 num bl: 0 bk list: 0x0) cr opc: 0x0 spc: 0 uba: 0x00000000.0000.00 (enqueue) TX-00010011-00D3B4CF DID: 0001-0051-00001323 lv: 7c ac ad 4d 03 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x45 res: 0xa447bb2c, lock_flag: 0x0 own: 0xa4157e90, sess: 0xa4157e90, prv: 0x9fedf774 slk: (nil) xga: 0x0, heap: UGA Trans IMU st: 0 Pool INDEX 65535, Redo pool 0x9fedfb74, Undo pool 0x9fedfbf0 Redo pool range [0x40ed57e8 0x40ed57e8 0x40ed7fe8] Undo pool range [0x40ed2fe8 0x40ed2fe8 0x40ed57e8] ---------------------------------------- SO: 0x9d42237c, TYPE: 50, owner: 0x9fedf748, flag: INIT/-/-/0x00 ROW cache enqueue: COUNT=1 SESSION=0xa4123d20 object=0xa5414098, request=X SAVEPOINT=0x395 ROW cache parent object: address=0xa5414098 cid=13(dc_sequences) hash=9649e7e typ=9 TRANSACTION=(nil) flags=00000000 own=0xa5414104[0xa5414104,0xa5414104] wat=0xa541410c[0x9d422398,0x9d422398] mode=N STATUS=-/-/-/-/-/-/-/-/- request=X release=FALSE flags=2 instance LOCK id=QN 010cdbb3 b3b24847 |
Tanel Poder showed in his seminar to use “grep -A 3 SO:” to find all lines containing the State Object Adresses and the following 3 lines to get the tree.
