Enable and Generate trace for Forms, Concurrent Program and Reports using TKPROF in Oracle Apps

Oracle SQL trace allows you to accurately assess the efficiency of the SQL statements. It can help you identify, pinpoint exact SQL query or event which is causing the performance problem.

Trace file as per this article shows below information,

  • Parse, execute, and fetch counts for SQL queries
  • CPU and elapsed times
  • Physical reads and logical reads
  • Number of rows processed
  • Misses on the library cache
  • Username under which each parse occurred
  • Each commit and rollback

This helps you to analyze and tune those to make it more efficient so that it consumes less resource.

Concurrent Program, Forms and Reports are major components in Oracle Apps. Performance of these components is the most important aspect. You may have good hardware but an ill-written concurrent program, form or report component may impact your overall ERP instance and slows it down during business hours. Users may complain that form is running very slow while performing business operations.

At the end it impacts business, so performance plays a very important role.

Oracle provides built-in utility TKPROF which can help you to trace the concurrent program, forms and reports.

In this article, let’s see how to enable trace and generate TKPROF in Oracle APPS.

How to enable trace for Concurrent Programs?

Navigate to Concurrent Program –> Define –> Query the concurrent program. User F11 and Ctrl + F11 to query the program. Check the Enable Trace checkbox as shown below.

concurrent program trace enable

This has just enabled the trace. Actually, trace file is generated when you run the concurrent program. Go ahead and submit the program and note down the request id. What it does, it generates a trace file at a predefined location.

Trace file path

This file path setup is in instance configuration file and is done by DBA. Use below query to get 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';

What is the name of trace file?

Trace file name follows some naming standard. Filename contains oracle_process_id generated internally. Let’s see how to find out the name. Assume that the request id 35133016.

Use below query to get Oracle Process id.

SELECT oracle_process_id
FROM fnd_concurrent_Requests
WHERE request_id = 35133016;

 

It is 108549 for the request id 35133016. Now navigate to the path which you got in the previous step and run below Unix ls command. ls command list content of the directory.

ls *108549*
-rwxrwxrwx. 1 nobody ora_dba 180K Mar 13 02:24 TSTINSTANCE_ora_108549_APPS_0313_020936.trc

How to enable trace for forms?

Open the form for which trace to be enabled. Here I am going to enable trace for Define concurrent program standard form.

Navigate to Help–>Diagnostics–>Trace–>Trace with Binds and Waits

 

oracle form enable trace

This opens a popup showing path and name of the trace file. Note it down.

form trace path

Now trace is enabled. Whatever operation you do will get recorded in the trace file. You can perform any transaction on form like querying, inserting, updating and deleting data. I am just going to query the concurrent program. After that make sure to disable trace. Tracing will be ON unless you explicitly disable it. Use same navigation as shown and choose No Trace option.

sql trace disabled

Oracle apps confirm you back that trace is disabled and again so you file name along with path.

Reports

Oracle reports mostly used as a concurrent program in Oracle Apps. If that is the case, follow How to enable Trace for Concurrent Program? section for details.

In some of the cases, you may be using reports using report server or independent components. You should use regular alter session command.

Write below code in the Before-report trigger.

ALTER SESSION SET sql_trace = true;
ALTER SESSION SET tracefile_identifier = report_trace_file_1;

This creates trace file at the same location with filename mentioned in alter command. Write below code in the after-report trigger.

ALTER SESSION SET sql_trace = false;

Format Trace file using TKPROF

Generated trace file(.trc) file contains all information and it is not human readable. You need to use tkprof command to convert it 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
=====================

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

 

Did you like artlcie? Please share and subscribe.

Related Post