Oracle Session Tracing Part VI

Thursday Feb 3rd 2005 by James Koopmann

Part six of this series discribes how to access and generate reports off of the trace files we generated in Part five, through the use of the TKPROF and trcsess utilities.

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 that were generated were in a raw format that does not allow 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 . These are typically stored in the $ORACLE_BASE/SID/udump directory of the database server. Listing 1 gives the top end of a trace file that 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. In addition, I have explicitly defined each of these client variables through my application. If they were not set, 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 of the trace files generated by a particular user, in a particular module, or performing a certain type of task.

Listing 1
Top part of a trace file

Dump file c:\oracle\admin\lager\udump\lager_ora_2100_jfk.trc
Tue Jan 25 09:48:56 2005
ORACLE V10. - Production vsnsta=0
vsnsql=13 vsnxtr=3
Oracle Database 10g Enterprise Edition Release - 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 of the information together for analysis. The trcsess utility is a java app that is 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 your 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 of the trace files for all of the individual times an application or user accessed the database without this utility. In addition, if we set ACTION_NAME and MODULE_NAME properly, it gives us the ability to pick the statistics generated around a certain application or statement type across trace files, out of that trace file.

In addition, 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]

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 criterion 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 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 presents 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 - 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
 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)



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


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 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.

» See All Articles by Columnist James Koopmann

Mobile Site | Full Site