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:
- What requests are currently running?
- I have an operating system process that is taking too much CPU - what is it doing?
- Can you tell me where the request is at? I've clicked on the log but it doesn't show anything!
- 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:
- Monitor the currently running requests in fnd_concurrent_requests
- Checking the v$sqlarea to see what SQL statement or PL/SQL is running
- Tailing the concurrent request log / output file while it is being written to near realtime - prior to request completing
- 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
