10046 Event Trace Session SQL

Background knowledge:

10046 events can be divided into 4 levels according to the content of the collected information:

Level 1: function equivalent to Sql_trace

Level 4: Increase the collection of binding variable information on the basis of 1

Level 8: Add information on the wait event on the basis of 1

Level 12: Equivalent to Level 4+level 8, which collects binding variable information and waits for event information at the same time.

One: Track current session SQL

1. SYS user authorization to perform tracking Dblink user
Sql> Grant alter session to Dblink;

Grant succeeded.

2. Return to Dblink user action
Sql> Show user;
USER is "DBLINK"

3. Query sid,serial#
Sql> Select sid,serial# from v$session where username= ' DBLINK ';

SID serial#
---------- ----------
45 14

4. Query the trace file of the current user
Sql> SELECT * from v$diag_info where name like ' default% ';

inst_id NAME
---------- ----------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
1 Default Trace File
/home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_2823.trc

5. Start 10046 Events
Sql> alter session SET events ' 10046 Trace name Context forever, Level 12 ';

Session altered.

6. Execute test SQL (SQL to be traced)
Sql> variable a number; #含有绷定变量的sql
Sql> exec:a:=2;
PL/SQL procedure successfully completed.

Sql> Select COUNT (*) from dba_objects where object_id=:a;

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

7. Closing 10046 Events
Sql> alter session SET events ' 10046 Trace name context off ';

Session altered.

8.1 Viewing trace files after original 10046 Note: The trace file content of the 10046 event is the result of SQL execution in chronological order

[Email protected] ~]$ VI/HOME/ORACLE/APP/DIAG/RDBMS/ORCL/ORCL/TRACE/ORCL_ORA_2823.TRC

Trace FILE/HOME/ORACLE/APP/DIAG/RDBMS/ORCL/ORCL/TRACE/ORCL_ORA_2823.TRC
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0-64bit Production
With the partitioning, OLAP, Data Mining and Real application testing options
Oracle_home =/home/oracle/app/oracle/product/11.2.0/dbhome_1
System Name:linux
Node name:11g
Release:2.6.32-573.el6.x86_64
Version: #1 SMP Thu Jul 15:44:03 UTC 2015
Machine:x86_64
Instance NAME:ORCL
Redo thread mounted by this instance:1
Oracle Process number:32
Unix process pid:2823, Image: [email protected] (TNS v1-v3)

2014-11-19 04:42:30.941
SESSION ID: (45.14) 2014-11-19 04:42:30.941
CLIENT ID: () 2014-11-19 04:42:30.941
SERVICE NAME: (sys$users) 2014-11-19 04:42:30.941
MODULE NAME: (sql*plus) 2014-11-19 04:42:30.941
ACTION NAME: () 2014-11-19 04:42:30.941

WAIT #2: nam= ' sql*net message to client ' Ela= 2 driver id=1650815232 #bytes =1 p3=0 obj#=-1 tim=1416390150940558

2014-11-19 04:44:47.004
WAIT #2: nam= ' sql*net message from client ' ela= 136063164 driver id=1650815232 #bytes =1 p3=0 obj#=-1 tim=1416390287004294
CLOSE #2: c=0,e=3,dep=0,type=3,tim=1416390287004441
=====================
Parsing in CURSOR #5 len=19 dep=0 uid=90 oct=47 lid=90 tim=1416390287005001 hv=3805855218 ad= ' 87972f88 ' sqlid= ' 1w9223jdjgg K
begin:a:=2; END;
END of STMT
PARSE #5: c=0,e=467,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1416390287005001
Binds #5:
Bind#0
Oacdty=02 mxl=22 () mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
Kxsbbbfp=7fd108695a28 bln=22 avl=00 flg=05
WAIT #5: nam= ' sql*net message to client ' Ela= 2 driver id=1650815232 #bytes =1 p3=0 obj#=-1 tim=1416390287006240
EXEC #5: c=1999,e=1191,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1416390287006261

2014-11-19 04:56:00.212
WAIT #5: nam= ' sql*net message from client ' ela= 673206425 driver id=1650815232 #bytes =1 p3=0 obj#=-1 tim=1416390960212735
CLOSE #5: c=0,e=49,dep=0,type=0,tim=1416390960212948
=====================
Parsing in CURSOR #1 len=51 dep=0 uid=90 oct=3 lid=90 tim=1416390960213839 hv=3085049059 ad= ' 87973410 ' sqlid= ' 214vxnyvy477 3 '
Select COUNT (*) from dba_objects where object_id=:a
END of STMT
PARSE #1: c=1000,e=844,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1416390960213838
=====================
Parsing in CURSOR #6 len=37 dep=1 uid=0 oct=3 lid=0 tim=1416390960214450 hv=1398610540 ad= ' 9a8c2c00 ' sqlid= ' GRWYDZ59PU6MC '
Select text from view$ where rowid=:1
END of STMT
PARSE #6: c=1000,e=408,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=1416390960214449
=====================
Parsing in CURSOR #2 len=210 dep=2 uid=0 oct=3 lid=0 tim=1416390960215089 hv=864012087 ad= ' 8a7b0300 ' sqlid= ' 96g93hntrzjtr '
Select/*+ Rule */bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, Minimum, maximum, distcnt, Lowval, H Ival, density, col#, Spare1, Spare2, Avgcln from hist_head$ where Obj#=:1 and Intcol#=:2
END of STMT
PARSE #2: c=0,e=292,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=3,plh=0,tim=1416390960215089
Binds #2:
Bind#0
Oacdty=02 mxl=22 () mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
Kxsbbbfp=7fd108751d48 bln=22 avl=02 flg=05
value=69
Bind#1
Oacdty=02 mxl=22 () mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
Kxsbbbfp=7fd108751d18 bln=24 avl=03 flg=05
value=1001
EXEC #2: c=1000,e=9315,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=3,plh=2239883476,tim=1416390960224458
FETCH #2: c=0,e=28,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1416390960224573
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=424 op= ' TABLE ACCESS by INDEX ROWID hist_head$ (cr=2 pr=0 pw=0 time=0 us) '
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=426 op= ' INDEX RANGE SCAN i_hh_obj#_intcol# (cr=2 pr=0 pw=0 time=0 us) '
CLOSE #2: c=0,e=2,dep=2,type=3,tim=1416390960224765
=====================
Parsing in CURSOR #5 len=210 dep=2 uid=0 oct=3 lid=0 tim=1416390960224900 hv=864012087 ad= ' 8a7b0300 ' sqlid= ' 96g93hntrzjtr '
Select/*+ Rule */bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, Minimum, maximum, distcnt, Lowval, H Ival, density, col#, Spare1, Spare2, Avgcln from hist_head$ where Obj#=:1 and Intcol#=:2
END of STMT
Binds #5:
Bind#0
Oacdty=02 mxl=22 () mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
Kxsbbbfp=7fd108751d48 bln=22 avl=02 flg=05
value=69
Bind#1
Oacdty=02 mxl=22 () mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
Kxsbbbfp=7fd108751d18 bln=24 avl=02 flg=05
Value=8
EXEC #5: c=0,e=132,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1416390960225016
FETCH #5: c=0,e=12,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1416390960225045
CLOSE #5: c=0,e=1,dep=2,type=3,tim=1416390960225068
Binds #6:
Bind#0
oacdty=11 mxl=16 (mxlc=00) mal=00 scl=00 pre=00
Oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
kxsbbbfp=7fd1086aa078 bln=16 avl=16 flg=05

。。。。。 Omit large amounts of output

"~/app/diag/rdbms/orcl/orcl/trace/orcl_ora_2823.trc" 148L, 8943C

8.2 Using the Tkprof tool to view 10046-time trace files
[Email protected] ~]$ TKPROF/HOME/ORACLE/APP/DIAG/RDBMS/ORCL/ORCL/TRACE/ORCL_ORA_2823.TRC andy.txt sys=no

Tkprof:release 11.2.0.1.0-development on Wed Nov 19 05:00:35 2014

Copyright (c) 1982, the Oracle and/or its affiliates. All rights reserved.

[Email protected] ~]$ VI andy.txt

From
Dba_objects where object_id=:a

Call count CPU Elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 5 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Total 4 0.01 0.00 0 5 0 1

Misses in library cache during parse:1
Misses in library cache during execute:1
Optimizer mode:all_rows
Parsing user id:90

Rows Row Source Operation # Execution plan
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=5 pr=0 pw=0 time=0 US)
1 VIEW dba_objects (cr=5 pr=0 pw=0 time=0 US cost=5 size=26 card=2)
1 Union-all (cr=5 pr=0 pw=0 time=0 US)
1 FILTER (cr=5 pr=0 pw=0 time=0 US)
1 NESTED LOOPS (cr=5 pr=0 pw=0 time=0 US cost=5 size=71 card=1)
1 NESTED LOOPS (cr=4 pr=0 pw=0 time=0 US cost=4 size=67 card=1)
1 TABLE ACCESS by INDEX ROWID obj$ (cr=3 pr=0 pw=0 time=0 US cost=3 size=45 card=1)
1 INDEX RANGE SCAN i_obj1 (cr=2 pr=0 pw=0 time=0 US cost=2 size=0 card=1) (object ID 36)
1 INDEX RANGE SCAN i_user2 (cr=1 pr=0 pw=0 time=0 US cost=1 size=22 card=1) (Object ID 47)
1 INDEX RANGE SCAN i_user2 (cr=1 pr=0 pw=0 time=0 US cost=1 size=4 card=1) (Object ID 47)
0 TABLE ACCESS by INDEX ROWID ind$ (cr=0 pr=0 pw=0 time=0 US cost=2 size=8 card=1)
0 INDEX UNIQUE SCAN i_ind1 (cr=0 pr=0 pw=0 time=0 US cost=1 size=0 card=1) (object ID 41)
0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 US cost=2 size=29 card=1)
0 INDEX Full SCAN i_user2 (cr=0 pr=0 pw=0 time=0 US cost=1 size=20 card=1) (Object ID 47)
0 INDEX RANGE SCAN i_obj4 (cr=0 pr=0 pw=0 time=0 US cost=1 size=9 card=1) (Object ID 39)

————————————————————————————————————————————————————

Second: track the specified session (specific steps in the above section, abbreviated here)

Start trace with 10046 event Trace
sql> exec dbms_monitor.session_trace_enable (45,14,waits=>true,binds=>true)

PL/SQL procedure successfully completed.

Close Trace
sql> exec dbms_monitor.session_trace_disable (45,14);

PL/SQL procedure successfully completed.

OK, end. Reprint please indicate the source.

10046 Event Trace Session SQL