演示使用sql_trace和10046事件对其他会话进行跟踪，并给出trace结果
一、引言
之前在《[转载]---教大家如何玩转跟踪(to owner session、other session)》中说到了使用DBMS_SYSTEM包和ORADEBUG对其他会话进行跟踪，但是演示的示例都是跟踪当前的会话，因此在这里做一个演示，使用它们如何对其他会话进行跟踪。
二、DBMS_SYSTEM
2.1、sql_trace
----在session 1中使用jack用户登录----
1 SQL> conn jack/jack 2 Connected. ----查看一下sid和serial#----
3 SQL> select sid, serial# from v$session where sid = (select sid from v$mystat where rownum=1); 4 5 SID SERIAL# 6 ---------- ---------- 7 36 283 8 ----再查看一下pid和spid，其中可以利用spid找到trace文件----
9 SQL> select pid, spid from v$process p, v$session s where p.addr = s.paddr and s.sid=(select sid from v$mystat where rownum=1); 10 11 PID SPID 12 ---------- ------------- 13 26 6251 14 ----在session 2中使用sys登录----
15 SQL> conn /as sysdba 16 Connected. 17 ----查看一下当前登录到数据库所有用户的sid,serial#,username等信息----
18 SQL> set linesize 150; 19 SQL> select s.sid,s.serial#,s.username,s.osuser 20 2 from v$session s,v$process p 21 3 where s.paddr=p.addr; 22 23 SID SERIAL# USERNAME OSUSER 24 ---------- -------- --------- ------------------
25 2 1 oracle 26 3 1 oracle 27 4 1 oracle 28 5 1 oracle 29 6 1 oracle 30 7 1 oracle 31 8 1 oracle 32 9 1 oracle 33 12 1 oracle 34 10 1 oracle 35 11 1 oracle 36 37 SID SERIAL# USERNAME OSUSER 38 ---------- --------- --------- ---------------- 39 13 1 oracle 40 14 1 oracle 41 15 1 oracle 42 16 1 oracle 43 38 203 SYS oracle 44 18 9 oracle 45 22 2 oracle 46 28 3 oracle 47 24 3 oracle 48 34 31 oracle 49 37 29 oracle 50 51 SID SERIAL# USERNAME OSUSER 52 ---------- -------- ------------ ----------- 53 36 283 JACK oracle ----找了需要跟踪的对象 54 55 23 rows selected. 56 ----我的办法比较笨，从sid入手找到spid，这样就能找到trace文件啦----
57 SQL> select pid, spid from v$process p, v$session s where p.addr = s.paddr and s.sid=36; 58 59 PID SPID 60 ---------- ----------- 61 26 6251 62 ----对session 1进行跟踪设置----
63 SQL> exec dbms_system.set_bool_param_in_session(36,283,'timed_statistics',true); 64 65 PL/SQL procedure successfully completed. 66 67 SQL> exec dbms_system.set_int_param_in_session(36,283,'max_dump_file_size',20000000); 68 69 PL/SQL procedure successfully completed. 70 71 SQL> exec dbms_system.set_sql_trace_in_session(36,283,true); 72 73 PL/SQL procedure successfully completed. 74 ----在session 1中执行一个查询----
75 SQL> select count(*) from jack; 76 77 COUNT(*) 78 ---------- 79 72449 80 ----查看一下当前trace文件的路径，完毕后退出----
81 SQL> select value from v$diag_info where name = 'Default Trace File'; 82 83 VALUE 84 -------------------------------------------------------------------------------- 85 /u01/app/oracle/diag/rdbms/yft/yft/trace/yft_ora_6251.trc 86 87 SQL> exit 88 ----回到session 2中，关闭跟踪，其实在session中已经exit，如果不关闭也得到什么内容----
89 SQL> exec dbms_system.set_sql_trace_in_session(36,283,false); 90 91 PL/SQL procedure successfully completed.
----这是刚才跟踪到的trace文件的部分内容----
1 [oracle@yft ~]$ cat /u01/app/oracle/diag/rdbms/yft/yft/trace/yft_ora_6251.trc 2 Trace file /u01/app/oracle/diag/rdbms/yft/yft/trace/yft_ora_6251.trc 3 Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production 4 With the Partitioning, OLAP, Data Mining and Real Application Testing options 5 ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1 6 System name: Linux 7 Node name: yft 8 Release: 2.6.18-164.el5 9 Version: #1 SMP Tue Aug 18 15:51:54 EDT 2009 10 Machine: i686 11 Instance name: yft 12 Redo thread mounted by this instance: 1 13 Oracle process number: 26 14 Unix process pid: 6251, image: oracle@yft (TNS V1-V3) 15 16 17 *** 2013-02-05 12:09:42.946 18 *** SESSION ID:(36.283) 2013-02-05 12:09:42.946 19 *** CLIENT ID:() 2013-02-05 12:09:42.946 20 *** SERVICE NAME:(SYS$USERS) 2013-02-05 12:09:42.946 21 *** MODULE NAME:(SQL*Plus) 2013-02-05 12:09:42.946 22 *** ACTION NAME:() 2013-02-05 12:09:42.946 23 24 CLOSE #2:c=0,e=172,dep=0,type=1,tim=1360037382921991 25 ===================== 26 PARSING IN CURSOR #3 len=25 dep=0 uid=91 oct=3 lid=91 tim=1360037382946854 hv=2169573763 ad='2e6883cc' sqlid='937fmby0p24c3' 27 select count(*) from jack 28 END OF STMT 29 PARSE #3:c=0,e=281,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1205023501,tim=1360037382946843 30 EXEC #3:c=0,e=152,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1205023501,tim=1360037382947147 31 FETCH #3:c=46993,e=47747,p=0,cr=1037,cu=0,mis=0,r=1,dep=0,og=1,plh=1205023501,tim=1360037382995052 32 STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1037 pr=0 pw=0 time=0 us)' 33 STAT #3 id=2 cnt=72449 pid=1 pos=1 obj=74560 op='TABLE ACCESS FULL JACK (cr=1037 pr=0 pw=0 time=216449 us cost=288 size=0 card=54647)' 34 FETCH #3:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1205023501,tim=1360037382996276 35 36 *** 2013-02-05 12:09:58.447 37 CLOSE #3:c=0,e=94,dep=0,type=1,tim=1360037398447719
2.2、10046事件
----在session 1中使用jack用户登录----
1 SQL> conn jack/jack 2 Connected. 3 SQL> select sid, serial# from v$session where sid = (select sid from v$mystat where rownum=1); 4 5 SID SERIAL# 6 ---------- ---------- 7 38 278 8 9 SQL> select pid, spid from v$process p, v$session s where p.addr = s.paddr and s.sid=(select sid from v$mystat where rownum=1); 10 11 PID SPID 12 ---------- --------- 13 25 6692 14 ----在session 2中使用sys登录----
15 SQL> conn /as sysdba 16 Connected. 17 SQL> set linesize 150; 18 SQL> select sid,serial#,username from v$session where username is not null; 19 20 SID SERIAL# USERNAME 21 ---------- ---------- ------------ 22 33 158 SYS 23 38 278 JACK 24 25 SQL> select pid, spid from v$process p, v$session s where p.addr = s.paddr and s.sid=38; 26 27 PID SPID 28 ---------- --------- 29 25 6692 30 ----使用10046事件跟踪session 1----
31 SQL> exec dbms_system.set_bool_param_in_session(38,278,'timed_statistics',true) 32 33 PL/SQL procedure successfully completed. 34 35 SQL> exec dbms_system.set_int_param_in_session(38,278,'max_dump_file_size',20000000) 36 37 PL/SQL procedure successfully completed. 38 39 SQL> exec dbms_system.set_ev(38,278,10046,12,''); ----在这里要说明一下'',当使用'jack'时发现无法生成trace文件，当''时可以生成文件。 40 41 PL/SQL procedure successfully completed. 42 ----在session 1中先清空buffer_cache,shared_pool----
43 SQL> alter system flush buffer_cache; 44 45 System altered. 46 47 SQL> alter system flush buffer_cache; 48 49 System altered. 50 51 SQL> alter system flush shared_pool; 52 53 System altered. 54 55 SQL> alter system flush shared_pool; 56 57 System altered. 58 59 SQL> variable w number; 60 SQL> exec :w:=1000 61 62 PL/SQL procedure successfully completed. 63 64 SQL> select count(*) from jack where object_id=:w; 65 66 COUNT(*) 67 ---------- 68 1 69 70 SQL> exec :w:=10 71 72 PL/SQL procedure successfully completed. 73 74 SQL> select count(*) from jack where object_id=:w; 75 76 COUNT(*) 77 ---------- 78 1 79 80 SQL> select value from v$diag_info where name = 'Default Trace File'; 81 82 VALUE 83 -------------------------------------------------------------------------------- 84 /u01/app/oracle/diag/rdbms/yft/yft/trace/yft_ora_6692.trc 85 ----关闭10046事件----
86 SQL> exec dbms_system.set_ev(38,278,10046,0,''); 87 88 PL/SQL procedure successfully completed. 89 ----trace文件内容，可以看到有等待事件和绑定变量信息----
90 PARSING IN CURSOR #2 len=22 dep=0 uid=91 oct=47 lid=91 tim=1360044255097438 hv=2136470701 ad='336f8d84' sqlid='3krnzsxzpgx5d' 91 BEGIN :w:=1000; END; 92 END OF STMT 93 PARSE #2:c=4999,e=9685,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1360044255097435 94 BINDS #2: 95 Bind#0 96 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 97 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 98 kxsbbbfp=00a58f04 bln=22 avl=00 flg=05 99 WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1360044255100848 100 EXEC #2:c=4000,e=3401,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1360044255100984 101 102 *** 2013-02-05 14:04:36.808 103 WAIT #2: nam='SQL*Net message from client' ela= 21707623 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1360044276808772 104 CLOSE #2:c=0,e=190,dep=0,type=0,tim=1360044276809209 105 ===================== 106 PARSING IN CURSOR #5 len=44 dep=0 uid=91 oct=3 lid=91 tim=1360044276811465 hv=2817092406 ad='33633780' sqlid='2cmywaamykutq' 107 select count(*) from jack where object_id=:w 108 END OF STMT 109 PARSE #5:c=1999,e=2118,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1360044276811459 110 。。。。。。 111 ===================== 112 PARSING IN CURSOR #2 len=20 dep=0 uid=91 oct=47 lid=91 tim=1360044286576308 hv=1276778704 ad='2e7260c8' sqlid='4nbsfbp61n66h' 113 BEGIN :w:=10; END; 114 END OF STMT 115 PARSE #2:c=999,e=1110,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1360044286576302 116 BINDS #2: 117 Bind#0 118 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 119 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 120 kxsbbbfp=00a34e24 bln=22 avl=02 flg=05 121 value=1000 122 WAIT #2: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=74560 tim=1360044286580498 123 EXEC #2:c=3999,e=3796,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1360044286580562 124 125 *** 2013-02-05 14:04:48.044 126 WAIT #2: nam='SQL*Net message from client' ela= 1463275 driver id=1650815232 #bytes=1 p3=0 obj#=74560 tim=1360044288043981 127 CLOSE #2:c=0,e=53,dep=0,type=0,tim=1360044288051930 128 ===================== 129 PARSING IN CURSOR #4 len=44 dep=0 uid=91 oct=3 lid=91 tim=1360044288052214 hv=2817092406 ad='33633780' sqlid='2cmywaamykutq' 130 select count(*) from jack where object_id=:w 131 END OF STMT 132 PARSE #4:c=0,e=182,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1205023501,tim=1360044288052209 133 BINDS #4: 134 Bind#0 135 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 136 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 137 kxsbbbfp=00a34e24 bln=22 avl=02 flg=05 138 value=10 139 EXEC #4:c=1000,e=318,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1205023501,tim=1360044288052738 140 WAIT #4: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=74560 tim=1360044288052868 141 FETCH #4:c=14998,e=22195,p=0,cr=1037,cu=0,mis=0,r=1,dep=0,og=1,plh=1205023501,tim=1360044288075125 142 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1037 pr=0 pw=0 time=0 us)' 143 STAT #4 id=2 cnt=1 pid=1 pos=1 obj=74560 op='TABLE ACCESS FULL JACK (cr=1037 pr=0 pw=0 time=0 us cost=289 size=156 card=12)' 144 WAIT #4: nam='SQL*Net message from client' ela= 235 driver id=1650815232 #bytes=1 p3=0 obj#=74560 tim=1360044288075549 145 FETCH #4:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1205023501,tim=1360044288075633 146 WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=74560 tim=1360044288075670 147 148 *** 2013-02-05 14:05:11.532 149 WAIT #4: nam='SQL*Net message from client' ela= 23456541 driver id=1650815232 #bytes=1 p3=0 obj#=74560 tim=1360044311532234
三、ORADEBUG
3.1、10046事件
因为在10046事件中level=1等同于SQL_TRACE的功能，所以在这里只演示了Level=12.
----在session 1中使用jack用户登录----
1 SQL> conn jack/jack 2 Connected. 3 SQL> select sid, serial# from v$session where sid = (select sid from v$mystat where rownum=1); 4 5 SID SERIAL# 6 ---------- ---------- 7 39 390 8 9 SQL> select pid, spid from v$process p, v$session s where p.addr = s.paddr and s.sid=(select sid from v$mystat where rownum=1); 10 11 PID SPID 12 ---------- --------- 13 25 6886 14 ----在session 2中使用sys登录----
15 SQL> conn /as sysdba 16 Connected. 17 SQL> set linesize 150; 18 SQL> select sid,serial#,username from v$session where username is not null; 19 20 SID SERIAL# USERNAME 21 ---------- ---------- ------------- 22 33 167 SYS 23 39 390 JACK 24 25 SQL> select pid, spid from v$process p, v$session s where p.addr = s.paddr and s.sid=39; 26 27 PID SPID 28 ---------- -------- 29 25 6886 30 ----指定跟踪SESSION的SPID(OS process)
31 SQL> oradebug setospid 6886 32 Oracle pid: 25, Unix process pid: 6886, image: oracle@yft (TNS V1-V3) 33 SQL> oradebug unlimit 34 Statement processed. 35 SQL> oradebug event 10046 trace name context forever,level 12 36 Statement processed. 37 ----在session 1中进行一些操作----
38 SQL> alter system flush buffer_cache; 39 40 System altered. 41 42 SQL> alter system flush buffer_cache; 43 44 System altered. 45 46 SQL> alter system flush shared_pool; 47 48 System altered. 49 50 SQL> alter system flush shared_pool; 51 52 System altered. 53 54 SQL> exec :i:=50; 55 56 PL/SQL procedure successfully completed. 57 58 SQL> select * from jack where object_id=:i; 59 60 OWNER 61 ------------------------------ 62 OBJECT_NAME 63 -------------------------------------------------------------------------------- 64 SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE 65 ------------------------------ ---------- -------------- ------------------- 66 CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE 67 --------- --------- ------------------- ------- - - - ---------- 68 EDITION_NAME 69 ------------------------------ 70 SYS 71 I_COL3 72 50 50 INDEX 73 74 OWNER 75 ------------------------------ 76 OBJECT_NAME 77 -------------------------------------------------------------------------------- 78 SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE 79 ------------------------------ ---------- -------------- ------------------- 80 CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE 81 --------- --------- ------------------- ------- - - - ---------- 82 EDITION_NAME 83 ------------------------------ 84 13-AUG-09 13-AUG-09 2009-08-13:23:00:54 VALID N N N 4 85 ----关闭10046事件----
86 SQL> oradebug event 10046 trace name context off; 87 Statement processed. 88 SQL> oradebug tracefile_name 89 /u01/app/oracle/diag/rdbms/yft/yft/trace/yft_ora_6886.trc 90 ----trace文件内容----
91 ===================== 92 PARSING IN CURSOR #4 len=20 dep=0 uid=91 oct=47 lid=91 tim=1360047844436331 hv=138812846 ad='335ecfac' sqlid='9n837ms44c7df' 93 BEGIN :i:=50; END; 94 END OF STMT 95 PARSE #4:c=1000,e=1204,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1360047844436326 96 BINDS #4: 97 Bind#0 98 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 99 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 100 kxsbbbfp=012d97a0 bln=22 avl=00 flg=05 101 WAIT #4: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360047844441224 102 EXEC #4:c=4999,e=4775,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1360047844441357 103 104 *** 2013-02-05 15:04:28.017 105 WAIT #4: nam='SQL*Net message from client' ela= 23575295 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360047868016889 106 CLOSE #4:c=0,e=51,dep=0,type=0,tim=1360047868017359 107 ===================== 108 。。。。。。 109 PARSING IN CURSOR #6 len=37 dep=0 uid=91 oct=3 lid=91 tim=1360047868084354 hv=792666545 ad='3351bf14' sqlid='7mvbn4crmy8dj' 110 select * from jack where object_id=:i 111 END OF STMT 112 PARSE #6:c=18997,e=66904,p=10,cr=26,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1360047868084351 113 =====================
最后，在这里有一篇是eygle写的《使用SQL_TRACE进行数据库诊断》的文章：http://www.eygle.com/archives/2004/10/use_sql_trace_to_diagnose_database.html
