Search

Friday, June 24, 2016

What is the correct way to trace a session in Oracle

What is the “correct” or recommended way to trace other sessions in Oracle 11g? I was wondering this lately because over the years I’ve seen a few different methods come up. So, this morning when prepping to trace something as part of a test, I got to thinking – I’d rather do it using the most appropriate method, but what is that? I did just a bit of research on the methods that I’m aware of, and here’s what I think is the way to go. I want to make it clear that this isn’t an “official” statement for Oracle, just what I’ve used and what I believe is what we should be using (if it really matters at all.) First, identify the session you want, in my case it is easy since I’m just mucking around:
SQL> select username, status, sid, serial# from v$session
where username ='PRODSUPT' order by 1;
USERNAME STATUS SID SERIAL#
-------- ------ --- -------
PRODSUPT ACTIVE 3   5023
Note, the serial# will change through this example because I need to logout and back in again, to verify I get a new trace file each time.

oradebug

This goes way back to when I first started in 7.3 or 8.0 (and before?) and I’m not going to cover it since Oracle provides many newer methods.

alter session set events ’10046 trace name context forever,level 12′;

Then I learned the “alter session” command, which works if you’re tracing your own session. In the case of a DBA though, you are often tracing another session, not yourself. This is worth trying out sometime though.

dbms_system.set_sql_trace_in_session(sid, serial#, true);

Next in my memory came the dbms_system procedure. This has been around since I believe 8i or 9i.
exec dbms_system.set_sql_trace_in_session(3,5023,true);
exec dbms_system.set_sql_trace_in_session(3,5023,false);

dbms_support.start_trace_in_session(sid, serial#, waits, binds);

Next I learned about dbms_support, but the catch here is that it isn’t in the database by default. You have to create it first.
SQL> @?/rdbms/admin/dbmssupp.sql
Package created. Package body created.
exec dbms_support.start_trace_in_session(3,5025,true,true);
exec dbms_support.stop_trace_in_session(3,5025);

dbms_monitor.session_trace_enable(session_id, serial_num,binds,waits);

So then comes dbms_monitor, which as best I can tell, is the official way we should be doing this as of 11g (since it is new in 11g). I really don’t know if there’s more to it than the previous methods, but it seems to be the future. I’m guessing the others might be deprecated over time, and this is what we’ll use. Anyone that knows more, please let me know.
SQL> exec dbms_monitor.session_trace_enable(session_id=>3,serial_num=>5027,binds=>true,waits=>true);
PL/SQL procedure successfully completed.
SQL> exec dbms_monitor.session_trace_disable(session_id=>3,serial_num=>5027);
PL/SQL procedure successfully completed.

With that covered

After you’ve done your trace, well – and while you’re doing it, you should be able to find a trace file in your trace directory:
->ll -rt *.trc
-rw-r----- 1 oracle dba 1057 May 24 10:35 T10AC_arc3_9069.trc
-rw-r----- 1 oracle dba 977 May 24 10:39 T10AC_lgwr_8922.trc
-rw-r----- 1 oracle dba 2127 May 24 10:49 T10AC_ora_3029.trc
-rw-r----- 1 oracle dba 65169 May 24 10:50 T10AC_ora_4412.trc
 
And the beginning of the file should look something like this:
Trace file /oracle/product/diag/rdbms/t10ac/T10AC/trace/T10AC_ora_4412.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /oracle/product/11.2.0.2
System name:    Linux
Node name:      ac-tst-db1.cmc.cable.comcast.com
Release:        2.6.18-128.1.1.el5
Version:        #1 SMP Mon Jan 26 13:58:24 EST 2009
Machine:        x86_64
Instance name: T10AC
Redo thread mounted by this instance: 1
Oracle process number: 32
Unix process pid: 4412, image: oracle@ac-tst-db1.cmc.cable.comcast.com (TNS V1)

tkprof

You can now use tkprof to format you trace file into a more readable format. The basic syntax is:
tkprof <source trace file> <output file>
tkprof T10AC_ora_4412.trc T10AC_ora_4412.tkprofs

Tracing and max_dump_file_size

Today I was tracing a poor query. The database had max_dump_file_size set to prevent overwhelming the system with huge trace files. I needed to increase the size to unlimited to so I could get my trace to complete. When you do this
alter session set max_dump_file_size = unlimited;
you have to set it on the session running the query, not the session that you run the trace from.



There are numerous ways to enable, disable and vary the contents of this trace.  The following methods have been available for several versions of the database.

-- All versions.
SQL> ALTER SESSION SET sql_trace=TRUE;
SQL> ALTER SESSION SET sql_trace=FALSE;
SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => TRUE);
SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => FALSE);
SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
SQL> ALTER SESSION SET EVENTS '10046 trace name context off';
SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>TRUE);
SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>FALSE);
SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>8, nm=>' ');
SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>0, nm=>' ');

-- All versions, requires DBMS_SUPPORT package to be loaded.
SQL> EXEC DBMS_SUPPORT.start_trace(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_SUPPORT.stop_trace;
SQL> EXEC DBMS_SUPPORT.start_trace(sid=>123, serial=>1234, waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_SUPPORT.stop_trace(sid=>123, serial=>1234);
The dbms_support package is not present by default, but can be loaded as the SYS user by executing the @$ORACLE_HOME/rdbms/admin/dbmssupp.sql script.
For methods that require tracing levels, the following are valid values:
  • 0 - No trace. Like switching sql_trace off.
  • 2 - The equivalent of regular sql_trace.
  • 4 - The same as 2, but with the addition of bind variable values.
  • 8 - The same as 2, but with the addition of wait events.
  • 12 - The same as 2, but with both bind variable values and wait events.
The same combinations are possible for those methods with boolean parameters for waits and binds.
With the advent of Oracle 10g, the SQL tracing options have been centralized and extended using the dbms_monitor package.  The examples below show a few possible variations for enabling and disabling SQL trace in Oracle 10g.

-- Oracle 10g
SQL> EXEC DBMS_MONITOR.session_trace_enable;
SQL> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable;
SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id=>1234, serial_num=>1234);
SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id =>1234, serial_num=>1234, waits=>TRUE,
binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable(session_id=>1234, serial_num=>1234);
SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall');
SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall', waits=>TRUE,
binds=>FALSE);
SQL> EXEC DBMS_MONITOR.client_id_trace_disable(client_id=>'tim_hall');
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g',
module_name=>'test_api', action_name=>'running');
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g',
module_name=>'test_api', action_name=>'running', waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_disable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');


The package provides the conventional session level tracing along with two new variations.  

First, tracing can be enabled on multiple sessions based on the value of the client_identifier column of the v$session view, set using the dbms_session package. 

Second, tracing can be activated for multiple sessions based on various combinations of the service_name, module, action columns in the v$session view, set using the dbms_application_info package, along with the instance_name in RAC environments.  
With all the possible permutations and default values, this provides a high degree of flexibility.

trcsess
Activating trace on multiple sessions means that trace information is spread throughout many trace files.  For this reason Oracle 10g introduced the trcsess utility, allowing trace information from multiple trace files to be identified and consolidated into a single trace file.  The trcsess usage is listed below.

trcsess [output=<output file name >]  [session=<session ID>] [clientid=<clientid>] [service=<service name>] [action=<action name>] [module=<module name>] <trace file names>
output=<output file name> output destination default being standard output.
session=<session Id> session to be traced.
Session id is a combination of session Index & session serial number e.g. 8.13.
clientid=<clientid> clientid to be traced.
service=<service name> service to be traced.
action=<action name> action to be traced.
module=<module name> module to be traced.
<trace_file_names> Space separated list of trace files with wild card '*' supported.

With all these options, the consolidated trace file can be as broad or as specific as needed.
tkprof


The SQL trace files produced by the methods discussed previously can be read in their raw form, or they can be translated by the tkprof utility into a more human readable form.  The output below lists the usage notes from the tkprof utility in Oracle 10g.

$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
  print=integer    List only the first 'integer' SQL statements.
  aggregate=yes|no
  insert=filename  List SQL statements and data inside INSERT statements.
  sys=no           TKPROF does not list SQL statements run as user SYS.
  record=filename  Record non-recursive statements found in the trace file.
  waits=yes|no     Record summary for any wait events found in the trace file.
  sort=option      Set of zero or more of the following sort options:

    prscnt  number of times parse was called
    prscpu  cpu time parsing
    prsela  elapsed time parsing
    prsdsk  number of disk reads during parse
    prsqry  number of buffers for consistent read during parse
    prscu   number of buffers for current read during parse
     prsmis  number of misses in library cache during parse
    execnt  number of execute was called
    execpu  cpu time spent executing
    exeela  elapsed time executing
    exedsk  number of disk reads during execute
    exeqry  number of buffers for consistent read during execute
    execu   number of buffers for current read during execute
    exerow  number of rows processed during execute
    exemis  number of library cache misses during execute
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    fchela  elapsed time fetching
    fchdsk  number of disk reads during fetch
    fchqry  number of buffers for consistent read during fetch
    fchcu   number of buffers for current read during fetch
    fchrow  number of rows fetched
     userid  userid of user that parsed the cursor 



While I was examining with tkprof, I noticed that there are 2 undocumented parameters (Oracle 11gR2): verbose and diag. Let’s take a look at them.
Verbose: If you set verbose=y, tkprof will provide some extra information on output files. It adds “SQL Text addres(s)” and “SQL Text Hash Value” lines for each query:


It also adds a summary part to the end of the output file:


Diag: This parameter expects you to give a file name. Tkprof can produce internal diagnostics information which seems only meaningful for Tkprof developers. Sample output of a tkprof diagnostic file:

Shell
Sizeof() info:
  kvpfctx:   3008,  kvpfcrs:     368,  kvpfsql:   192
  kvpfvid:    112,  kvpfvxp:      52,  kvpfxpl:    56,  kvpfpln:    56
  kvpfehdr:    24,  kvpfehtbl:   360,  kvpfomn:    32,  kvpfmsg:   312
  kvpfoctname:   808,  kvpfstnames:   256,  kvpfdsb:    56
  kvpfusr:    16  kvpfsql:   104,  kvpfrws:     0
*** SESSION ID:(51.505) 2014-09-22 15:46:41.965
 
cursor: 0,  dep: 0,  seq: 0
prevcur: 0,  prevdep: 0
newcur: 1,  dep: 1,  seq: 1,  type: 1
 
 
cursor: 1,  dep: 1,  seq: 1
prevcur: 0,  prevdep: 0
newcur: 1,  dep: 1,  seq: 2,  type: 3





View the summary at the bottom of the tkprof formatted trace file to assess what was taking up the most time.  For example, the below shows that most of the overall elapsed time was spent on the execution of SQL.  Therefore it would be worthwhile looking at a tkprof formatted trace file which was sorted by exeela (execute elapsed time).  The most expensive queries will then be displayed from top down ordered by how long it took to execute each query. 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse      124      0.60       0.73          7        227          0           0 Execute    125     10.98     105.79      16113     578057      14414        7042 Fetch        2      0.00       0.00          0          5          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ---------- total      251     11.58     106.53      16120     578289      14414        7043
Misses in library cache during parse: 62
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     121        0.00          0.00 
  SQL*Net message from client                   121        0.01          0.23
  library cache lock                            153        0.00          0.02
  library cache pin                              17        0.00          0.00
  row cache lock                                 67        0.00          0.02
  global cache cr request                     12558        0.43          7.43
  db file sequential read                     15394        0.09         87.58
  enqueue                                        22        0.00          0.00
  global cache open x                             6        0.00          0.00
  log file sync                                   5        0.00          0.01
  db file scattered read                         23        0.08          0.56
  global cache s to x                          2557        0.07          0.82
  SQL*Net more data from client                  47        0.00          0.00
  global cache open s                             1        0.00          0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse      296      0.09       0.07          0         39          0           0 Execute  14211      5.66      15.66       1569     946009        276         127 Fetch      953      0.09       0.49         95       2161          3         753
------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    15460      5.84      16.24       1664     948209        279         880
Misses in library cache during parse: 20
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  row cache lock                                 12        0.00          0.00
  global cache cr request                      2815        0.18          0.97 
  db file sequential read                       981        0.10          9.34
  enqueue                                         2        0.00          0.00
  global cache open x                             1        0.00          0.00
  db file scattered read                          2        0.03          0.04
  global cache s to x                             3        0.00          0.00
  global cache open s                             2        0.00          0.00
  db file parallel read                           9        0.07          0.32
If the overall timings are minimal then there would be very little scope for tuning the SQL within the trace thus it would not be worth wasting your time investigating the queries.

Investigating SQL inside a tkprof formatted trace file.

UPDATE c_inrd_ins_redemption inrd
   SET (inrd.c_inrd_input_date,
        inrd.c_inrd_rdm_early_value,
        inrd.c_inrd_exsh_j1
       ) =
       (SELECT ixj.i_xj_file_date,
               DECODE(inrd.c_inrd_rdm_early_value,0,ixj.i_xj_j4_early_value,
                DECODE(ixj.i_xj_j4_early_value,0,inrd.c_inrd_rdm_early_value,
                     ixj.i_xj_j4_early_value)),
               ixj.i_xj_j1_redemption_type
          FROM i_xj_exshare_section_j ixj,
               c_in_instrument ins
         WHERE ixj.i_xj_sedol_num = ins.c_in_sedol
           AND inrd.c_inrd_in_id = ins.c_in_id)
WHERE EXISTS
      (SELECT ins1.c_in_id
         FROM c_in_instrument ins1,
              i_xj_exshare_section_j ixj1
         WHERE ins1.c_in_current_mkr = 'Y'
           AND ixj1.i_xj_rdm_early_date IS NOT NULL
           AND ixj1.i_xj_sedol_num = ins1.c_in_sedol
           AND inrd.c_inrd_rdm_early_date = ixj1.i_xj_rdm_early_date
           AND inrd.c_inrd_in_id = ins1.c_in_id)
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0 Execute      1      7.55      93.15      13807     535656          0           0 Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        2      7.56      93.15      13807     535656          0           0
Column Value
Meaning
PARSE
Translates the SQL statement into an execution plan, including checks for proper security authorization and checks for the existence of tables, columns, and other referenced objects.
EXECUTE
Actual execution of the statement by Oracle. For INSERT, UPDATE, and DELETE statements, this modifies the data. For SELECT statements, this identifies the selected rows.
FETCH
Retrieves rows returned by a query. Fetches are only performed for SELECT statements.
COUNT
Number of times a statement was parsed, executed, or fetched.
CPU
Total CPU time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.
ELAPSED
Total elapsed time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.
DISK
Total number of data blocks physically read from the datafiles on disk for all parse, execute, or fetch calls.
QUERY
Total number of buffers retrieved in consistent mode for all parse, execute, or fetch calls. Usually, buffers are retrieved in consistent mode for queries.
CURRENT
Total number of buffers retrieved in current mode. Buffers are retrieved in current mode for statements such as INSERT, UPDATE, and DELETE.
ROWS
Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement.
Note: Query + Current = Logical Reads (total number of buffers accessed)
Looking at the above example we can see the SQL statement was executed once and took 93.15 seconds to complete.  The query performed 535,656 logical reads of which 13,807 were from disk in order to update 0 rows.  Therefore the query does not look very efficient.
The following part of the trace file shows the explain plan of the query and any wait events that occurred while running the SQL:
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 6055  (INTERFACE)
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE 
      0   FILTER 
 103779    TABLE ACCESS FULL C_INRD_INS_REDEMPTION
      0    NESTED LOOPS 
 103395     TABLE ACCESS BY INDEX ROWID C_IN_INSTRUMENT
 103480      INDEX UNIQUE SCAN C_IN_X_1 (object id 43932)
      0     TABLE ACCESS BY INDEX ROWID I_XJ_EXSHARE_SECTION_J
      0      INDEX UNIQUE SCAN I_XJ_X_1 (object id 1167486)
      0   NESTED LOOPS 
      0    TABLE ACCESS BY INDEX ROWID C_IN_INSTRUMENT
      0     INDEX UNIQUE SCAN C_IN_X_1 (object id 43932)
      0    TABLE ACCESS BY INDEX ROWID I_XJ_EXSHARE_SECTION_J
      0     INDEX UNIQUE SCAN I_XJ_X_1 (object id 1167486)
Rows     Execution Plan
-------  ---------------------------------------------------
      0  UPDATE STATEMENT   GOAL: CHOOSE
      0   UPDATE OF 'C_INRD_INS_REDEMPTION'
      0    FILTER
 103779     TABLE ACCESS   GOAL: ANALYZED (FULL) OF
                'C_INRD_INS_REDEMPTION'
      0     NESTED LOOPS
 103395      TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
                 'C_IN_INSTRUMENT'
 103480       INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF 'C_IN_X_1'
                  (UNIQUE)
      0      TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
                 'I_XJ_EXSHARE_SECTION_J'
      0       INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF 'I_XJ_X_1'
                  (UNIQUE)
      0    NESTED LOOPS
      0     TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
                'C_IN_INSTRUMENT'
      0      INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF 'C_IN_X_1' (UNIQUE)
      0     TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
                'I_XJ_EXSHARE_SECTION_J'
      0      INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF 'I_XJ_X_1' (UNIQUE)
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  global cache cr request                     10959        0.43          6.86
  db file scattered read                         19        0.06          0.41
  db file sequential read                     13311        0.09         79.68
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00  
The above example shows that of the 93.15 seconds it took to execute the query 79.68 seconds were spent reading from disk (db file sequential read).  The Rows column in the explain section gives you a clue where most of the work is being performed.
The above query was actually tuned by rewriting the UPDATE as a MERGE INTO statement.  As the below shows this greatly reduced the amount of logical reads that were required:
MERGE into c_inrd_ins_redemption col1
USING (select inrd.rowid,
              ixj.i_xj_file_date a,
              DECODE(inrd.c_inrd_rdm_early_value,
                     0,
                     ixj.i_xj_j4_early_value,
                     DECODE(ixj.i_xj_j4_early_value,
                            0,
                            inrd.c_inrd_rdm_early_value,
                            ixj.i_xj_j4_early_value)) b,
              ixj.i_xj_j1_redemption_type c
         FROM c_inrd_ins_redemption  inrd,
              i_xj_exshare_section_j ixj,
              c_in_instrument        ins
        WHERE ixj.i_xj_sedol_num = ins.c_in_sedol
          AND inrd.c_inrd_in_id = ins.c_in_id
          AND ins.c_in_current_mkr = 'Y'
          AND ixj.i_xj_rdm_early_date IS NOT NULL
          AND inrd.c_inrd_rdm_early_date = ixj.i_xj_rdm_early_date) t1
ON (col1.rowid = t1.rowid)
WHEN matched then
  update
     set col1.c_inrd_input_date      = t1.a,
         col1.c_inrd_rdm_early_value = t1.b,
         col1.c_inrd_exsh_j1         = t1.c
WHEN not matched then
  insert (c_inrd_exsh_j1) values (null)
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.01       0.01          0          0          0           0 Execute      1      0.00       0.00          0          3          0           0 Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        2      0.01       0.01          0          3          0           0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 6055  (INTERFACE)
Rows     Row Source Operation
-------  ---------------------------------------------------
      2  MERGE 
      0   VIEW 
      0    NESTED LOOPS OUTER
      0     NESTED LOOPS 
      0      NESTED LOOPS 
      0       TABLE ACCESS FULL I_XJ_EXSHARE_SECTION_J
      0       TABLE ACCESS BY INDEX ROWID C_IN_INSTRUMENT
      0        INDEX RANGE SCAN C_IN_X_2 (object id 43935)
      0      TABLE ACCESS BY INDEX ROWID C_INRD_INS_REDEMPTION
      0       INDEX UNIQUE SCAN C_INRD_X_1 (object id 42684)
      0     TABLE ACCESS BY USER ROWID C_INRD_INS_REDEMPTION
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
Note: The WHEN NOT MATCHED condition would never be met so just contains a dummy insert.

 

Row Source Operations in tkprof formatted trace files

Row source operations provide the number of rows processed for each operation executed on the rows and additional row source information, such as physical reads and writes. The following is a sample:
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  DELETE  (cr=43141 r=266947 w=25854 time=60235565 us)
  28144   HASH JOIN ANTI (cr=43057 r=262332 w=25854 time=48830056 us)
  51427    TABLE ACCESS FULL STATS$SQLTEXT (cr=3465 r=3463 w=0 time=865083 us)
 647529    INDEX FAST FULL SCAN STATS$SQL_SUMMARY_PK
                      (cr=39592 r=39325 w=0 time=10522877 us) (object id 7409)
In this sample TKPROF output, note the following under the Row Source Operation column:
cr specifies consistent reads performed by the row source
r specifies physical reads performed by the row source
w specifies physical writes performed by the row source time specifies time in microseconds
Row source operations only appear in trace files if the relevant cursor was closed before the tracing ended.  Therefore if you want to capture Row Source Operations make sure the relevant session being traced is closed cleanly before ending tracing and formatting the file using tkprof.

Posted by at
Subscribe to: Posts (Atom)