使用ass109.awk 分析会话阻塞情况

使用ass109.awk 分析会话阻塞情况

测试环境：
主机：RHEL6.3
数据库：11.2.0.3

现象：
在会话1，修改表dept中deptid=1的值并且没有提交
SQL> update DEPT set DEPTNAME='AAA' where DEPTID=1;
1 row updated.

在会话2，也同样修改dept中deptid=1的值
SQL> update dept set deptname='SSS' where deptid=1;
会话被阻塞，长时间无法提交

在会话3，使用oradebug工具做systemstate
SQL> oradebug setmypid
Statement processed.
SQL> oradebug unlimit   
Statement processed.
SQL> oradebug dump systemstate 10
Statement processed.
SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/db/db/trace/db_ora_40685.trc

使用ass109.awk工具分析trace文件
[oracle@r11g ~]$ awk -f /home/oracle/ass109.awk /u01/app/oracle/diag/rdbms/db/db/trace/db_ora_40685.trc

Starting Systemstate 1
..............................
Ass.Awk Version 1.0.9 - Processing /u01/app/oracle/diag/rdbms/db/db/trace/db_ora_40685.trc

System State 1
~~~~~~~~~~~~~~~~
1:                                      
2:  0: waiting for 'pmon timer'         
3:  0: waiting for 'rdbms ipc message'  
4:  0: waiting for 'VKTM Logical Idle Wait' 
5:  0: waiting for 'rdbms ipc message'  
6:  0: waiting for 'DIAG idle wait'     
7:  0: waiting for 'rdbms ipc message'  
8:  0: waiting for 'DIAG idle wait'     
9:  0: waiting for 'rdbms ipc message'  
10: 0: waiting for 'rdbms ipc message'  
11: 0: waiting for 'rdbms ipc message'  
12: 0: waiting for 'rdbms ipc message'  
13: 0: waiting for 'smon timer'         
14: 0: waiting for 'rdbms ipc message'  
15: 0: waiting for 'rdbms ipc message'  
16: 0: waiting for 'rdbms ipc message'  
17:                                     
18:                                     
19: 0: waiting for 'Space Manager: slave idle wait' 
20: 0: waiting for 'rdbms ipc message'  
21: 0: waiting for 'rdbms ipc message'  
22: 0: waiting for 'rdbms ipc message'  
23: 0: waiting for 'rdbms ipc message'  
24: 0: waiting for 'Streams AQ: qmn coordinator idle wait' 
25: 0: waiting for 'SQL*Net message from client' 
26: 0: waiting for 'enq: TX - row lock contention'[Enqueue TX-00050005-000001BE] 
     Cmd: Update
27: 0: waiting for 'Streams AQ: qmn slave idle wait' 
28: 0: waited for 'Streams AQ: waiting for time management or cleanup tasks' 
29: 0: waiting for 'rdbms ipc message'  
30:                                     
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 TX-00050005-000001BE    25: 0: waiting for 'SQL*Net message from client'

Object Names
~~~~~~~~~~~~
Enqueue TX-00050005-000001BE                                  

15700 Lines Processed.

从上面可以看到pid 26 被pid 25的会话给阻塞了。
SQL> select sid,SERIAL# from v$session where paddr in (select addr from v$process where pid in (25,26));


       SID    SERIAL#
---------- ----------
        44        821
        45        805
从v$lock视图，也可以查询到阻塞信息，这个同trace文件分析的一致。
USERNAME                    SID    SERIAL# TY LMODE                REQUEST                     ID1        ID2
-------------------- ---------- ---------- -- -------------------- -------------------- ---------- ----------
LIUTYA                       44        821 TX Exclusive            None                     327685        446
LIUTYA                       45        805 TX None                 Exclusive                327685        446

从原始trace文件中，我们可以进一步获取信息
PROCESS 26:
  ----------------------------------------
  SO: 0x9f49fad8, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x9f49fad8, name=process, file=ksu.h LINE:12616, pg=0
  (process) Oracle pid:26, ser:177, calls cur/top: 0x9f093a20/0x9f093a20
            flags : (0x0) -
            flags2: (0x0),  flags3: (0x10)
            intr error: 0, call error: 0, sess error: 0, txn error 0
            intr queue: empty
    ksudlp FALSE at location: 0
  (post info) last post received: 0 0 0
              last post received-location: No post
              last process to post me: none
              last post sent: 0 0 26
              last post sent-location: ksa2.h LINE:285 ID:ksasnd
              last process posted by me: 9f490088 1 6
    (latch info) wait_event=0 bits=0
    Process Group: DEFAULT, pseudo proc: 0x9f52d920
    O/S info: user: oracle, term: UNKNOWN, ospid: 40616
    OSD pid info: Unix process pid: 40616, image: oracle@r11g (TNS V1-V3)
    ----------------------------------------
    SO: 0x9d8f5f20, type: 10, owner: 0x9f49fad8, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
     proc=0x9f49fad8, name=FileOpenBlock, file=ksfd.h LINE:6448, pg=0
    (FOB) 0x9d8f5f20 flags=2050 fib=0x9dabef40 incno=0 pending i/o cnt=0
     fname=/u01/app/oracle/oradata/db/users01.dbf
     fno=4 lblksz=8192 fsiz=64000
    ----------------------------------------
    SO: 0x9d8f5e00, type: 10, owner: 0x9f49fad8, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
     proc=0x9f49fad8, name=FileOpenBlock, file=ksfd.h LINE:6448, pg=0
    (FOB) 0x9d8f5e00 flags=2050 fib=0x9dabdcf8 incno=0 pending i/o cnt=0
     fname=/u01/app/oracle/oradata/db/system01.dbf
     fno=1 lblksz=8192 fsiz=64000
    ----------------------------------------
    SO: 0x9f798f18, type: 4, owner: 0x9f49fad8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
     proc=0x9f49fad8, name=session, file=ksu.h LINE:12624, pg=0
    (session) sid: 45 ser: 805 trans: 0x9d673fd8, creator: 0x9f49fad8
              flags: (0x45) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
              flags2: (0x40009) -/-/INC
              DID: , short-term DID:
              txn branch: (nil)
              oct: 6, prv: 0, sql: 0x92979f40, psql: 0x92b2c318, user: 32/LIUTYA
    ksuxds FALSE at location: 0
    service name: SYS$USERS
    client details:
      O/S info: user: oracle, term: pts/1, ospid: 40612
      machine: r11g program: sqlplus@r11g (TNS V1-V3)
      application name: SQL*Plus, hash value=3669949024
    Current Wait Stack:
     0: waiting for 'enq: TX - row lock contention'
        name|mode=0x54580006, usn<<16 | slot=0x50005, sequence=0x1be
        wait_id=67 seq_num=68 snap_id=1
        wait times: snap=8 min 2 sec, exc=8 min 2 sec, total=8 min 2 sec
        wait times: max=infinite, heur=8 min 2 sec
        wait counts: calls=161 os=161
        in_wait=1 iflags=0x15a0
    There is at least one session blocking this session.
      Dumping 1 direct blocker(s):
        inst: 1, sid: 44, ser: 821
      Dumping final blocker:
        inst: 1, sid: 44, ser: 821
    Wait State:
      fixed_waits=0 flags=0x22 boundary=(nil)/-1
    Session Wait History:
        elapsed time of 0.004040 sec since current wait
     0: waited for 'SQL*Net message from client'
        driver id=0x62657100, #bytes=0x1, =0x0
        wait_id=66 seq_num=67 snap_id=1
        wait times: snap=1 min 27 sec, exc=1 min 27 sec, total=1 min 27 sec
        wait times: max=infinite
        wait counts: calls=0 os=0
        occurred after 0.000021 sec of elapsed time
     1: waited for 'SQL*Net message to client'
        driver id=0x62657100, #bytes=0x1, =0x0
        wait_id=65 seq_num=66 snap_id=1
        wait times: snap=0.000000 sec, exc=0.000000 sec, total=0.000000 sec
        wait times: max=infinite
        wait counts: calls=0 os=0
        occurred after 0.000019 sec of elapsed time
     2: waited for 'SQL*Net message from client'
        driver id=0x62657100, #bytes=0x1, =0x0
        wait_id=64 seq_num=65 snap_id=1
        wait times: snap=0.000399 sec, exc=0.000399 sec, total=0.000399 sec
        wait times: max=infinite
        wait counts: calls=0 os=0
        occurred after 0.000046 sec of elapsed time
     3: waited for 'db file sequential read'
        file#=0x4, block#=0x81, blocks=0x1
        wait_id=63 seq_num=64 snap_id=1
        wait times: snap=0.000110 sec, exc=0.000110 sec, total=0.000110 sec
        wait times: max=infinite
        wait counts: calls=0 os=0
        occurred after 0.000131 sec of elapsed time
     4: waited for 'db file sequential read'
        file#=0x4, block#=0x80, blocks=0x1
        wait_id=62 seq_num=63 snap_id=1
        wait times: snap=0.000109 sec, exc=0.000109 sec, total=0.000109 sec
        wait times: max=infinite
        wait counts: calls=0 os=0
        occurred after 0.000006 sec of elapsed time
     5: waited for 'Disk file operations I/O'
        FileOperation=0x2, fileno=0x4, filetype=0x2
        wait_id=61 seq_num=62 snap_id=1

ass109.awk使分析trace文件简单了许多，是分析trace 的不错工具。


参考 惜分飞《 使用ass109.awk分析systemstate》

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/11590946/viewspace-1063005/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/11590946/viewspace-1063005/