Oracle Session Tracing Part VI

 

Author   : James F. Koopmann

More at  : www.jameskoopmann.com

 

 

Part VI in our series will show you how to access and generate reports off of the trace files we generated in Part V through the use of the TKPROF and trcsess utilities.

 

In the last part of this series we re-visited methods on how to generate trace files. These trace files generated were in a raw format that doesn’t allow for us to read them very easily. This article will be the last in this series and will show how to take these generated trace files and produce reports in a more readable form.

What does a trace file look like

In Part IV of this series we discussed how to find where your trace files are generated but are typically stored in the $ORACLE_BASE/SID/udump directory of the database server. Listing 1 gives the top end of a trace file I generated so that you could get a flavor if you have never seen a trace file before. Through out this series we have zeroed in on setting and monitoring the SESSION_ID, CLIENT_IDENTIFIER, SERVICE_NAME, MODULE_NAME, and ACTION_NAME environment variables. At the bottom of this abbreviated trace file listing (Listing 1) you can see exactly how Oracle now stores this in each and every trace file. Note that you can change these environment variables throughout an application and these output lines may be scattered throughout a trace file. Also, I have explicitly defined each of these client variables so as to show them here but if you were not to have set them you would end up with an empty string for those variables. If we were to set these variables religiously, you can see how easy it is to issue a Unix GREP command or Windows FIND command to give you all the trace files generated by a particular user, was in a particular module, or was performing a certain type of task.

 

Listing 1

Top part of a trace file

*** TRACE DUMP CONTINUED FROM FILE  ***

Dump file c:\oracle\admin\lager\udump\lager_ora_2100_jfk.trc

Tue Jan 25 09:48:56 2005

ORACLE V10.1.0.2.0 - Production vsnsta=0

vsnsql=13 vsnxtr=3

Oracle Database 10g Enterprise Edition Release 10.1.0.2.0 - Production

With the Partitioning, OLAP and Data Mining options

Windows 2000 Version V5.0 Service Pack 4

CPU             : 1 - type 586

Process Affinity: 0x00000000

Memory (A/P)    : PH:19M/509M, PG:633M/1247M, VA:1752M/2047M

Instance name: lager

 

Redo thread mounted by this instance: 1

 

Oracle process number: 19

 

Windows thread id: 2100, image: ORACLE.EXE (SHAD)

 

 

*** 2005-01-25 09:48:56.875

*** ACTION NAME:(ADD) 2005-01-25 09:48:56.859

*** MODULE NAME:(EMP_MAINT) 2005-01-25 09:48:56.859

*** SERVICE NAME:(SYS$USERS) 2005-01-25 09:48:56.859

*** CLIENT ID:( James?F.?Koopmann:PINEHORSE\FINE-ALE) 2005-01-25 09:48:56.859

*** SESSION ID:(148.12) 2005-01-25 09:48:56.859

 

 

What is the trcsess Utility

After you have determined which trace files include the particular combinations of  SID, CLIENT_IDENTIFIER, SERVICE_NAME, ACTION_NAM, or MODULE_NAME variables you need to be able to pull all the information together for analysis. The trcsess utility is a java app that gets executed through the command line of your O/S and will consolidate trace information in multiple trace files for the information across these SID, CLIENT_IDENTIFIER, SERVICE_NAME, ACTION_NAME, and MODULE_NAME variables. Not to worry about invoking java, Oracle has provided a shell script for you particular operating system that can be executed instead. The output of the trcsess utility is a single file that can be the input into the TKPROF reporting utility. This is of great importance for finding true bottlenecks or an application that is consuming large amounts of resources. It would be nearly impossible to tally all the trace files for all the individual times an application or user accessed the database without this utility. Also it gives us the ability to pick out of a trace file, if we set ACTION_NAME and MODULE_NAME properly, the statistics generated around a certain application or statement types across trace files. Also if you are in a connection polling environment where the user’s session is never the same, this utility gives you the ability to zero in and pick out that user easily from all the trace files generated during the performance tuning time slice you are interested in and giving you a true look into the user’s session. Listing 2 gives the syntax for the new trcsess utility and a simple example.

Listing 2

Syntax & Example for trcsess

trcsess [output   = output_file_name]
        [session  = session_Id]
        [clientid = client_Id]
        [service  = service_name]
        [action   = action_name]
        [module   = module_name]
        [trace_files]

 

Example: Consolidate all trace files for everyone that has been                        in the Employee Maintenance Module (EMP_MAINT).

SQL > trcsess output=emp_maint.trc module=EMP_MAINT *.trc

What Can TKPROF Do

Up to this point we have just generated trace files and consolidated trace files based on a search criteria through the trcsess utility. As stated before, you can edit these trace files and read them by hand but they do tend to be cryptic. Oracle has provides us with a reporting mechanism on these trace files in the form of the TKPROF utility. This utility provides for the following mechanisms. Listing 3 also gives the syntax and example on running the TKPROF utility.

  1. Formats all the cryptic information in a more readable form that is understandable for you and me.
  2. Breaks out each statement executed during the trace period and present various statistics that enable us to determine where bottlenecks lay and where we might spend our time tuning application code.
  3. Can generate a SQL script that allows us to store the captured statistics into a database.
  4. Will determine the explain plan for executed SQL statements.
  5. Provides for summary as well as detail information for collected statistics

 

 

 

Listing 3

Syntax & Example for TKPROF

tkprof trace_file report_file

       [waits     = yes|no] 

       [sort      = option]

       [print     = n]

       [aggregate = yes|no]

       [insert    = filename3]

       [sys       = yes|no]

       [table     = schema.table]

       [explain   = user/password]

       [record    = filename4]

       [width     = n]

 
Example: Produce report for all users within the Employee 
         Maintenance Module (EMP_MAINT).
 
SQL > tkprof emp_maint.trc emp_maint.rpt
 
Sample Output:
TKPROF: Release 10.1.0.2.0 - Production on Tue Jan 25 10:34:27 2005
 
Copyright (c) 1982, 2004, Oracle.  All rights reserved.
 
Trace file: emp_maint.trc
Sort options: default
 
***************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
***************************************************************************
UPDATE emp SET salary = 350000
WHERE
 empid = 101
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.04          0          1          0           0
Execute      2      0.00       0.01          0         14          6           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.05          0         15          6           2
 
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 77
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  (cr=7 pr=0 pw=0 time=350 us)
      1   TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=160 us)
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        9      0.04       0.06          0          2          0           0
Execute     11      0.01       0.04          0         21          8           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       20      0.06       0.11          0         23          8           3
 
Misses in library cache during parse: 6
Misses in library cache during execute: 2
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0         14          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.01       0.01          0         14          0           2
 
Misses in library cache during parse: 2
 
   13  user  SQL statements in session.
    0  internal SQL statements in session.
   13  SQL statements in session.
********************************************************************************
Trace file: emp_maint.trc
Trace file compatibility: 10.01.00
Sort options: default
 
       0  session in tracefile.
      13  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
      13  SQL statements in trace file.
      10  unique SQL statements in trace file.
     102  lines in trace file.
     816  elapsed seconds in trace file.

Tracing Enhancements

The world of tracing Oracle sessions has changed drastically with Oracle 10g. Not so much as the mechanisms but in the way we can initiate a trace for one session or a group of sessions. We are now able to “tag” sessions as they are connected to Oracle and move through applications. We can now accurately pinpoint where in the application a session is, the amount of resources being consumed, and more importantly if the session is having difficulty and is in need of tuning. This is extremely important in a multi-tier environment where connection polling takes place and we would be lost if it where not for these new tracing features.