[20210207]使用gdb檢視等待事件11g.txt
[20210207]使用gdb檢視等待事件11g.txt
https://nenadnoveljic.com/blog/wait-events-dtrace/
Before jumping to the DTrace script, I'd like summarize (and partially paraphrase) the most relevant information in
Stefan's article.
1. Oracle function kslwtbctx represents the start of a wait event.
2. Oracle function kslwtbctx calls the function kskthbwt to get/store the corresponding wait event (number).
3. Oracle function kslwtectx represents the end of a wait event.
4. The Solaris kernel function get_cur_hrtime returns the current time in nanoseconds relative to some arbitrary point
in the past.
5. The Solaris kernel function get_cur_hrtime gets called before and after the wait event. Subsequently, the difference
--//無聊看了一下dtrace,我也沒有soalris,好奇使用gdb寫一個測試看看,我不知道如何使用時間戳,使用shell呼叫,這樣誤差很大.
--//拋磚引玉,那位有更好的方法.
1.環境:
SCOTT@book> @ ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.建立gdb指令碼:
$ cat wait.gdb
break kslwtbctx
set pagination off
commands
silent
shell echo -n $( date +"%Y/%m/%d %T.%N : ")
printf "kslwtbctx %d\n", *($rdi+104)
continue
end
break kslwtectx
set pagination off
commands
silent
shell echo -n $( date +"%Y/%m/%d %T.%N : ")
printf "kslwtectx %d\n", *($rdi+104)
continue
end
3.測試:
--//session 1:
SCOTT@book> @ spid
SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
44 17325 16254 DEDICATED 16255 27 31 alter system kill session '44,17325' immediate;
SCOTT@book> select rowid,dept.* from dept;
ROWID DEPTNO DNAME LOC
------------------ ---------- -------------- -------------
AAAVRCAAEAAAACHAAA 10 ACCOUNTING NEW YORK
AAAVRCAAEAAAACHAAB 20 RESEARCH DALLAS
AAAVRCAAEAAAACHAAC 30 SALES CHICAGO
AAAVRCAAEAAAACHAAD 40 OPERATIONS BOSTON
SCOTT@book> @ rowid AAAVRCAAEAAAACHAAA
OBJECT FILE BLOCK ROW ROWID_DBA DBA TEXT
---------- ---------- ---------- ---------- -------------------- -------------------- ----------------------------------------
87106 4 135 0 0x1000087 4,135 alter system dump datafile 4 block 135 ;
--//session 2:
$ gdb -p 16255 -x ~/sqllaji/gdb/wait.gdb
--//session 1:
SCOTT@book> select * from dept where rowid='AAAVRCAAEAAAACHAAA';
--//session 2:
(gdb) c
Continuing.
2021/02/07 16:47:23.548676089 :kslwtectx 354
2021/02/07 16:47:23.554744212 :kslwtbctx 350
2021/02/07 16:47:23.560578464 :kslwtectx 350
2021/02/07 16:47:23.566160107 :kslwtbctx 354
2021/02/07 16:47:23.571898349 :kslwtectx 354
2021/02/07 16:47:23.577223148 :kslwtbctx 350
2021/02/07 16:47:23.582679122 :kslwtectx 350
2021/02/07 16:47:23.588008331 :kslwtbctx 354
--//session 3:
SYS@book> select * from v$event_name where event# in (354,350);
EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- -------------------- -------------------- -------------------- ------------- ----------- --------------------
350 2067390145 SQL*Net message to client driver id #bytes 2000153315 7 Network
354 1421975091 SQL*Net message from client driver id #bytes 2723168908 6 Idle
--//可以發現第1個等待事件SQL*Net message from client是它的結束,就是等待輸入SQL語句執行.
SYS@book> alter system flush buffer_cache;
System altered.
--//session 1:
SCOTT@book> select * from dept where rowid='AAAVRCAAEAAAACHAAA';
DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
--//session 2:
2021/02/07 16:51:09.465856590 :kslwtectx 354
2021/02/07 16:51:09.471628314 :kslwtbctx 350
2021/02/07 16:51:09.476914617 :kslwtectx 350
2021/02/07 16:51:09.482343684 :kslwtbctx 147
2021/02/07 16:51:09.487629492 :kslwtectx 147
2021/02/07 16:51:09.493093759 :kslwtbctx 354
2021/02/07 16:51:09.498740145 :kslwtectx 354
2021/02/07 16:51:09.504203935 :kslwtbctx 350
2021/02/07 16:51:09.509550913 :kslwtectx 350
2021/02/07 16:51:09.514826023 :kslwtbctx 354
SYS@book> select * from v$event_name where event# in (354,350,147);
EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- -------------------- -------------------- -------------------- ------------- ----------- --------------------
147 2652584166 db file sequential read file# block# blocks 1740759767 8 User I/O
350 2067390145 SQL*Net message to client driver id #bytes 2000153315 7 Network
354 1421975091 SQL*Net message from client driver id #bytes 2723168908 6 Idle
--//再次重複:
--//session 2:
SYS@book> alter system flush buffer_cache;
System altered.
SYS@book> select * from v$session_event where sid=44;
SID EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT MAX_WAIT TIME_WAITED_MICRO EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------------
44 Disk file operations I/O 2 0 666 332.8 666 6655904 166678035 1740759767 8 User I/O
44 latch: cache buffers chains 2 0 9134 4566.96 7166 91339244 2779959231 3875070507 4 Concurrency
44 db file sequential read 89 0 6389 71.79 6387 63893115 2652584166 1740759767 8 User I/O
44 db file scattered read 1 0 0 0 0 31 506183215 1740759767 8 User I/O
44 SQL*Net message to client 97 0 6493 66.94 2781 64932466 2067390145 2000153315 7 Network
44 SQL*Net message from client 96 0 439391 4576.99 56085 4393908646 1421975091 2723168908 6 Idle
6 rows selected.
--//session 1:
SCOTT@book> select * from dept where rowid='AAAVRCAAEAAAACHAAA';
DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
--//session 2:
SYS@book> select * from v$session_event where sid=44;
SID EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT MAX_WAIT TIME_WAITED_MICRO EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------------
44 Disk file operations I/O 2 0 666 332.8 666 6655904 166678035 1740759767 8 User I/O
44 latch: cache buffers chains 2 0 9134 4566.96 7166 91339244 2779959231 3875070507 4 Concurrency
44 db file sequential read 90 0 6390 71 6387 63898432 2652584166 1740759767 8 User I/O
44 db file scattered read 1 0 0 0 0 31 506183215 1740759767 8 User I/O
44 SQL*Net message to client 99 0 6494 65.6 2781 64943292 2067390145 2000153315 7 Network
44 SQL*Net message from client 98 0 451908 4611.31 56085 4519080888 1421975091 2723168908 6 Idle
6 rows selected.
--//注意看TOTAL_WAITS計數,db file sequential read 增1, SQL*Net message to client, SQL*Net message from client計數增加2.
4.繼續測試:
--//人為產生cbc latch.
--//session 2:
SYS@book> @ bh 4 135
INST_ID HLADDR DBARFIL DBABLK CLASS CLASS_TYPE STATE TCH CR_SCN_BAS CR_SCN_WRP CR_UBA_FIL CR_UBA_BLK CR_UBA_SEQ BA LE_ADDR OBJECT_NAME
---------- ---------------- ---------- ---------- ---------- ------------------ ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------- ---------------- --------------------
1 0000000084D25320 4 135 1 data block xcur 1 0 0 0 0 0 000000006CF8E000 00 DEPT
SYS@book> oradebug setmypid
Statement processed.
SYS@book> oradebug peek 0x0000000084D25320 8
[084D25320, 084D25328) = 00000000 00000000
SYS@book> oradebug poke 0x0000000084D25320 8 0x2000000000000000
BEFORE: [084D25320, 084D25328) = 00000000 00000000
AFTER: [084D25320, 084D25328) = 00000000 20000000
--//session 1:
SCOTT@book> select * from dept where rowid='AAAVRCAAEAAAACHAAA';
--//session 1,取消cbc latch:
SYS@book> oradebug poke 0x0000000084D25320 8 0x0000000000000000
BEFORE: [084D25320, 084D25328) = 00000000 20000000
AFTER: [084D25320, 084D25328) = 00000000 00000000
--//session 2,gdb介面:
2021/02/07 16:58:17.429107633 :kslwtectx 354
2021/02/07 16:58:17.434651886 :kslwtbctx 350`
2021/02/07 16:58:17.439885967 :kslwtectx 350
2021/02/07 16:58:17.445169457 :kslwtbctx 88
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2021/02/07 16:58:29.017377562 :kslwtectx 88
2021/02/07 16:58:29.022706668 :kslwtbctx 354
2021/02/07 16:58:29.028331485 :kslwtectx 354
2021/02/07 16:58:29.033839150 :kslwtbctx 350
2021/02/07 16:58:29.039043786 :kslwtectx 350
2021/02/07 16:58:29.044309059 :kslwtbctx 354
--//session 2:
SYS@book> select * from v$event_name where event# in (354,350,147,88);
EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- -------------------- -------------------- -------------------- ------------- ----------- --------------------
88 2779959231 latch: cache buffers chains address number tries 3875070507 4 Concurrency
147 2652584166 db file sequential read file# block# blocks 1740759767 8 User I/O
350 2067390145 SQL*Net message to client driver id #bytes 2000153315 7 Network
354 1421975091 SQL*Net message from client driver id #bytes 2723168908 6 Idle
--//event# = 88,對應latch: cache buffers chains.
--//v$session_event執行前後對比.
SYS@book> select * from v$session_event where sid=44;
SID EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT MAX_WAIT TIME_WAITED_MICRO EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------------
44 Disk file operations I/O 2 0 666 332.8 666 6655904 166678035 1740759767 8 User I/O
44 latch: cache buffers chains 4 0 13187 3296.72 7166 131868697 2779959231 3875070507 4 Concurrency
44 db file sequential read 90 0 6390 71 6387 63898432 2652584166 1740759767 8 User I/O
44 db file scattered read 1 0 0 0 0 31 506183215 1740759767 8 User I/O
44 SQL*Net message to client 103 0 6496 63.07 2781 64964428 2067390145 2000153315 7 Network
44 SQL*Net message from client 102 0 479279 4698.81 56085 4792789306 1421975091 2723168908 6 Idle
6 rows selected.
SYS@book> select * from v$session_event where sid=44;
SID EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT MAX_WAIT TIME_WAITED_MICRO EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------------
44 Disk file operations I/O 2 0 666 332.8 666 6655904 166678035 1740759767 8 User I/O
44 latch: cache buffers chains 5 0 14344 2868.82 7166 143441219 2779959231 3875070507 4 Concurrency
44 db file sequential read 90 0 6390 71 6387 63898432 2652584166 1740759767 8 User I/O
44 db file scattered read 1 0 0 0 0 31 506183215 1740759767 8 User I/O
44 SQL*Net message to client 105 0 6498 61.88 2781 64975517 2067390145 2000153315 7 Network
44 SQL*Net message from client 104 0 493138 4741.71 56085 4931378816 1421975091 2723168908 6 Idle
6 rows selected.
--//做一個全表掃描:
--//session 2:
SYS@book> alter system flush buffer_cache;
System altered.
--//session 1:
SCOTT@book> select rowid,dept.* from dept;
ROWID DEPTNO DNAME LOC
------------------ ---------- -------------- -------------
AAAVRCAAEAAAACHAAA 10 ACCOUNTING NEW YORK
AAAVRCAAEAAAACHAAB 20 RESEARCH DALLAS
AAAVRCAAEAAAACHAAC 30 SALES CHICAGO
AAAVRCAAEAAAACHAAD 40 OPERATIONS BOSTON
--//session 3:
2021/02/07 17:07:21.308298655 :kslwtectx 354
2021/02/07 17:07:21.314106317 :kslwtbctx 350
2021/02/07 17:07:21.319513842 :kslwtectx 350
2021/02/07 17:07:21.324941069 :kslwtbctx 147
2021/02/07 17:07:21.330333334 :kslwtectx 147
2021/02/07 17:07:21.335758381 :kslwtbctx 148
2021/02/07 17:07:21.341103117 :kslwtectx 148
2021/02/07 17:07:21.346587995 :kslwtbctx 354
2021/02/07 17:07:21.352430245 :kslwtectx 354
2021/02/07 17:07:21.357701504 :kslwtbctx 350
2021/02/07 17:07:21.363057556 :kslwtectx 350
2021/02/07 17:07:21.368542079 :kslwtbctx 354
--//session 2:
SYS@book> select * from v$event_name where event# in (354,350,147,88,148);
EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- -------------------- -------------------- -------------------- ------------- ----------- --------------------
88 2779959231 latch: cache buffers chains address number tries 3875070507 4 Concurrency
147 2652584166 db file sequential read file# block# blocks 1740759767 8 User I/O
148 506183215 db file scattered read file# block# blocks 1740759767 8 User I/O
350 2067390145 SQL*Net message to client driver id #bytes 2000153315 7 Network
354 1421975091 SQL*Net message from client driver id #bytes 2723168908 6 Idle
總結:
--//如何獲得時間戳或者差值,那位知道.找到一個連結感覺也不是很好.
--//gdb指令碼編寫也不是自己的特長,放棄!!
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2756673/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20150520]使用gdb檢視等待事件.txt事件
- Oracle 等待事件V$檢視Oracle事件
- 檢視當前使用者正在等待事件事件
- 檢視等待事件慢在哪個object上事件Object
- 檢視EBS 資料庫等待事件及處理資料庫事件
- 檢視造成等待事件的具體SQL語句事件SQL
- 使用 gdb 檢視 coredump 檔案的 backtrace
- 檢視歷史會話等待事件對應的session資訊會話事件Session
- GDB檢視記憶體(x 命令)記憶體
- 等待事件統計檢視 | 全方位認識 sys 系統庫事件
- 使用treedump事件檢視索引結構事件索引
- GDB為什麼檢視不了原始碼？原始碼
- gdb golang 檢視iface 內部結構Golang
- 用GDB檢視記憶體內容記憶體
- 【等待事件】ORACLE常見等待事件事件Oracle
- 【等待事件】等待事件系列（5.1）--Enqueue(佇列等待)事件ENQ佇列
- 檢視MySQL鎖等待的原因MySql
- 等待事件事件
- 很經典的GDB除錯命令，包括檢視變數，檢視記憶體除錯變數記憶體
- PostgreSQL15-beta1版本系統表、系統檢視、等待事件變化SQL事件
- 【Oracle】 檢查log fie sysnc 等待事件的指令碼Oracle事件指令碼
- 【TUNE_ORACLE】等待事件之等待事件類別Oracle事件
- mysql InnoDB鎖等待的檢視及分析MySql
- Oracle等待檢視v$session_waitOracleSessionAI
- DB2檢視鎖等待的SQLDB2SQL
- 等待事件分析事件
- oracle等待事件Oracle事件
- Oracle 等待事件Oracle事件
- px等待事件事件
- 等待事件 二事件
- 事件檢視器事件ID部分說明事件
- 微信小程式-檢視事件微信小程式事件
- Windows事件檢視器（收集）Windows事件
- w10系統怎麼使用事件檢視器 w10電腦事件檢視器檢查磁碟的方法事件
- 【等待事件】等待事件系列（1）--User I/O型別事件型別
- 【效能調整】等待事件(三) 常見等待事件（一）事件
- 【效能調整】等待事件(四) 常見等待事件（二）事件
- 使用10046事件檢視oracle執行計劃事件Oracle