I. How To Run SQL*Trace and Format
the Trace File
The following document explains how to run SQL*Trace, and how to format
the trace file that is created. This document can also be found in GSX
by querying on the key words ‘trace’, ‘applications’ and ‘tkprof’.
SQL*Trace is a database tool analysts or customers can use to debug
certain problems in Oracle Applications. SQL*Trace creates a file containing
all SQL statements, and statistics for each statement executed during a
user’s session. This file can later be reviewed to determine:
· What SQL statements were executed.
· How long and how much CPU time did each
script take
· How the database was accessed by each statement
(Explain option)
SQL*Trace is especially useful for performance issues. Oracle developers WILL ask for 'trace output' for performance problems in order to find out exactly what the process is doing at the database level.
SQL*Trace may also help identify the SQL script that is causing other
problems such as:
· A process suddenly terminates with an ORA error.
· Quickpick is not returning an expected value.
· Query in a form is not returning an expected
value.
SQL*Trace for form level processes can be turned on from the application menu. For processes run by the concurrent manager, such as executables and Oracle Reports, SQL*Trace must be turned on at the database level.
NOTE: It is possible to run SQL*Trace on an Oracle Report without shutting down the database; however, it requires modification of the report. Another bulletin is available which explains how to do this, query the problem repository on ‘r20conv’ and ‘trace’.
Running SQL*Trace at the Database Level
Following are the steps to turn SQL*Trace on at the database level.
NOTE: This process should be performed by your database administrator,
if you have one.
1. Edit your INIT.ORA or CONFIG.ORA (Server Administration Guide, Appendix
A )
- This file resides under $ORACLE_HOME/dbs
- The INIT.ORA is read when the database is
started.
- The following INIT.ORA parameters must be
set:
SQL_TRACE =
TRUE
USER_DUMP_DEST
= <preferred directory for the trace output>
TIMED_STATISTICS
= TRUE
MAX_DUMP_FILE_SIZE
= <optional, determines trace output file size>
2. Shutdown Concurrent Manager and Database.
- Shutdown the concurrent manager first. Then
shut down the database.
- Make sure that no users are on the system.
3. Restart the Database and the Concurrent Manager.
4. Run the process.
SUGGESTION: Do not have other users on the
system while trace is on. Only run the
process in question. This will make finding the problem much easier.
5. Check the USER_DUMP_DEST directory for the trace output.
NOTE: An easy way of determining the directory
a trace file is written to is to run the
following SQL:
Select value from v$parameter where name = 'user_dump_dest';
6. Find the trace file for your process.
- If there are multiple trace files use the creation
date to help determine which file is yours.
In UNIX, use 'ls -lrt'.
- If there are multiple files for the same session,
they may all be relevant.
- The file names will be *.trc.
7. Shutdown and restart the database with the original INIT.ORA.
Using TKPROF to Format the Trace
File
The trace file that is created contains statistics on how long each
SQL script took, but this information needs to be formatted to be readable.
Use tkprof on the trace file to format it into readable performance statistics.
Tkprof also formats the SQL scripts making them easier to read.
Before running tkprof on the trace file:
- Make sure the table plan_table exists.
- If not, find the command to create the table from
the Server Application Developer's
Guide, page B-11.
TKPROF Format:
tkprof tracefile outputfile [explain= ] [table=
] [print= ] [insert= ] [sys= ] [sort= ]
Examples:
1. tkprof ora_11598.trc
myfilename
2. tkprof ora_11598.trc
/tmp/myfilename
3. tkprof ora_11598.trc
/tmp/myfilename explain=apps/apps
4. tkprof ora_23532.trc
myfilename explain=apps/apps sort=execpu
NOTES:
· In order to create the tkprof file, you must have write
access in the directory where you are
creating the file. If you do not have write access
in the trace directory, then specify a directory
where you do have write access. The /tmp directory
is a possible directory to use since users
should have write access to this directory. Example
#2 shows how to do this.
· The values listed in [ ] are optional; however, explain
should always be used if the issue is a
performance problem. Explain should be followed
by the userid/passwd of the product that
SQL*Trace was executed from. See Example #3.
· For more information, type <tkprof> and hit return
at the operating system prompt. This will
return an explanation on the usage of tkprof,
as well as the optional parameters.
· Example #4 shows how to sort the SQL scripts in order
of the CPU time spent executing. This
will list the SQL scripts that use the most CPU
time at the top of the file. This is useful for
identifying performance problems in large trace
files.
Setting Up Form Level Trace
Following are the steps to set up SQL*Trace from your application menu.
This is used to turn SQL*Trace on while in a form. (It is not necessary
to shut down the database when running SQL*Trace from a form).
1. Go to the Application Developer responsibility.
2. Navigate to the Define Menu form. This will vary slightly with Application
version.
3. Query the Menu for which you would like to add Trace. (This
is typically added to the
menu OTHER.)
4. Add the following entry in the Menu Entries zone.
Prompt Description
Type Application
Name Arguments
Trace
SQL Trace Menu Appl. Object Library
TRACE
5. Commit.
II. A Detailed Look at the Contents of a Trace File
What Does a Trace File Look Like?
Following are examples of select statements from a trace that
has been reformatted using tkprof.
********************************************************************************
select sum(extended_amount)
from
ra_customer_trx_lines where customer_trx_id = :1 and line_type
= 'FREIGHT'
call count
cpu elapsed disk
query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1
0.10 0.20
0
0
0
0
Execute 1 0.00
0.05 0
0
0
0
Fetch 1
0.00 0.20
0
6
0
1
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2
0.10 0.45
0
6
0
1
Misses in library cache during parse: 0
Optimizer hint: RULE
Parsing user id: 108
********************************************************************************
SELECT AML.MEMO_LINE_ID, AL.MEANING "Type", AML.NAME "Name", AML.DESCRIPTION
"Description", DECODE(AML.LINE_TYPE, 'TAX', 0, 'FREIGHT', 0,
AML.UNIT_STD_PRICE / NVL(:A00, 1)), DECODE(:A01, NULL,
ROUND((AML.UNIT_STD_PRICE / NVL(:A02, 1)), :A03), ROUND((AML.UNIT_STD_PRICE
/ NVL(:A04, 1)) / :A05) * :A06 ), AML.LINE_TYPE, AML.TAX_CODE
FROM
AR_MEMO_LINES AML, AR_LOOKUPS AL WHERE(AL.LOOKUP_TYPE = 'STD_LINE_TYPE'
AND
AL.LOOKUP_CODE = AML.LINE_TYPE ) AND ( AML.DESCRIPTION
= :KEYCOL) ORDER
BY AL.MEANING, AML.NAME
call count cpu
elapsed disk query
current rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 0
0.00 0.00
0 0
0 0
Execute 1 0.00
0.00 0
0 0
1
Fetch 1
0.00 0.00
0 4
3 0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 2
0.00 0.00
0 4
3 1
Misses in library cache during parse: 0
Optimizer hint: RULE
Parsing user id: 108
********************************************************************************
What do the Statistics Mean?
The statistics listed after each SQL statement are explained at the
top of the tkprof’d trace file.
For example:
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
The values that you will primarily use are cpu and elapsed.
What Does the Explain Parameter
Do?
By including the explain parameter, tkprof will create an explain plan
for each SQL statement.
Following is an excerpt from the document Oracle7 Server Application
Developer’s Guide, Appendix B, which defines explain.
"The EXPLAIN PLAN command displays the execution plan chosen by the ORACLE optimizer for SELECT, UPDATE, INSERT, and DELETE statements. A statement’s execution plan in the sequence of operations the ORACLE performs to execute the statement. By examining the execution plan, you can see exactly how ORACLE executes your SQL statement. This information can help you determine whether the SQL statement you have written takes advantage of the indexes available’
Following is an example of an explain plan for a SQL statement.
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT
HINT: RULE
0 MERGE JOIN
0 NESTED
LOOPS
0
TABLE ACCESS HINT: ANALYZED (BY ROWID) OF 'RA_ADDRESSES'
0
INDEX HINT: ANALYZED (UNIQUE SCAN) OF 'RA_ADDRESSES_U1' (UNIQUE)
0
TABLE ACCESS HINT: ANALYZED (BY ROWID) OF 'FND_TERRITORIES'
0
INDEX (UNIQUE SCAN) OF 'FND_TERRITORIES_U1' (UNIQUE)
0
FIRST ROW
0 VIEW
0 TABLE ACCESS
HINT: ANALYZED (FULL) OF 'RA_REMIT_TOS'
This shows how the SQL statement was processed by the database. Development will use this information to determine if the SQL statement is being processed efficiently. For more information on EXPLAIN read Appendix B in Oracle7 Server Application Developer’s Guide.
What are Bind Variables?
Any value preceded by a ‘:’ or a ‘&’ is a bind variable. SQL*Forms
and C executables use the ‘:’ to indicate bind variables and Oracle Reports
uses the ‘&’. The values for bind variables will vary with each execution
of the code based on the values populated by the code. Usually it is not
necessary to know the bind variable’s value in order to resolve the problem.
However, if you need to find the actual bind value, then look at the code
to see how the value is populated.
Following is an example of how to find the value that was passed for
the bind variable in the following SQL statement from a trace file.
NOTE: This is just one example of how a bind variable is populated
and does not cover all
situations.
select sum(extended_amount)
from
ra_customer_trx_lines where customer_trx_id = :1 and line_type
= 'FREIGHT'
The first SQL script above has the bind variable ‘:1’. Do the
following to find the value that was
used for this bind variable.
1. Open the code that contains
the script in a text editor (In this example, a forms .inp file).
2. Search the text for the
select statement in question.
3. When you find the appropriate
select, it will tell you the block and field used to get the
value for the bind variable (:block.field).
For example, the first select above looks like the following in the
.inp file.
SELECT SUM(EXTENDED_AMOUNT)
INTO HEADER_DISPLAY.FREIGHT_AMOUNT
FROM RA_CUSTOMER_TRX_LINES
WHERE CUSTOMER_TRX_ID = :HEADER.CUSTOMER_TRX_ID
AND LINE_TYPE = ‘FREIGHT’
c. You can then use
EXAMINE in the application to query the Block ‘HEADER’, and the
field ‘CUSTOMER_TRX_ID’ to find the value that was populated.
1. Pull up the form and the record used to create the trace file.
2. Get into Examine. (Examine is a debug utility that has to be added to
your menu.
Talk to a senior analyst if you are not familiar with Examine)
3. Quickpick in Block and
select the block specified (HEADER)
4. Quickpick in Field and select the field specified (CUSTOMER_TRX_ID)
5. The Value field will show the value used in the trace file.
III. Examples of How to Use SQL*Trace
to Debug a Problem
Following are a couple of examples of how you might use SQL*Trace to
resolve an issue.
The examples are taken from actual tars where trace was used to resolve
the problem.
A. Expected record is not returned
when executing a query in a form.
Situation: Customer is querying in the invoice lines zone of the Enter
Invoice form and not finding invoice lines that they expect to be there.
Resolution steps:
a. Query the invoice in question and turn trace on before executing
the query in the lines
zone.
b. Run tkprof on the trace file and find the select that is querying
the invoice lines.
SELECT LINE_NUMBER,DESCRIPTION,UNIT_SELLING_PRICE,CUSTOMER_TRX_ID,
INVENTORY_ITEM_ID,LAST_UPDATED_BY,LAST_UPDATE_DATE,CREATED_BY,CREATION_DATE,
LAST_UPDATE_LOGIN,QUANTITY_INVOICED,QUANTITY_CREDITED,SET_OF_BOOKS_ID,
UNIT_STANDARD_PRICE,ATTRIBUTE_CATEGORY,ATTRIBUTE1,ATTRIBUTE2,ATTRIBUTE3,
ATTRIBUTE4,ATTRIBUTE5,ATTRIBUTE6,ATTRIBUTE7,ATTRIBUTE8,ATTRIBUTE9,
ATTRIBUTE10,INTERFACE_LINE_CONTEXT,INTERFACE_LINE_ATTRIBUTE1,
INTERFACE_LINE_ATTRIBUTE2,INTERFACE_LINE_ATTRIBUTE3,TAX_EXEMPT_FLAG,
INTERFACE_LINE_ATTRIBUTE4,INTERFACE_LINE_ATTRIBUTE5,
INTERFACE_LINE_ATTRIBUTE6,INTERFACE_LINE_ATTRIBUTE7,
INTERFACE_LINE_ATTRIBUTE8,DEFAULT_USSGL_TRANSACTION_CODE,
INTERFACE_LINE_ATTRIBUTE9,INTERFACE_LINE_ATTRIBUTE10,
INTERFACE_LINE_ATTRIBUTE11,INTERFACE_LINE_ATTRIBUTE12,
INTERFACE_LINE_ATTRIBUTE13,INTERFACE_LINE_ATTRIBUTE14,
INTERFACE_LINE_ATTRIBUTE15,INITIAL_CUSTOMER_TRX_LINE_ID,
DEFAULT_USSGL_TRX_CODE_CONTEXT,AUTORULE_COMPLETE_FLAG,
PROGRAM_APPLICATION_ID,PROGRAM_ID,PROGRAM_UPDATE_DATE,REVENUE_AMOUNT,
UOM_CODE,ATTRIBUTE11,ATTRIBUTE12,ATTRIBUTE13,ATTRIBUTE14,ATTRIBUTE15,
REQUEST_ID,LINE_TYPE,EXTENDED_AMOUNT,MEMO_LINE_ID,CUSTOMER_TRX_LINE_ID,
TAX_EXEMPT_REASON_CODE, TAX_EXEMPT_NUMBER, AUTORULE_DURATION_PROCESSED,
ROWID
FROM
RA_CUSTOMER_TRX_LINES WHERE customer_trx_id=:1 and line_type
in ('LINE',
'CB', 'CHARGES') and CUSTOMER_TRX_ID = '11735' and SET_OF_BOOKS_ID
= '2'
order by line_number
c. Find out why the SQL is not returning any rows. All of the values
in the SELECT are not
needed to do this. For example, modify the above
SQL statement and remove all of the
SELECT values except for CUSTOMER_TRX_ID.
This will make things easier to
investigate.
SELECT CUSTOMER_TRX_ID
FROM
RA_CUSTOMER_TRX_LINES WHERE customer_trx_id=:1 and line_type
in ('LINE',
'CB', 'CHARGES') and CUSTOMER_TRX_ID = '11735' and SET_OF_BOOKS_ID='2'
d. Find the values for the bind variables and insert them into the script.
SELECT CUSTOMER_TRX_ID
FROM RA_CUSTOMER_TRX_LINES
WHERE customer_trx_id=11735
and line_type in ('LINE', 'CB', 'CHARGES')
and CUSTOMER_TRX_ID = '11735'
and SET_OF_BOOKS_ID = '2'
e. Run the modified SQL script in SQL*Plus. It should return 0 rows.
f. The question at this point is which line(s) of the SQL script are
causing 0 lines to be returned?
Use your best judgment as to which lines are the
problem and remove them from the script.
Do this until the script returns a value.
HINT: Avoid removing join lines, as this will cause
a ‘cartesian product’ (which is a SQL
script that will take a very long time to run because there is no join
between tables)
In the case above, the following line was removed:
and line_type in ('LINE',
'CB', 'CHARGES')
The script then returned 3 rows! So this is the
line that is the problem.
g. Then determine why this line is causing the problem for the
record in question.
What value is the script returning to exclude
itself?
One method of research is to find out
what value the record DOES have for the problem
column. For example, run the following
script to identify what value the record is returning
for line_type.
Select line_type
from ra_customer_trx_lines
where customer_trx_id = ‘11735’;
In this example, the script returned
3 lines
LINE_TYPE
---------------
FREIGHT
TAX
Notice that the line between FREIGHT
and TAX is null? This is why this line is not selected
and it is not showing up in the form!
h. The next step is to determine why this value is null?
In this example, the TRM states that this column
was supposed to be a NOT NULL column.
The analyst discussed this with the customer and
found that they had made this a NULL
column during the upgrade. Customer was informed
that they need to populate this column
with the correct value and make the column NOT NULL.
B. Expected value not found in quickpick
Situation: Customer defined some items, but the items do not show up
in a quickpick when
entering a Purchase Order.
Resolution:
a. Turn on SQL*Trace before executing the quickpick on the item field.
b. Examine the trace file and find that the SQL statement being used
for the quickpick.
SELECT
MTL_SYSTEM_ITEMS.SEGMENT10 C0, MTL_SYSTEM_ITEMS.SEGMENT11
C1,
DESCRIPTION DESCRIPTION
FROM
MTL_SYSTEM_TIMES
WHERE
MTL_SYSTEM_TIMES.ENABLED_FLAG = ‘Y’
AND TO_DATE(:A00,’J’) BETWEEN
NVL(MTL_SYSTEM_TIMES.START_DATE_ACTIVE, TO_DATE(:A01, ‘J’))
AND NVL(MTL_SYSTEM_TIMES.END_DATE_ACTIVE, TO_DATE(:A02, ‘J’))
AND MTL_SYSTEM_TIMES.ORGANIZATION_ID = :A03
AND PURCHASING_ENABLED_FLAG = ‘Y’
AND NVL(OUTSIDE_OPERATION_FLAG, ‘N’) = ‘N’
ORDER BY MTL_SYSTEM_TIMES.SEGMENT10, MTL_SYSTEM_TIMES.SEGMENT11
c. Determine why a value is not appearing in the quickpick by
changing the SQL
statement to SELECT the values in the WHERE/AND
statements for one of the items in
question.
For Example:
SELECT
ENABLED_FLAG, START_DATE_ACTIVE, END_DATE_ACTIVE,
ORGANIZATION_ID, PURCHASING_ENABLED_FLAG,
OUTSIDE_OPERATION_FLAG
FROM
MTL_SYSTEM_ITEMS
WHERE INVENTORY_ITEM_ID = 3345
d. Then compare the values the SQL statement returns to the values that
are expected by the
quickpick statement. What value is different?
In this example, the above SQL script identified
that the
PURCHASING_ENABLED_FLAG = ‘N’ for the item. The
script used for the quickpick is
looking for values where PURCHASING_ENABLED_FLAG=’Y’.
This is why it did not
show up in the quickpick.