A trace file is a log of SQL run in a particular session or sessions focused on selects, inserts, updates, and deletes. A trace file can be used in many circumstances including reviewing performance, finding tables and views referenced, or finding the root of an error. More details about trace files can be read in the database user's guide related to your version.
-- Example #1: ORA-Error
The following is an snippet from a trace file that had an Oracle standard error. In this case it is a unique constraint violation, ORA 1 unique constraint.
See the line: ERROR #117:err=1 tim=1443801753. The ERROR flags the line and the 'err=1' lists the Oracle error as ORA-1:
=====================
PARSING IN CURSOR #117 len=1828 dep=1 uid=173 oct=2 lid=173 tim=1203661932011076 hv=1015075934 ad='cc60a820'INSERT INTO BOM_SUB_OPERATION_RESOURCES (OPERATION_SEQUENCE_ID, SUBSTITUTE_GROUP_NUM, RESOURCE_ID, SCHEDULE_SEQ_NUM, REPLACEMENT_GROUP_NUM, ACTIVITY_ID, STANDARD_RATE_FLAG, ASSIGNED_UNITS, USAGE_RATE_OR_AMOUNT, USAGE_RATE_OR_AMOUNT_INVERSE, BASIS_TYPE, SCHEDULE_FLAG, LAST_UPDATE_DATE, LAST_UPDATED_BY, CREATION_DATE, CREATED_BY, LAST_UPDATE_LOGIN, RESOURCE_OFFSET_PERCENT, AUTOCHARGE_TYPE, ATTRIBUTE_CATEGORY, REQUEST_ID, PROGRAM_APPLICATION_ID, PROGRAM_ID, PROGRAM_UPDATE_DATE, ATTRIBUTE1, ATTRIBUTE2, ATTRIBUTE3, ATTRIBUTE4, ATTRIBUTE5, ATTRIBUTE6, ATTRIBUTE7, ATTRIBUTE8, ATTRIBUTE9, ATTRIBUTE10, ATTRIBUTE11, ATTRIBUTE12, ATTRIBUTE13, ATTRIBUTE14, ATTRIBUTE15, PRINCIPLE_FLAG, SETUP_ID, CHANGE_NOTICE, ACD_TYPE, ORIGINAL_SYSTEM_REFERENCE ) SELECT DISTINCT A.OPERATION_SEQUENCE_ID, B.SUBSTITUTE_GROUP_NUM, D.RESOURCE_ID, B.SCHEDULE_SEQ_NUM, B.REPLACEMENT_GROUP_NUM, B.ACTIVITY_ID, B.STANDARD_RATE_FLAG, B.ASSIGNED_UNITS, B.USAGE_RATE_OR_AMOUNT, B.USAGE_RATE_OR_AMOUNT_INVERSE, B.BASIS_TYPE, B.SCHEDULE_FLAG, SYSDATE, :B4 , SYSDATE, :B4 , NULL, B.RESOURCE_OFFSET_PERCENT, B.AUTOCHARGE_TYPE, B.ATTRIBUTE_CATEGORY, FND_GLOBAL.CONC_REQUEST_ID, NULL, FND_GLOBAL.CONC_PROGRAM_ID, SYSDATE, B.ATTRIBUTE1, B.ATTRIBUTE2, B.ATTRIBUTE3, B.ATTRIBUTE4, B.ATTRIBUTE5, B.ATTRIBUTE6, B.ATTRIBUTE7, B.ATTRIBUTE8, B.ATTRIBUTE9, B.ATTRIBUTE10, B.ATTRIBUTE11, B.ATTRIBUTE12, B.ATTRIBUTE13, B.ATTRIBUTE14, B.ATTRIBUTE15, B.PRINCIPLE_FLAG, B.SETUP_ID, DECODE (:B2 , 1, B.CHANGE_NOTICE, :B3 ), DECODE (:B2 , 1, B.ACD_TYPE, 1), B.ORIGINAL_SYSTEM_REFERENCE FROM BOM_OPERATION_RESOURCES A, BOM_SUB_OPERATION_RESOURCES B, BOM_RESOURCES C, BOM_RESOURCES D WHERE A.LAST_UPDATED_BY = B.OPERATION_SEQUENCE_ID AND B.RESOURCE_ID = C.RESOURCE_ID AND C.RESOURCE_CODE = D.RESOURCE_CODE AND D.ORGANIZATION_ID = :B1 AND NVL (D.DISABLE_DATE, SYSDATE + 1) > SYSDATEEND OF STMTEXEC
#117:c=2099681,e=2436776,p=315,cr=5416,cu=19,mis=0,r=0,dep=1,og=1,tim=1203661932011073ERROR #117:err=1 tim=1443801753
=====================
-- Example #2: Rollback
Another common thing to look for in trace files are rollbacks. There are several formats that you might see for a rollback including the word 'rollback' or text like 'XCTEND rlbk=1, rd_only=1'.
=====================
PARSING IN CURSOR #118 len=30 dep=1 uid=173 oct=45 lid=173 tim=1203661932011639 hv=4099445834 ad='0'ROLLBACK TO BEGIN_ROUTING_COPYEND OF STMTEXEC #118:c=0,e=124,p=0,cr=0,cu=21,mis=0,r=0,dep=1,og=0,tim=1203661932011637RPC EXEC:c=2105681,e=2524801BINDS #116:=====================
2. What are bind variables?
A bind variable is a substitution value used within a trace file. To improve performance, the Oracle database will reuse SQL substituting values for variables as necessary. For example, the same SQL statement could be run for each of your employees. The employee id might be a variable that is changed before you run each SQL. This could be translated to the database as a bind variable so that the same SQL can be used each time but the correct variable can be substituted just before the SQL is run. If someone requests that you enable bind variables for your trace file, this causes the database to document the substitution variables within the trace file as well as the SQL run. For example, we may see that a select statement ran against the employee table ten times, but without the binds, we would not know what employee was selected each time.
-- Example #1: Binds
Here is an example of a trace file with binds. In this example, we see a query against a table called MTL_SYSTEM_ITEMS_VL. Bind variables are used in the where-clause to substitute for the following
":num", ":SEGMENT1", and ":FND_FLEX_WHERE_BIND_0".
=====================
PARSING IN CURSOR #78 len=785 dep=0 uid=173 oct=3 lid=173 tim=1203661928858323 hv=3885565797 ad='d16ab6f8'SELECT ENABLED_FLAG, SUMMARY_FLAG, NVL(TO_CHAR(START_DATE_ACTIVE, 'J'), 0),NVL(TO_CHAR(END_DATE_ACTIVE, 'J'), 0),SEGMENT1, DESCRIPTION, PRIMARY_UOM_CODE, LOCATION_CONTROL_CODE, RESTRICT_LOCATORS_CODE, RESTRICT_SUBINVENTORIES_CODE, INVENTORY_ASSET_FLAG, product_family_item_id, BOM_ITEM_TYPE, SERIAL_NUMBER_CONTROL_CODE, INVENTORY_ITEM_ID FROM MTL_SYSTEM_ITEMS_VL WHERE ORGANIZATION_ID = :num AND SEGMENT1 = :SEGMENT1 AND ( bom_enabled_flag = 'Y' And bom_item_type <> 3 And pick_components_flag = 'N' And eng_item_flag = 'N' And not exists (Select null From bom_operational_routings bor Where bor.assembly_item_id = inventory_item_id And bor.organization_id = :FND_FLEX_WHERE_BIND_0 And bor.alternate_routing_designator is null And bor.routing_type <> 1) And eam_item_type IS NULL ) END OF STMTEXEC #78:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1203661928858320FETCH #78:c=0,e=76,p=0,cr=10,cu=0,mis=0,r=1,dep=0,og=1,tim=1203661928858425BINDS #78:kkscoacd Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=01 fl2=1000000 frm=00 csi=00 siz=2056 off=0 kxsbbbfp=2a9cff79f0 bln=22 avl=03 flg=05 value=101 Bind#1 oacdty=01 mxl=32(15) mxlc=00 mal=00 scl=00 pre=00 oacflg=01 fl2=1000000 frm=01 csi=873 siz=0 off=24 kxsbbbfp=2a9cff7a08 bln=32 avl=09 flg=01 value="MRS6814MC" Bind#2 oacdty=01 mxl=2000(255) mxlc=00 mal=00 scl=00 pre=00 oacflg=01 fl2=1000000 frm=01 csi=873 siz=0 off=56 kxsbbbfp=2a9cff7a28 bln=2000 avl=03 flg=01 value="101"EXEC #78:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1203661928859390FETCH #78:c=0,e=36,p=0,cr=10,cu=0,mis=0,r=1,dep=0,og=1,tim=1203661928859438
=====================
-- Example #2: Binds
Here is another example where you see the bind numbers. This is more common. Note that the binds are off by one -- bind#0 goes with the variable :b1, bind#1 goes with variable :b2, etc.
=====================
PARSING IN CURSOR #128 len=863 dep=0 uid=173 oct=6 lid=173 tim=1203661928862922 hv=1516422370 ad='d1d91940'UPDATE BOM_OPERATIONAL_ROUTINGS SET ROUTING_SEQUENCE_ID = :b1,ASSEMBLY_ITEM_ID = :b2,ORGANIZATION_ID = :b3,ALTERNATE_ROUTING_DESIGNATOR = :b4,LAST_UPDATE_DATE = :b5,LAST_UPDATED_BY = :b6,LAST_UPDATE_LOGIN = :b7 WHERE ROWID = :b8 END OF STMTPARSE #128:c=0,e=442,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1203661928862919BINDS #128:kkscoacd Bind#0 oacdty=02 mxl=23(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=2200 off=0 kxsbbbfp=2a9cff7cd8 bln=23 avl=04 flg=05 value=30020 Bind#1 oacdty=02 mxl=23(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24 kxsbbbfp=2a9cff7cf0 bln=23 avl=04 flg=01 value=13003 Bind#2 oacdty=02 mxl=23(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=48 kxsbbbfp=2a9cff7d08 bln=23 avl=03 flg=01 value=101 Bind#3 oacdty=01 mxl=2000(255) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=72 kxsbbbfp=2a9cff7d20 bln=2000 avl=00 flg=01 Bind#4 oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2072 kxsbbbfp=2a9cff84f0 bln=07 avl=07 flg=01 value="1/21/2009 8:56:55" Bind#5 oacdty=02 mxl=23(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2080 kxsbbbfp=2a9cff84f8 bln=23 avl=03 flg=01 value=1555 Bind#6 oacdty=02 mxl=23(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2104 kxsbbbfp=2a9cff8510 bln=23 avl=04 flg=01 value=370867 Bind#7 oacdty=01 mxl=32(18) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=2168 kxsbbbfp=2a9cfef550 bln=32 avl=18 flg=01 value="AABDb6AAiAAAGBqAA3"
=====================
3. How does one enable trace in the Oracle Application screens / forms?
One can enable trace through the forms by using the Help menu, choosing the daignostics menu, trace and then selecting the appropriate trace for your needs. Most commonly if debugging an error, you should at least provide trace with binds. When debugging a performance issue, you may consider using trace with binds and waits. For example, the following is the navigation to enable trace in a form:
Goto the Oracle Applications Login
Open the form where the error occurs but do not yet cause the error.
Enable SQL*Trace by choosing
Help > Diagnostics > Trace > Trace with binds
A message appears indicating that the trace will be recorded Note the file name and location of the file Now reproduce the error. Once the error occurs, disable trace as soon as possible.
Disable SQL*Trace by choosing
Help > Diagnostics > Trace > Trace off
The same file name and location will be noted in case you need it again. Retrieve the trace file.
4. How does one enable trace for a concurrent program?
A simple way to enable trace in a concurrent program is to review the concurrent program definition and select trace enabled. This will enable trace without binds for all users that run the program. For example, the following steps could be used.
Goto Sysadmin > Concurrent > Program > Define
Query the concurrent program
Check the trace box to enable trace
If you require bind variables for your trace file from a concurrent program, a more sophisticated method is required as noted below.
5. How does one enable trace for a concurrent program INCLUDING bind variables and waits?
Trace can be enabled for a concurrent program by enabling trace on the program definition for all users as noted above, but this does not include bind variables or wait times. To enable trace with bind variables for a concurrent program, you may consider the following approach that uses the bde script for concurrent program tracing with binds and waits using event 10046 at level 12. *** This method will enable trace with binds for all new sessions and connections Download and review the script, bde_system_event_10046.sql,
from Note 179848.1.
Run the script and press enter when prompted:
SQL> bde_system_event_10046.sql
Return to the application Execute the concurrent program Monitor the program until it begins to run Return to SQL*Plus and press enter to cancel tracing new programs
6. How does one find a trace file for a concurrent program?
It is common for people to look for the last updated trace files or to use UNIX functions like 'grep' to parse the trace files looking for the one related to their concurrent program. However, the following SQL can be used to assist in identifying the trace file associated to a concurrent program. The SQL prompts the user for the request id and outputs the trace file name and location.
Warning: Some users have pointed out that this SQL does not always point out the exact filename and location. On a multi-node database environment, the user might not know what machine to look at. Also, the construction of the actual filename may be different on your environment as this is configurable. If your filenames are configured differently, you may want to use number part of the filename (the process id), then search for files in your trace directory with the same id.
A trick that may help you find the correct trace file directory is to enable trace via the Application user using
Help > Diagnostics > Trace > Trace On.
This will popup a window indicating the directory where trace files are written.Finally, the oracle_process_id is selected from v$process so this ID is only available during runtime of the process.It gets cleared shortly after the process terminated. Then you cannot find the trace file for a concurrent program anymore. Therefore, you should run this SQL shortly after running the concurrent program.
SQL> prompt accept request prompt 'Please enter the concurrent request id for the appropriate concurrent program:'
prompt column traceid format a8
column tracename format a80
column user_concurrent_program_name format a40
column execname format a15
column enable_trace format a12
set lines 80
set pages 22
set head off
SELECT 'Request id: 'request_id , 'Trace id: 'oracle_Process_id, 'Trace Flag: 'req.enable_trace, 'Trace Name: 'dest.value'/'lower(dbnm.value)'_ora_'oracle_process_id'.trc', 'Prog. Name: 'prog.user_concurrent_program_name, 'File Name: 'execname.execution_file_name execname.subroutine_name , 'Status : 'decode(phase_code,'R','Running') '-'decode(status_code,'R','Normal'), 'SID Serial: 'ses.sid',' ses.serial#, 'Module : 'ses.module from fnd_concurrent_requests req, v$session ses, v$process proc, v$parameter dest, v$parameter dbnm, fnd_concurrent_programs_vl prog, fnd_executables execname where req.request_id = &request and req.oracle_process_id=proc.spid(+) and proc.addr = ses.paddr(+) and dest.name='user_dump_dest' and dbnm.name='db_name' and req.concurrent_program_id = prog.concurrent_program_id and req.program_application_id = prog.application_id and prog.application_id = execname.application_id and prog.executable_id=execname.executable_id;
7. How does one enable trace for all actions that occur for a user?
One can enable trace for all actions that a user takes by setting a profile option for the user. See Note 170223.1 for detailed screen shots.
This will function when the user logs into the Oracle Applications forms or when logging into the Self Service Web Applications. This method uses an Event Trace. The instructions for enabling the event trace follow: a. First enable trace for a specific user: -
Bring up the Core application - System Administrator responsibility - Move to Profile/System - Check off the USER box -
and enter your username that you are using when getting the error - Search on the following profile option -
'Initialization SQL Statement - Custom' Please set this at the user level with the following string:
BEGIN FND_CTL.FND_SESS_CTL('','', '', 'TRUE','','ALTER SESSION SET TRACEFILE_IDENTIFIER=''''''4269824.999' ''''' EVENTS ='''''' 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12 '''''); END;
(Cut and paste the above sql statement into the User Level profile option: "Initialization SQL - Custom") This must be one complete line of text - so may be best to copy the string into notepad prior to putting it into the profile.
b. Once the profile is set, please change responsibilities and directly go and reproduce the problem. To locate the trace file, use the following sql in sqlplus:
SQL> select name, value from v$parameter where name like 'user_dump_dest';
- The value is the location of the trace file on the database server - Please move to this directory and search for the file having 4269824.999 in the filename - This is the trace file created - please tkprof and upload BOTH the raw and tkprof trace file to metalink.
c. Ensure that the profile option is unset before exiting the Application. This is a very important step. If this is not unset, unnecessary trace files will be generated.
d. Note that a similar technique can be used for enabling trace with binds for a user in SQL*Plus. The commands would look like the following:
SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER='577' EVENTS ='10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
SQL> select 'x' from dual;
-- or any SQL that you want to trace
SQL> alter session set sql_trace = false;
8. How does one enable trace for a web-based screen like found in the self service applications?
Use the same method as noted above in "How does one enable trace for all actions that occur for a user?" Also review Note 245974.1, section "10. How To Generate and Retrieve Trace Files in SSA (Self Service Applications)". Section 10 discusses techniques available within Self Service for debugging and tracing.
9. Are there any other tools that can assist in reviewing trace files (what is TraceAnalyzer)?
... a. Using TKPROF
A trace file can be reviewed using TKPROF.
TKPROF reformats the raw data so that it is easier to review.
The TKPROF commands are normally run at the operating system command prompt.
This will be signified with a $ as this is a common prompt in UNIX.
1. Retrieve the trace file.
2. Issue a command like the following to create a TKPROF version of the trace file.
The explain option will look to see how each query is handled by the database in terms of what tables and indexes are referenced.
$ tkprof
However, TKPROF does not take into account bind variables. Therefore, these are ignored in the output. When you need to analyze bind variables, consider using TraceAnalyzer.
A handy technique when trouble shooting performance issues is to use TKPROF to look at the longest running queries. Since trace files related to performance can be huge, one might spend hours looking through the results to find the queries causing the issue. If you sort the file by the longest running queries first, it makes it much easier to investigate. The following example sorts by longest running queries first with the sort options selected as "sort='(prsela,exeela,fchela)'" and limits the results to the "Top 10" long running queries with the "print=10" command:
$ tkprof
... b. Using TraceAnalyzer
Please refer to Note 224270.1: Trace Analyzer TraceAnalyzer reformats the raw data so that it is easier to review. It is a more powerful tool than TKPROF. It translates things like bind variables and make them easy to find. 1. Download TraceAnalyzer from Note 224270.12. Install trace analyzer in SQL:
SQL> start TRCACREA.sql
3. Retrieve the trace file. 4. In SQL*Plus, issue a command like the following to create a TraceAnalyzer version of the trace file:
SQL> start TRCANLZR.sql UDUMP vis015_ora_22854.trc
10. Will these techniques work in previous versions before 11i (For example, 10.7 and 11.0.3)?
Many of the same techniques will work in previous versions of the Oracle Applications. However, there are some limitations for example, in 10.7 and 11.0.3, the application did not indicate the trace file name when a user enabled trace using Help > Diagnostics > Trace. Also, the previous versions of the application did not allow for the user to enable trace with binds using the Help > Diagnostics navigation path.
11. Another technique for finding / supplying trace files?Check out Note 161474.1 where the RDA output can grab the last trace file and you could then upload the RDA to the Service Request.
Cheers!!!!
