09 | January | 2012 | Charles Hooper's Oracle Notes

Dumping Trace Events – What You See is Not Necessarily What You Get

9 01 2012

January 9, 2012

A recent thread in the comp.databases.oracle.server Usenet group brought back memories of when Randolf Geist and I worked on the two chapters for the “Expert Oracle Practices” book. In the chapters, among other things, we demonstrated how to enable 10046 trace files for sessions using various approaches (some of the approaches change the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns in V$SESSION to indicate that a 10046 trace is active, and other methods do not), and how to use ORADEBUG to see which events are enabled in other sessions.

The OP in the thread mentioned that the ORADEBUG EVENTDUMP session command, when executed in SQL*Plus by a SYSDBA user, showed no events enabled for another session when the DBMS_MONITOR package was used to enable a 10046 trace at level 12 for the other session. I have a vague memory of reading (somewhere) that the ORADEBUG EVENTDUMP session command will only show newly enabled events for another session after that other session issues another call to the database (parse, execute, fetch, etc.). In the Usenet group thread I stated something that is slightly less complete: “I believe that the session with the trace enabled through DBMS_MONITOR must execute at least one SQL statement after tracing is enabled for the session, before ORADEBUG will report that the trace is enabled.”

In the Usenet thread I put together a quick test case script that demonstrated that after the second session (Session 1) issued a SELECT statement, the first session (Session 2) was able to issue a ORADEBUG EVENTDUMP session command and determine that a 10046 trace at level 12 was enabled for the other session. I believe that the OP answered his own question after a bit of experimentation and searching. I thought that I would provide an extended version of the test case script in case anyone would like to experiment a bit. In this test case, Session 1 will be the target of the tracing – that session must be able to query V$SESSION and V$PROCESS during the script execution, while Session 2 will be connected as the SYS user. In the test case script I have removed the SQL> prompts to make it easier for you to copy and paste the scripts into SQL*Plus, and when the returned output is important, that information also appears in the test case script (all commands executed begin with UPPERCASE keywords).

In Session 1, execute the following SQL statement to pick up the SID, SERIAL# and PID for Session 1, along with the columns in V$SESSION that indicate whether or not a 10046 trace at level 1, 4, 8, or 12 is enabled. The SID and SERIAL# will be used in Session 2 to enable a trace in Session 1, and the PID will be used with ORADEBUG in Session 2:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

As can be determined by the above output, the SID is 4, PID is 24, and a 10046 trace is not enabled for the session (fair warning, the SQL_TRACE column can be misleading).

In Session 2, enable a 10046 trace using the DBMS_MONITOR package for Session 1 at level 12, and dump the events for Session 1 (note that this test case script is being executed on a Windows server with Oracle Database 11.2.0.2):

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>4,SERIAL_NUM=>143,WAITS=>TRUE,BINDS=>TRUE)

ORADEBUG SETORAPID 24

ORADEBUG EVENTDUMP session
Statement processed.

The output of the ORADEBUG EVENTDUMP session command is significant – the Statement processed. note indicates that the statement executed successfully with no return output.

In Session 1, let’s execute the same SQL statement as was executed earlier, to not only confirm that the DBMS_MONITOR.SESSION_TRACE_ENABLE call executed by Session 2 was successful, but also to issue another database call in the session (the significance will be seen later):

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

The above output shows that the DBMS_MONITOR.SESSION_TRACE_ENABLE call was successful, as indicated by the changed values in the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns – a level 12 10046 trace is enabled.

In Session 2, let’s check again which events are enabled for Session 1:

ORADEBUG EVENTDUMP session
sql_trace level=12

Notice in the above output that ORADEBUG now indicates that a 10046 trace at level 12 is enabled for Session 1, because another database call (initiated when the SQL statement was executed) was performed in Session 1 after the trace was enabled.

—

Let’s try a bit more experimentation. In Session 2, let’s disable the trace in Session 1 using the DBMS_MONITOR package, and verify whether or not tracing is enabled in Session 1 by using ORADEBUG:

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>4,SERIAL_NUM=>143)
PL/SQL procedure successfully completed.

ORADEBUG EVENTDUMP session
sql_trace level=12

The above output shows that ORADEBUG still indicates that a 10046 trace at level 12 is enabled for Session 1. In Session 2, let’s check the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns for Session 1:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

ORADEBUG EVENTDUMP session
sql_trace level=12

So, the query of V$SESSION indicates that a 10046 trace for Session 1 is disabled, yet ORADEBUG still insists that a 10046 trace at level 12 is enabled. WYSIWYG (What You See Is What You Get) is taking a bit of a vacation. Let’s issue another database call in Session 1 so that ORADEBUG provides correct output about whether or not a 10046 trace is enabled. In Session 1:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

Let’s confirm in Session 2 that ORADEBUG now reports that a 10046 trace is not enabled in Session 1:

ORADEBUG EVENTDUMP session
Statement processed.

OK, but what happens if we use ORADEBUG in Session 2 to enable a 10046 trace is Session 1? In Session 2:

ORADEBUG session_event 10046 trace name context forever,level 12
Statement processed.

ORADEBUG EVENTDUMP session
sql_trace level=12

The above shows that if ORADEBUG enables a 10046 trace in Session 1, the ORADEBUG EVENTDUMP session command will correctly indicate that a 10046 trace is enabled for Session 1. Nice, but what about the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns in V$SESSION for Session 1? Let’s check using Session 2:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

The above output suggests that a 10046 trace at level 12 is not enabled for Session 1. Let’s check again from within Session 1 and then determine today’s date (if that second SQL statement appears in the 10046 trace file, then we know that the 10046 trace was in fact enabled for Session 1):

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

SELECT SYSDATE FROM DUAL;

SYSDATE
---------
08-JAN-12

The above still suggests that a 10046 trace is not enabled for Session 1 and that today’s date is January 8, 2012. Let’s jump back to Session 2 and disable the 10046 trace using ORADEBUG:

ORADEBUG session_event 10046 trace name context off
Statement processed.

Out of curiosity, let’s repeat a portion of the initial test, just to confirm that the initial test results were not a fluke:

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>4,SERIAL_NUM=>143,WAITS=>TRUE,BINDS=>TRUE)

ORADEBUG EVENTDUMP session
Statement processed.

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

ORADEBUG EVENTDUMP session
Statement processed.

Once again, the above shows that ORADEBUG does not initially report that a 10046 trace is enabled in Session 1 when the officially supported method for enabling a 10046 trace in another session is used. Let’s disable the 10046 trace using the DBMS_MONITOR package and then confirm that ORADEBUG still indicates that a 10046 trace is not enabled in Session 1:

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>4,SERIAL_NUM=>143)

ORADEBUG EVENTDUMP session
Statement processed.

So, what about the unsupported method of enabling a 10046 trace in another session, using SYS.DBMS_SYSTEM.SET_EV? In Session 2:

EXEC SYS.DBMS_SYSTEM.SET_EV(4, 143, 10046, 12, '')

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

ORADEBUG EVENTDUMP session
Statement processed.

The SYS.DBMS_SYSTEM.SET_EV call changed the value of the columns in V$SESSION for Session 1, but still did not alter the output of ORADEBUG EVENTDUMP session.

One final test in Session 2:

ORADEBUG session_event 10046 trace name context forever,level 12
Statement processed.

ORADEBUG EVENTDUMP session
sql_trace level=12

Once again, if we enable the 10046 trace using ORADEBUG, then ORADEBUG is able to show that the trace is enabled for Session 1.

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

At this point you might be curious why I mentioned that the above test case script was performed on a Windows server running Oracle Database 11.2.0.2. Does the Oracle Database version make a difference in the results? Does the operating system (Windows, Linux, or Unix) make a difference in the results? It appears that a part 2 is required for this blog article, where I will compare the above results with the results obtained with 10.2.0.5 on a Windows server and 11.1.0.6 on a Linux server.

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

You are probably curious to see the contents of the trace file for Session 1. Here is the trace file (if you need help in reading the trace file, see this three part article series):

*** 2012-01-08 09:47:51.686
*** SESSION ID:(4.143) 2012-01-08 09:47:51.686
*** CLIENT ID:() 2012-01-08 09:47:51.686
*** SERVICE NAME:(OR1122) 2012-01-08 09:47:51.686
*** MODULE NAME:(SQL*Plus) 2012-01-08 09:47:51.686
*** ACTION NAME:() 2012-01-08 09:47:51.686

Received ORADEBUG command (#1) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:47:51.686
Finished processing ORADEBUG command (#1) 'EVENTDUMP session'

*** 2012-01-08 09:48:18.426
Received ORADEBUG command (#2) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:48:18.426
Finished processing ORADEBUG command (#2) 'EVENTDUMP session'

*** 2012-01-08 09:49:16.415
CLOSE #3:c=0,e=20,dep=0,type=0,tim=488596106412
=====================
PARSING IN CURSOR #2 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596107091 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #2:c=0,e=264,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=488596107088
BINDS #2:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000273.0010.0001
EXEC #2:c=0,e=550,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=3684871272,tim=488596107744
FETCH #2:c=0,e=25,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596107790
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #2:c=0,e=501,dep=1,type=0,tim=488596108309
=====================
PARSING IN CURSOR #5 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596108602 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #5:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596108602
BINDS #5:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000273.0012.0001
EXEC #5:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596108701
FETCH #5:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596108727
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #5:c=0,e=23,dep=1,type=0,tim=488596108766
=====================
PARSING IN CURSOR #3 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596109217 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #3:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596109217
BINDS #3:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000274.0010.0001
EXEC #3:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596109318
FETCH #3:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596109344
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #3:c=0,e=21,dep=1,type=0,tim=488596109385
=====================
PARSING IN CURSOR #4 len=204 dep=0 uid=91 oct=3 lid=91 tim=488596111910 hv=1585533233 ad='7ffb7578ec0' sqlid='dk42yjjg82n9j'
SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR
END OF STMT
PARSE #4:c=0,e=5410,p=0,cr=6,cu=0,mis=1,r=0,dep=0,og=1,plh=1985757361,tim=488596111909
EXEC #4:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=488596112094
WAIT #4: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596112181
FETCH #4:c=0,e=1190,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1985757361,tim=488596113404
WAIT #4: nam='SQL*Net message from client' ela= 232 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596113665
FETCH #4:c=0,e=397,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=488596114102
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=53 card=1)'
STAT #4 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=49 card=1)'
STAT #4 id=3 cnt=810 pid=2 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=346 us cost=0 size=16146 card=598)'
STAT #4 id=4 cnt=30 pid=3 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=494 card=26)'
STAT #4 id=5 cnt=810 pid=3 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=130 us cost=0 size=184 card=23)'
STAT #4 id=6 cnt=27 pid=5 pos=1 obj=0 op='FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=26 us cost=0 size=184 card=23)'
STAT #4 id=7 cnt=1 pid=2 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=22 card=1)'
STAT #4 id=8 cnt=1 pid=7 pos=1 obj=0 op='COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)'
STAT #4 id=9 cnt=1 pid=8 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=0 us cost=0 size=40 card=2)'
STAT #4 id=10 cnt=1 pid=9 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
STAT #4 id=11 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596114237

*** 2012-01-08 09:50:22.069
Received ORADEBUG command (#3) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:50:22.069
Finished processing ORADEBUG command (#3) 'EVENTDUMP session'

*** 2012-01-08 09:51:24.578
Received ORADEBUG command (#4) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:51:24.578
Finished processing ORADEBUG command (#4) 'EVENTDUMP session'

*** 2012-01-08 09:54:05.768
Received ORADEBUG command (#5) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:54:05.768
Finished processing ORADEBUG command (#5) 'EVENTDUMP session'

*** 2012-01-08 09:55:01.068
WAIT #4: nam='SQL*Net message from client' ela= 344636055 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488940750307

*** 2012-01-08 09:55:48.744
Received ORADEBUG command (#6) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:55:48.744
Finished processing ORADEBUG command (#6) 'EVENTDUMP session'

*** 2012-01-08 09:56:50.964
Received ORADEBUG command (#7) 'session_event 10046 trace name context forever,level 12' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 09:56:50.964
Finished processing ORADEBUG command (#7) 'session_event 10046 trace name context forever,level 12'

*** 2012-01-08 09:57:18.634
Received ORADEBUG command (#8) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:57:18.634
Finished processing ORADEBUG command (#8) 'EVENTDUMP session'

*** 2012-01-08 10:00:01.094
WAIT #2: nam='SQL*Net message from client' ela= 300017366 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240770346
CLOSE #2:c=0,e=19,dep=0,type=0,tim=489240770476
=====================
PARSING IN CURSOR #5 len=204 dep=0 uid=91 oct=3 lid=91 tim=489240770687 hv=1585533233 ad='7ffb7578ec0' sqlid='dk42yjjg82n9j'
SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR
END OF STMT
PARSE #5:c=0,e=130,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240770686
EXEC #5:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240770814
WAIT #5: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240770862
FETCH #5:c=0,e=7007,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1985757361,tim=489240777893
WAIT #5: nam='SQL*Net message from client' ela= 192 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240778675
FETCH #5:c=0,e=336,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240779049
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=53 card=1)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=49 card=1)'
STAT #5 id=3 cnt=700 pid=2 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=349 us cost=0 size=16146 card=598)'
STAT #5 id=4 cnt=28 pid=3 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=494 card=26)'
STAT #5 id=5 cnt=700 pid=3 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=81 us cost=0 size=184 card=23)'
STAT #5 id=6 cnt=25 pid=5 pos=1 obj=0 op='FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us cost=0 size=184 card=23)'
STAT #5 id=7 cnt=1 pid=2 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=22 card=1)'
STAT #5 id=8 cnt=1 pid=7 pos=1 obj=0 op='COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)'
STAT #5 id=9 cnt=1 pid=8 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=0 us cost=0 size=40 card=2)'
STAT #5 id=10 cnt=1 pid=9 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
STAT #5 id=11 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240779190

*** 2012-01-08 10:00:49.694
WAIT #5: nam='SQL*Net message from client' ela= 48590415 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289369620
CLOSE #5:c=0,e=16,dep=0,type=0,tim=489289369744
=====================
PARSING IN CURSOR #3 len=24 dep=0 uid=91 oct=3 lid=91 tim=489289370485 hv=124468195 ad='7ffb78cd410' sqlid='c749bc43qqfz3'
SELECT SYSDATE FROM DUAL
END OF STMT
PARSE #3:c=0,e=704,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=489289370484
EXEC #3:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=489289370563
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370620
FETCH #3:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=489289370661
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
WAIT #3: nam='SQL*Net message from client' ela= 189 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370905
FETCH #3:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=489289370957
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370997

*** 2012-01-08 10:09:13.997
Received ORADEBUG command (#9) 'session_event 10046 trace name context off' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 10:09:13.997
Finished processing ORADEBUG command (#9) 'session_event 10046 trace name context off'

*** 2012-01-08 10:11:16.960
Received ORADEBUG command (#10) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:11:16.960
Finished processing ORADEBUG command (#10) 'EVENTDUMP session'

*** 2012-01-08 10:12:42.528
Received ORADEBUG command (#11) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:12:42.528
Finished processing ORADEBUG command (#11) 'EVENTDUMP session'

*** 2012-01-08 10:15:29.621
Received ORADEBUG command (#12) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:15:29.621
Finished processing ORADEBUG command (#12) 'EVENTDUMP session'

*** 2012-01-08 10:19:54.941
Received ORADEBUG command (#13) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:19:54.941
Finished processing ORADEBUG command (#13) 'EVENTDUMP session'

*** 2012-01-08 10:21:25.459
Received ORADEBUG command (#14) 'session_event 10046 trace name context forever,level 12' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 10:21:25.459
Finished processing ORADEBUG command (#14) 'session_event 10046 trace name context forever,level 12'

*** 2012-01-08 10:21:40.549
Received ORADEBUG command (#15) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:21:40.549
Finished processing ORADEBUG command (#15) 'EVENTDUMP session'

Comments : Leave a Comment »

Categories : Performance

	Charles Hooper on Favorite Free Applications to…
	Zach on Favorite Free Applications to…
	Charles Hooper on Favorite Free Applications to…
	Zach on Favorite Free Applications to…
	Charles Hooper on Huge Presentation – Work…
	Dan on Huge Presentation – Work…
	Charles Hooper on Review of Synology DS415+, How…
	Matthias Clausen on Review of Synology DS415+, How…
	Charles Hooper on _SMALL_TABLE_THRESHOLD Paramet…
	mohd atif on _SMALL_TABLE_THRESHOLD Paramet…
	Charles Hooper on Free ANSI SQL to Oracle Specif…
	Kalin Agrawal on Free ANSI SQL to Oracle Specif…
	Charles Hooper on Large Page Support or Not…
	vaurob on Large Page Support or Not…
	Locating Oracle… on Finding a New Home for a Clien…

Charles Hooper's Oracle Notes

Dumping Trace Events – What You See is Not Necessarily What You Get

Categories

Recent Articles

Misc. Articles

Popular Articles

Recent Comments

Blogroll

Hints for Posting Code Sections in Comments