event事件的花样玩法

无意中看到Tanel Poder大佬的文章What Caused This Wait Event: Using Oracle’s wait_event[] tracing，原来events事件还可以这么玩，挺有意思。测试一下。

一、等待事件中附加操作

SQL> ALTER SESSION SET EVENTS 'wait_event["log file sync"] crash()';

Session altered.

SQL> create table t as select * from dba_objects;
ERROR:
ORA-03113: end-of-file on communication channel
Process ID: 21598
Session ID: 19 Serial number: 32872

二、等待事件中追踪call stack

SQL> alter session set events '10046 trace name context forever,level 12';

Session altered.

SQL> ALTER SESSION SET EVENTS 'wait_event["db file sequential read"] trace("stack is: %\n", shortstack())';

Session altered.

SQL> select count(*) from t;

  COUNT(*)
----------
     72398

SQL> alter session set events '10046 trace name context off';

Session altered.

tarce日志

stack is: ksfd_io<-ksfdread<-kcfrbd1<-kcbzib<-kcbgtcr<-ktrget2<-kdst_fetch0<-kdstf000100100001000kmP<-kdsttgr<-qertbFetch<-qerstFetch<-qergsFetch<-qerstFetch<-opifch2<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkedsamp<-kkedsSel<-kkecdn<
WAIT #139961280769560: nam='db file sequential read' ela= 79 file#=1 block#=115628 blocks=1 obj#=73254 tim=13956740704
stack is: ksfd_io<-ksfdread<-kcfrbd1<-kcbzib<-kcbgtcr<-ktrget2<-kdst_fetch0<-kdstf000100100001000kmP<-kdsttgr<-qertbFetch<-qerstFetch<-qergsFetch<-qerstFetch<-opifch2<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkedsamp<-kkedsSel<-kkecdn<
WAIT #139961280769560: nam='db file scattered read' ela= 67 file#=1 block#=115642 blocks=6 obj#=73254 tim=13956818796
WAIT #139961280769560: nam='db file scattered read' ela= 22 file#=1 block#=115747 blocks=8 obj#=73254 tim=13956819916
WAIT #139961280769560: nam='db file scattered read' ela= 18 file#=1 block#=115758 blocks=8 obj#=73254 tim=13956821310
WAIT #139961280769560: nam='db file scattered read' ela= 18 file#=1 block#=115794 blocks=8 obj#=73254 tim=13956822505
WAIT #139961280769560: nam='db file sequential read' ela= 70 file#=1 block#=115816 blocks=1 obj#=73254 tim=13956838142
stack is: ksfd_io<-ksfdread<-kcfrbd1<-kcbzib<-kcbgtcr<-ktrget2<-kdst_fetch0<-kdstf000100100001000kmP<-kdsttgr<-qertbFetch<-qerstFetch<-qergsFetch<-qerstFetch<-opifch2<-opiall0<-opikpr<-opiodr<-rpidrus<-skgmstack<-rpidru<-rpiswu2<-kprball<-kkedsamp<-kkedsSel<-kkecdn<
WAIT #139961280769560: nam='db file scattered read' ela= 31 file#=1 block#=115845 blocks=8 obj#=73254 tim=13956916138
WAIT #139961280769560: nam='db file scattered read' ela= 18 file#=1 block#=115865 blocks=8 obj#=73254 tim=13956917385

追踪除了调用堆栈

三、等待事件转储

SQL> ALTER SESSION SET EVENTS 'wait_event["PL/SQL lock timer"] errorstack(1)';

Session altered.

SQL> alter session set events '10046 trace name context forever,level 12';

Session altered.

SQL> exec p;

PL/SQL procedure successfully completed.

SQL> alter session set events '10046 trace name context off';

Session altered.

tarce 日志

WAIT #139912614064928: nam='PL/SQL lock timer' ela= 1046843 duration=0 p2=0 p3=0 obj#=-1 tim=14942985752

*** 2023-02-28T22:52:29.741112+08:00 (CDB$ROOT(1))
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=1, mask=0x0)
----- Error Stack Dump -----
<error barrier> at 0x7fff2bdf7160 placed dbkda.c@296
----- Current SQL Statement for this session (sql_id=0g33y61cdq54y) -----
BEGIN p; END;
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x6faf9780       215  package body SYS.DBMS_LOCK.SLEEP
0x70de76f8         4  procedure SYS.P
0x69723430         1  anonymous block

----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst1()+95         call     kgdsdst()            7FFF2BDF65C0 000000002
                                                   7FFF2BDF08F0 ? 7FFF2BDF0A08 ?
                                                   000000000 000000082 ?
ksedst()+58          call     ksedst1()            000000000 000000001
                                                   7FFF2BDF08F0 ? 7FFF2BDF0A08 ?
                                                   000000000 ? 000000082 ?
dbkedDefDump()+2308  call     ksedst()             000000000 000000001 ?
0                                                  7FFF2BDF08F0 ? 7FFF2BDF0A08 ?
                                                   000000000 ? 000000082 ?
ksedmp()+577         call     dbkedDefDump()       000000001 000000000
                                                   7FFF2BDF08F0 ? 7FFF2BDF0A08 ?
                                                   000000000 ? 000000082 ?
dbkdaKsdActDriver()  call     ksedmp()             000000001 000000000 ?
+2484                                              7FFF2BDF08F0 ? 7FFF2BDF0A08 ?

四、跟踪所有等待事件

SQL> ALTER SESSION SET EVENTS 'wait_event[all] trace(''event="%" ela=% p1=% p2=% p3=%\n'',evargs(5), evargn(1), evargn(2), evargn(3), evargn(4))';

Session altered.

SQL> alter session set events '10046 trace name context forever,level 12';

Session altered.

SQL> select count(1) from t;

  COUNT(1)
----------
     72398

SQL> alter session set events '10046 trace name context off';

Session altered.

trace日志

event="Disk file operations I/O" ela=39 p1=8 p2=0 p3=8
event="SQL*Net message to client" ela=2 p1=1650815232 p2=1 p3=0

*** 2023-02-28T22:56:38.932973+08:00 (CDB$ROOT(1))
event="SQL*Net message from client" ela=31742740 p1=1650815232 p2=1 p3=0
event="PGA memory operation" ela=31 p1=65536 p2=2 p3=0
WAIT #140025824823600: nam='Disk file operations I/O' ela= 30 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=15192178573
event="Disk file operations I/O" ela=30 p1=8 p2=0 p3=8
WAIT #140025824823600: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15192178813
event="SQL*Net message to client" ela=2 p1=1650815232 p2=1 p3=0

*** 2023-02-28T22:56:51.837186+08:00 (CDB$ROOT(1))
WAIT #140025824823600: nam='SQL*Net message from client' ela= 12903261 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15205082097
event="SQL*Net message from client" ela=12903261 p1=1650815232 p2=1 p3=0