This article explains, how to enable trace for Concurrent Program and generate TKPROF in Oracle Apps. These steps should work for Oracle Apps 11i and R12 release.
Concurrent programs execute business logic by connecting to the database and performing database operations like the update, insert, delete. These operations consume CPU, Memory and other resources. An ill-written concurrent program may impact your overall ERP instance and slows it down during business hours.
You can trace the concurrent program and generate tkprof to understand how queries are running, is there any full table scan, any query which needs tuning.
1. Enable trace for Concurrent Programs
Log in to Oracle App and navigate to Application Developer-> Concurrent Program –> Define. Query the concurrent program (Use F11 and Ctrl + F11). Check the Enable Trace checkbox as shown below and save.
2. Run Concurrent Program
Now, go to the responsibility where the concurrent program is registered. Navigate to View -> Request -> Submit Request and submit the concurrent program. Wait till the concurrent program completes before moving to the next steps.
3. Find Trace file path
Use the below query to get the trace file location. This is the actual physical directory on the database server. The trace file is generated at the database tier.
SELECT value FROM v$parameter WHERE name='user_dump_dest';
4. Name of the trace file
The trace file name follows some naming standards. It contains oracle_process_id generated internally. Let’s see how to find out the name. Assume that the request-id 35133016.
Use the below query to get Oracle Process id.
SELECT oracle_process_id FROM fnd_concurrent_Requests WHERE request_id = 35133016;
It is 121313 for the request-id 35133016.
Now login to Unix/Linux database server. Navigate to the path which you got in the previous step and run below Unix ls command.
ls *121313*
-rwxrwxrwx. 1 nobody ora_dba 180K Mar 13 02:24 TSTINSTANCE_ora_121313_APPS_0313_020936.trc
The trace file name is TSTINSTANCE_ora_121313_APPS_0313_020936.trc.
5. Format Trace file using TKPROF
Generated trace file(.trc) file contains all information and it is not human readable. You need to use the tkprof command utility to convert in a readable format.
Sample trace file
===================== PARSING IN CURSOR #139949424689864 len=33 dep=0 uid=173 oct=47 lid=173 tim=2369959266663 hv=1991901736 ad='8c58fed08' sqlid='4g2612tvbn0j8' begin FND_TRACE.START_TRACE; end; END OF STMT EXEC #139949424689864:c=8997,e=10037,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=2369959266661 WAIT #139949424689864: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=34388 tim=2369959266722 WAIT #139949424689864: nam='SQL*Net message from client' ela= 260 driver id=1952673792 #bytes=1 p3=0 obj#=34388 tim=2369959266999 CLOSE #139949424689864:c=0,e=12,dep=0,type=1,tim=2369959267035 WAIT #139949424692008: nam='SQL*Net message to client' ela= 0 driver id=1952673792 #bytes=1 p3=0 obj#=34388 tim=2369959267136 =====================
Run below command to generate TKPROF on the Unix tier.
tkprof TSTINSTANCE_ora_121313_APPS_0313_020936.trc trace.txt apps/<apps username>
Below is generated TKPROF file
TKPROF: Release 12.1.0.2.0 - Development on Tue Mar 13 02:23:39 2018
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
Trace file: TSTINSTANCE_ora_108549_APPS_0313_020936.trc
Sort options: prsela exeela fchela
********************************************************************************
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
********************************************************************************
SELECT f.column_seq_num Sequence,
f.form_left_prompt Prompt,
f.end_user_column_name Name,
f.description Description,
decode(f.enabled_flag,'Y','Yes','No') ParamEnabled ,
decode(f.display_flag,'Y','Yes','No') ParamDisplayed ,
f.srw_param Token,
fv.flex_value_set_name ValueSet,
f.default_value DefaultValue,
substr(descriptive_flexfield_name,7) ParamConcProg
FROM fnd_descr_flex_col_usage_vl f ,
fnd_flex_value_sets fv
WHERE ( f.flex_value_set_id = fv.flex_value_set_id ) AND ( :ConcProgName = substr(descriptive_flexfield_name,7)) order by f.column_seq_num
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 0
Fetch 1 0.70 2.91 10977 11951 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.70 2.91 10977 11951 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 SORT (ORDER BY)
0 HASH JOIN
0 HASH JOIN
0 TABLE ACCESS MODE: ANALYZED (FULL) OF
'FND_DESCR_FLEX_COLUMN_USAGES' (TABLE)
0 TABLE ACCESS MODE: ANALYZED (FULL) OF
'FND_FLEX_VALUE_SETS' (TABLE)
0 TABLE ACCESS MODE: ANALYZED (FULL) OF
'FND_DESCR_FLEX_COL_USAGE_TL' (TABLE)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 5 0.00 0.00
db file scattered read 754 0.01 2.23
db file sequential read 15 0.00 0.02
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
Summary
Generating trace and tkprof of concurrent programs help you to pinpoint exact SQL which is causing the program to run slow.
I hope you found this helpful. Please share and subscribe.
