使用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》
測試環境：
主機：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/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- hanganalyze分析會話阻塞會話
- Oracle阻塞會話查詢Oracle會話
- 模擬阻塞會話例項會話
- hs message to agent'阻塞會話會話
- SQLServer如何監控阻塞會話SQLServer會話
- oracle ora-60 deadlock發生在多個會話的情況Oracle會話
- 為什麼sleeping的會話會造成阻塞會話
- switch不加break情況分析
- Check_oracle_health 之阻塞會話數Oracle會話
- 為什麼sleeping的會話會造成阻塞(2)會話
- 呼叫layoutSubviews各種情況分析View
- MySQL的共享鎖阻塞會話案例淺析MySql會話
- oracle v$sqlare 分析SQL語句使用資源情況OracleSQL
- mysql索引不會命中的情況MySql索引
- Mysql 會導致索引失效的情況MySql索引
- 一句話計算出 TopN 的增長情況
- 流失原因分析方法6 版本消化情況分析法
- 工信部：2016年1月電話使用者分省資料情況
- Kill會話過程分析會話
- oracle order by索引是否使用的情況Oracle索引
- 直接登入資料庫使用drop table tablename;會是什麼情況？資料庫
- CIO：採用多雲策略的情況分析
- Cirium：疫情之下航空業復甦情況分析
- ORACLE程式佔用CPU情況分析（轉載）Oracle
- 試分析tempdb transaction log變滿的情況
- eMarketer：印尼社會化網路發展情況
- Mongodb記憶體管理和使用情況情況查詢MongoDB記憶體
- 遭遇cursor:pin x等待事件定位阻塞會話診斷過程事件會話
- 在不會使用excel函式的情況下如何完成複雜任務Excel函式
- 觀察者Observer模型事件，使用注意情況Server模型事件
- 記一次使用Oauth的情況OAuth
- 公司使用大資料的基本情況大資料
- PHP應避免使用addslashes()的情況PHP
- Web會話安全分析工具ProxyStrikeWeb會話
- Kill會話過程分析（二）會話
- MySQL中slave監控的延遲情況分析MySql
- Redis 實用小技巧—— key 分佈情況分析Redis
- 伺服器過載會出現什麼情況伺服器