Track and Trace E-Business Suite Concurrent Request - EBS Logs, O/S Process IDs, Locks

I often get asked to take a look at an Oracle eBusiness Suite concurrent request to see what it is doing, this can come from a few different angles:

1. What requests are currently running?
2. I have an operating system process that is taking too much CPU - what is it doing?
3. Can you tell me where the request is at? I've clicked on the log but it doesn't show anything!
4. My request is taking too long - can you check for blocking locks?

There are a number of strategies to track and trace where things are at for a running request, these include:

1. Monitor the currently running requests in fnd_concurrent_requests
2. Checking the v$sqlarea to see what SQL statement or PL/SQL is running
3. Tailing the concurrent request log / output file while it is being written to near realtime - prior to request completing
4. Checking for locks blocking the concurrent request

So without further ado, let's take a look at the following sweet query. UPDATE: 23-Aug-2012 fixed multi rows due to missing join on inst_id between gv$session and gv$process. Also note for non-RAC environments change gv$ to v$ and remove joins to sys.v_$active_instances:

set pages 9999 feed on lines 150
col user_concurrent_program_name format a40 head PROGRAM trunc
col elapsed format 9999
col request_id format 9999999 head REQUEST
col user_name format a12
col oracle_process_id format a5 head OSPID
col inst_name format a10
col sql_text format a30
col outfile_tmp format a30
col logfile_tmp format a30

REM *********************
REM **** RAC VERSION ****
REM *********************
select /*+ ordered */ 
       fcp.user_concurrent_program_name
,      fcr.request_id
,      round(24*60*( sysdate - actual_start_date )) elapsed
,      fu.user_name
,      fcr.oracle_process_id
,      sess.sid
,      sess.serial#
,      inst.inst_name
,      sa.sql_text
,      cp.plsql_dir || '/' || cp.plsql_out outfile_tmp
,      cp.plsql_dir || '/' || cp.plsql_log logfile_tmp
from   apps.fnd_concurrent_requests fcr
,      apps.fnd_concurrent_programs_tl fcp
,      apps.fnd_concurrent_processes cp
,      apps.fnd_user fu
,      gv$process pro
,      gv$session sess
,      gv$sqlarea sa
,      sys.v_$active_instances inst
where  fcp.concurrent_program_id = fcr.concurrent_program_id
and    fcp.application_id = fcr.program_application_id
and    fcr.controlling_manager = cp.concurrent_process_id
and    fcr.requested_by = fu.user_id (+)
and    fcr.oracle_process_id = pro.spid (+)
and    pro.addr = sess.paddr (+)
and    pro.inst_id = sess.inst_id (+)
and    sess.sql_address = sa.address (+)
and    sess.sql_hash_value = sa.hash_value (+)
and    sess.inst_id = inst.inst_number (+)
and    fcr.phase_code = 'R' /* only running requests */
;

REM *********************
REM ** NON-RAC VERSION **
REM *********************
select /*+ ordered */ 
       fcp.user_concurrent_program_name
,      fcr.request_id
,      round(24*60*( sysdate - actual_start_date )) elapsed
,      fu.user_name
,      fcr.oracle_process_id
,      sess.sid
,      sess.serial#
,      sa.sql_text
,      cp.plsql_dir || '/' || cp.plsql_out outfile_tmp
,      cp.plsql_dir || '/' || cp.plsql_log logfile_tmp
from   apps.fnd_concurrent_requests fcr
,      apps.fnd_concurrent_programs_tl fcp
,      apps.fnd_concurrent_processes cp
,      apps.fnd_user fu
,      v$process pro
,      v$session sess
,      v$sqlarea sa
where  fcp.concurrent_program_id = fcr.concurrent_program_id
and    fcp.application_id = fcr.program_application_id
and    fcr.controlling_manager = cp.concurrent_process_id
and    fcr.requested_by = fu.user_id (+)
and    fcr.oracle_process_id = pro.spid (+)
and    pro.addr = sess.paddr (+)
and    sess.sql_address = sa.address (+)
and    sess.sql_hash_value = sa.hash_value (+)
and    fcr.phase_code = 'R' /* only running requests */
;

PROGRAM                                   REQUEST ELAPSED USER_NAME    OSPID        SID    SERIAL# INST_NAME  SQL_TEXT                       OUTFILE_TMP                    LOGFILE_TMP
---------------------------------------- -------- ------- ------------ ----- ---------- ---------- ---------- ------------------------------ ------------------------------ ------------------------------
Workflow Background Process               2960551       1 VIRTUATE     24814        130      29699 APPLPROD1  BEGIN WF_ENGINE.BACKGROUNDCONC /usr/tmp/o0068194.tmp          /usr/tmp/l0068194.tmp
                                                                                                              URRENT(:errbuf,:rc,:A0,:A1,:A2
                                                                                                              ,:A3,:A4,:A5); END;

1 row selected.

From the above we can see key information:

• The running Concurrent Request Program Name and Request_ID
• The database node operating system process id (OSPID) so we can monitor usage via top / iostat / vmstat
• The SID / Serial in case we want to kill the session via alter system kill session '130,29699';
• The instance name the database session is running on in a RAC environment
• The currently running SQL text
• The temporary files where concurrent request log/out is being written to via utl_file while running. These files are copied over to the Concurrent Tier $APPLCSF/$APPLOUT and $APPLLOG after completion of the request.

We can break out the above into a few queries and procedures to drill into specific information information from the core EBS tables and DBA v$ views

1. Get concurrent requests running, temp files and Operating System PID

col user_concurrent_program_name format a40 head PROGRAM trunc
col elapsed format 9999
col request_id format 9999999 head REQUEST
col user_name format a12
col oracle_process_id format a5 head OSPID
select  fcp.user_concurrent_program_name
,       fcr.request_id
,       round(24*60*( sysdate - actual_start_date )) elapsed
,       fu.user_name
,       fcr.oracle_process_id
from    apps.fnd_concurrent_requests fcr
,       apps.fnd_concurrent_programs_tl fcp
,       apps.fnd_user fu
where   fcp.concurrent_program_id = fcr.concurrent_program_id
and     fcp.application_id = fcr.program_application_id
and     fu.user_id = fcr.requested_by
and     fcr.phase_code = 'R';

PROGRAM                                   REQUEST ELAPSED USER_NAME    OSPID
---------------------------------------- -------- ------- ------------ -----
Virtuate GL OLAP Data Refresh             2960541       5 VIRTUATE     21681

2. Get current running sql from instance (RAC inst_id/name) where request is running

col inst_name format a10
col sql_text format a30
col module format a20

REM *********************
REM **** RAC VERSION ****
REM *********************
select sess.sid
,      sess.serial#
,      sess.module
,      sess.inst_id
,      inst.inst_name
,      sa.fetches
,      sa.runtime_mem
,      sa.sql_text
,      pro.spid
from   gv$sqlarea sa
,      gv$session sess
,      gv$process pro
,      sys.v_$active_instances inst
where  sa.address = sess.sql_address
and    sa.hash_value = sess.sql_hash_value
and    sess.paddr = pro.addr
and    sess.inst_id = pro.inst_id
and    sess.inst_id = inst.inst_number (+)
and    pro.spid = &OSPID_from_running_request;

REM *********************
REM ** NON-RAC VERSION **
REM *********************

select sess.sid
,      sess.serial#
,      sess.module
,      sa.fetches
,      sa.runtime_mem
,      sa.sql_text
,      pro.spid
from   v$sqlarea sa
,      v$session sess
,      v$process pro
where  sa.address = sess.sql_address
and    sa.hash_value = sess.sql_hash_value
and    sess.paddr = pro.addr
and    pro.spid = &OSPID_from_running_request;

If you're running something that has long SQL statements, get the full SQL Statement by selecting from v$sqltext_with_newlines as follows

select t.sql_text
from   v$sqltext_with_newlines t
,      v$session s
where  s.sid = &SID
and    s.sql_address = t.address
order by t.piece

3. Find currently spooling temp file from request

col outfile format a30
col logfile format a30
select cp.plsql_dir || '/' || cp.plsql_out outfile
,      cp.plsql_dir || '/' || cp.plsql_log logfile
from  apps.fnd_concurrent_requests cr
,     apps.fnd_concurrent_processes cp
where cp.concurrent_process_id = cr.controlling_manager
and cr.request_id = &request_id;

OUTFILE                        LOGFILE
------------------------------ ------------------------------
/usr/tmp/PROD/o0068190.tmp     /usr/tmp/PROD/l0068190.tmp

REM Now tail log file on database node to see where it is at, near realtime
REM tail -f /usr/tmp/l0068190.tmp

Then on the Database node you can tail -f the above plsql_out or plsql_log files to see where program is at. Combine this with good logging techniques (date/time stamp on each entry) and you'll be able to know where your program is at.

If locks are the potential problem, then drill into those:

Currently held locks per concurrent request

set lines 150
col object_name format a32
col mode_held format a15
select /*+ ordered */
       fcr.request_id
,      object_name
,      object_type
,      decode( l.block
             , 0, 'Not Blocking'
             , 1, 'Blocking'
             , 2, 'Global'
             ) status
,      decode( v.locked_mode
             , 0, 'None'
             , 1, 'Null'
             , 2, 'Row-S (SS)'
             , 3, 'Row-X (SX)'
             , 4, 'Share'
             , 5, 'S/Row-X (SSX)'
             , 6, 'Exclusive'
             , to_char(lmode)
             ) mode_held
from   apps.fnd_concurrent_requests fcr
,      gv$process pro
,      gv$session sess
,      gv$locked_object v
,      gv$lock l
,      dba_objects d
where  fcr.phase_code = 'R'
and    fcr.oracle_process_id = pro.spid (+)
and    pro.addr = sess.paddr (+)
and    sess.sid = v.session_id (+)
and    v.object_id = d.object_id (+)
and    v.object_id = l.id1 (+)
;

REQUEST_ID OBJECT_NAME                      OBJECT_TYPE         STATUS       MODE_HELD
---------- -------------------------------- ------------------- ------------ ---------------
   1070780 VIRTUATE_GL_OLAP_REFRESH         TABLE               Not Blocking Exclusive

So there you have it - enough tools to keep you happy Track n Tracing! Maybe next time we'll look at tracing with bind / waits or PL/SQL Profiling concurrent programs

Catch ya!
Gareth
This is a post from Gareth's blog at http://garethroberts.blogspot.com

Related Posts

• Query: Find scheduled or on hold concurrent requests
• Query: Concurrent Programs by User and Responsibility
• Where do I get the XML file or request output file for my BI Publisher Report / Concurrent Request?