How to get a Trace first And Begin to Analyze a E-Business Applications Performance Issue (Doc ID 117129.1)

PURPOSE
-------
The purpose of this article is to offer step by step instructions to aid the 
inexperienced in retrieving and analyzing a trace for the purpose of 
troubleshooting a performance problem.

 
SCOPE & APPLICATION
-------------------
This article offers step by step instructions for creating and retrieving a 
trace for the purpose of troubleshooting a performance problem.  This article 
also offers general information about how to determine if there is a problem 
with the Oracle code vs. a problem with the current status of the database.  

Within this article, there are references to detailed documentation about how 
to tune the Oracle 7 and/or Oracle 8 database for optimum performance.  The 
referred articles are not necessarily intended for the inexperienced user.  
Whenever troubleshooting performance it is advisable to involve an experienced 
DBA with the problem.


PART I :  Tracing The Performance of a Process:
-----------------------------------------------
Whenever there is a performance problem, it is extremely important to identify 
the portion of the code that is causing the problem.  The only way to do this is
by obtaining an SQL Trace of the process that is performing poorly.   Depending 
on the process, there are several ways to get a trace.


STEP 1:  Turning on Timed_Statistics
------------------------------------
Whenever troubleshooting an application performance problem, it is a good idea 
to collect timed_statistics to determine which piece of code is taking the 
longest amount of time to execute.  Before running a trace, make sure that 
timed_statistics is turned on at the database level.  This will in no way affect 
performance for the users that are currently using the database.  Here is how to 
turn on timed_statistics.

    1.  Navigate to SQLPLUS.
    2.  At the SQL prompt, type the following:

            SQL> alter system set timed_statistics = true;

(Note:  A common misperception is that you always have to change the init.ora 
parameters and bounce the database (turn the database off and then on again) in 
order to get timed_statistics.  In Oracle 7 and Oracle 8, you do not have to 
bounce the database to get timed_statistics.)


STEP 2: Choosing the Best Type of Trace:
----------------------------------------
1.  Form Trace:

A form trace is used whenever the poor performance is happening on-line.  
For example, one might use a form trace to trace an inquiry that is taking 
a long time to complete (i.e..  An ATP inquiry, or an item inquiry).  Before 
turning trace on at the form level, close the application and then re-enter it.
This causes any open cursors from your previous session to close.  Do not turn 
trace on until just before you are ready to duplicate the problem.  To turn 
trace on at the form level, go to the toolbar and navigate to 
HELP -> TOOLS -> TRACE.  By clicking on the word trace, a checkmark will appear 
next to it, indicating that trace has been turned on.   Reproduce the problem.  
Navigate to HELP -> TOOLS -> TRACE, and click on the word trace to uncheck 
trace and turn it off.

2.  SQL Trace:

A SQL trace is used whenever you need to trace a background or concurrent 
process.  There are a couple of ways to set the system up to get a SQL Trace.

    a.  Some applications now have profiles that allow you to turn trace  
        on within the application.  These profiles are usually updateable at 
        the user level and can be turned on just for the user who is trying 
        to trace a process.  By turning trace on with the use of one of these 
        profile options, you are effectively doing the same thing as setting 
        SQL_TRACE=TRUE in the init.ora, but you DO NOT have to bounce the 
        database.  See the below list of current Trace Profile Options:

            AX: Trace Mode
            Debug: Trace Level for Danish
            INV: Debug Trace
            MRP: Trace Mode
            OE: Debug Trace
            Utilities: SQL Trace

    b.  If you do not have the luxury of a profile option to turn SQL trace 
        on, you can also turn trace on by typing the following at the SQL 
        prompt:

            SQL> alter session set sql_trace = true;

       After setting SQL Trace to true, run the process and then turn off trace 
       when you are done:

            SQL> alter session set sql_trace = false;

    c.  If all else fails, you can always edit your init<sid>.ora parameter,
        and set SQL_TRACE=TRUE, however, this should only be done as a last 
        resort, because it does require bouncing the database (turning the 
        database off and then on again) in order for the new setting to take 
        effect.  Whenever you change your init<sid>.ora to obtain a trace, you 
        will not only be tracing your process, but any other process that is 
        occurring in the database.  When using this method, it can become 
        quite difficult to weed through all the trace files that are created 
        to find the one you are looking for.

    d.  Please note that some processes, such as an MRP run, will create 
        more than one trace file.  This happens if the concurrent process 
        you are tracing spawns other concurrent processes.  For processes such
        as this, you may wish to empty your user_dump_destination directory 
        (see below) before running your trace.  That way, it will be less 
        difficult for you to find the trace that indicates the performance 
        problem.  When running an MRP or DRP trace, it is always a good idea 
        to set the profile,  MRP:Snapshot Workers, to 0 (zero) so you will 
        only get one trace file for the Memory-based Snapshot.


STEP 3: Finding Your Trace File:
--------------------------------
Normally, the trace files are saved to the user_dump_destination directory 
on the UNIX server. Depending on the features used, you may find them on 
other directories, though. For example, if using parallel queries, traces
will be dumped to the background_dump_destination; if using MTS (shared servers)
refer to Note 1038578.6.

If you do not know the path for those directories, you can run a command
like the following query in SQL, 

    SQL>    select name, value
       from v$parameter
     where name = 'user_dump_dest';

Example script result:
NAME
----------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
user_dump_dest
/cpl/oraclelogs/v1102vd/db/trace


Now, go to the UNIX prompt on your server and change the directory to the 
directory retrieved from the query above.   See the following example:

    lerikson:/cpl/home/lerikson/sql> cd /cpl/oraclelogs/v1102vd/db/trace

Now, type ls -lrt at the UNIX prompt.  See example below:

    lerikson:/cpl/oraclelogs/v1102vd/db/trace> ls -lrt

The result will be a list of trace files in chronological order from first 
to last.   Scroll down to the last file.  Most likely, the last one in the 
list will be yours.  Look at the time it was created.  You can usually tell 
which one is yours by the time it was created.  You can also find the right 
trace file by grepping for a table or index that you know was used by the 
process you ran.  For example, if you are tracing a material transaction, you 
might want to grep for mtl_material_transactions to find the correct trace.  
See example below:

    lerikson:/cpl/oraclelogs/v1102vd/db/trace> grep -i mtl_material_transactions

 
STEP 4: tkprof:
---------------
Now that you have a trace file, your analyst will need to see the tkprof?d 
output in order to analyze the problem.  A tkprof?d file has important 
information in readable format for the technical analyst to use for trouble-
shooting purposes.

When troubleshooting a performance problem, it is best to issue the tkprof 
command at the UNIX prompt using the following syntax: 

    tkprof <filename.trc> <output_filename> sys=no explain=apps/<password> 
    sort='(prsela,exeela,fchela)'

The above mentioned command sorts the SQL by placing the worst performing 
SQL statement at the top of the output file.

(Please note: You can only issue the tkprof command within a directory in
which you have write permission.  If you do not have write permission in the 
directory where the raw trace is stored, copy the trace file to your $HOME 
directory, and then issue the following tkprof command from there.  To copy 
the .trc file to your $HOME directory, use the following syntax):

    cp <filename.trc> $HOME


Example of tkprof'd output:

    UPDATE mrp_relief_interface 
    SET request_id = :sql_req_id, 
    process_status = 3 
    WHERE   inventory_item_id  IN 
        (SELECT inventory_item_id
         FROM   mrp_relief_interface rel2
         WHERE  rel2.request_id IS NULL 
         AND    rel2.error_message IS NULL 
         AND    rel2.relief_type = 1
         AND    rel2.process_status = 2
         AND    rownum <= :batch_size
         AND    NOT EXISTS
           (SELECT 'x'
            FROM   mrp_form_query
            WHERE  query_id = :in_process_items
                 AND    number1  = rel2.inventory_item_id))
    AND request_id IS NULL 
    AND error_message IS NULL 
    AND relief_type = 1 
    AND process_status = 2 

call     count       cpu    elapsed       disk      query    current       rows
------- ------  -------- ---------- ---------- ---------- ----------  ---------
Parse        2      0.02       0.02          0          0          0          0
Execute      2    239.39    1003.16     274981    3792129        534        242
Fetch        0      0.00       0.00          0          0          0          0
------- ------  -------- ---------- ---------- ---------- ----------  ---------
total        4    239.41    1003.18     274981    3792129        534        242

Misses in library cache during parse: 1
Optimizer goal: RULE
Parsing user id: 41  (APPS)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  UPDATE STATEMENT   GOAL: RULE
      0   UPDATE OF 'MRP_RELIEF_INTERFACE'
    242    NESTED LOOPS
    234     VIEW
    242      SORT (UNIQUE)
    242       COUNT (STOPKEY)
    242        FILTER
1886651         TABLE ACCESS (BY INDEX ROWID) OF 
                    'MRP_RELIEF_INTERFACE'
1886652          INDEX (RANGE SCAN) OF 'MRP_RELIEF_INTERFACE_N2' 
                     (NON-UNIQUE)
    234         INDEX   GOAL: ANALYZED (RANGE SCAN) OF 
                    'MRP_FORM_QUERY_N89' (NON-UNIQUE)
   3597     TABLE ACCESS (BY INDEX ROWID) OF 'MRP_RELIEF_INTERFACE'
   3831      INDEX (RANGE SCAN) OF 'MRP_RELIEF_INTERFACE_N2' 
                 (NON-UNIQUE)


PART II : Analyzing The Results of The Trace:
---------------------------------------------

Deciding if there is a problem with the code vs. the condition of your database:
--------------------------------------------------------------------------------
Each SQL statement in the tkprof?d output file has three sections:

    a.  The SQL statement itself.
    b.  Diagnostics including cpu and elapsed time, disk reads and logical 
        reads, and number of rows returned from the query.   
    c.  An execution plan listing all of the tables, views, and indexes
        that were accessed by the query.

One of the first things you can do with your tkprof?d output is find out what
your hit ratio was.   The hit ratio is an indication of how often your query 
had to go to the disk vs. memory to get the information it needed.  A ?good? 
hit ratio will fall somewhere between 99% and 100%.  Anything lower could 
indicate fragmentation or a problem with the size of your memory buffer.  The 
hit ratio is calculated as follows:

    Logical Reads - Physical Reads     or    (Query + Current) - Disk 
    ------------------------------            ------------------------               
           Logical Reads   (Query + Current)


In the tkprof?d example on the previous page, the hit ratio = 

    3517682/3792663 = 92%

If your hit ratio is lower than 99%, you should check to see how many 
extents you have on each and every object listed in the explain plan.  
In Oracle 7 and Oracle 8 it is always a good idea to keep your extents 
below double digits to maintain optimum performance.   Following is a 
simple query you can run to find out the number of extents on an object:

    select substr (tablespace_name,1,15) tname,
    substr(segment_name,1,25) segname,
    substr(segment_type,1,10) segtype,
    substr(owner,1,5) "OWNER",
    count(*) "Extents",
    blocks
    from dba_extents
    where segment_name = '&your_object_name'
    group by tablespace_name,
    segment_name,
    segment_type,
    owner,
    blocks;

Example Output:

TNAME           SEGNAME                   SEGTYPE    OWNER   Extents
BLOCKS                      
--------------- ------------------------- ---------- ----- ---------
---------                      
SHR             QA_RESULTS                TABLE      QA          187
513                      
SHR             QA_RESULTS                TABLE      QA          139
515


The query results above indicate some disk fragmentation.  The 
recommendation was to copy, drop and recreate the table, qa_results, 
into fewer extents.  For detailed information about how to maintain 
your database for optimum performance, please refer note 100964.1 and 
note 100960.1.

If your hit ratio is  > 99%, or if you have tuned the database to the best of
your knowledge and performance is still an issue, there is a strong possibility
that the code can be tuned to improve performance.  Before calling Oracle 
Support, check to see if the SQL statement with the performance problem was 
using the cost-based or the rule-based optimizer.  It is hard to tell from the 
tkprof?d output?s explain plan whether the rule or cost-based optimizer was
used because the explain plan always says, "Goal:  Rule".  If there are any 
hints in the SQL statement other than /*+Choose or /*+Rule, then you can assume
that the cost-based optimizer was used to create the explain plan.  You can tell
if there is a hint in the code, because a hint always follows this sequence of 
characters: /*+.  If a hint was not used, and if you are on Oracle 7 or 
Oracle 8, the rule-based optimizer was used to create the execution plan.  

You are probably asking, "What is the difference between the Cost-based and 
Rule-based Optimizers?."  This article will not go into detail, but to explain 
it very briefly, the rule and cost-based optimizers use different methods to 
determine what indexes or tables should be used when searching for data.  The 
optimizer also determines how the index will be scanned (full, range, etc..) 
when searching for data.  The cost-based optimizer depends on whether or not 
statistics have been collected on the database objects in order to determine 
the best execution plan for the SQL statement in question.  If statistics have 
not been recently collected, the cost-based optimizer may not always make a 
good decision with regards to the use of indexes, etc. when creating an 
execution plan for a SQL statement.  Therefore, if you have determined that the
cost-based optimizer was used on the SQL statement with the problem, please 
make sure that statistics have been collected on all of the tables in the 
execution plan before calling Oracle Support.  You might discover that simply 
collecting statistics on the tables in the execution plan would fix the problem.
 

Collecting Statistics in release 11.0.3 or lower
------------------------------------------------
To compute statistics for a table, use the following syntax at the 
SQL prompt:

    SQL>analyze table <owner.table_name> compute statistics.

Find more detailed information about collecting statistics for the cost-based
optimizer within the following documents:

    Note 102334.1 - How to automate ANALYZE TABLE when changes occur on tables
    Note 114671.1 - Gathering Statistics for the Cost Based Optimizer
    Note 116178.1 - Analyze Command - Compute Statistics vs. Estimate Statistics


Collecting Statistics in Release 11i or higher:
----------------------------------------------
In prior releases of the application, the rule-based optimizer was the
default optimizer.  In release 11i or higher, the cost-based optimizer is 
the default optimizer.  If you are on release 11i or higher, it is necessary 
to run the concurrent program called GATHER SCHEMA STATISTICS on a regular
basis to insure optimum performance. Gather Schema Statistics calls the 
FND_STATS function.  This should not be confused with running
analyze.  FND_STATS and analyze return different results.  Refer to the
following notes for more information about GATHER SCHEMA STATISTICS:

Note 122371.1 - How to gather statistics for Oracle Applications
Note 116571.1 - Cost Based Optimiser and Applications Release 11i
Note 117363.1 - Analysing 11i Tables for Performance


ADDITIONAL REFERENCES
---------------------
Note 100964.1 - Troubleshooting Performance Issues Relating to the Database 
                and Core/MFG MRP
Note 100960.1 - Troubleshooting Performance Issues Relating To Database 
                Objects And Core/Mfg MRP
Note 102334.1 - How to automate ANALYZE TABLE when changes occur on tables
Note 114671.1 - Gathering Statistics for the Cost Based Optimizer
Note 116178.1 - Analyze Command - Compute Statistics vs. Estimate Statistics