Oracle Session Tracing Part VI

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


*** TRACE DUMP CONTINUED FROM FILE ***
Dump file c:oracleadminlagerudumplager_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:PINEHORSEFINE-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]
[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 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 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 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

James Koopmann
James Koopmann
James Koopmann has fourteen years of database design, development and performance tuning experience. In addition, he has extensive database administration experience in Oracle and other relational databases in production environments, specializing in performance tuning of database engines and SQL based applications. Koopmann is an accomplished author with several technical papers in various Oracle related publications such as Oracle Magazine, Oracle Professional and SQL>UPDATE_RMOUG. He is a featured author and database expert for DatabaseJournal, a member of the editorial review committee for Select Journal (The Magazine for the International Oracle Users Group), an Oracle Certified Professional DBA and noted speaker at local Oracle User Groups around the country.

Latest Articles