Tuesday, May 12, 2026

Get completed request start and end time

Get completed request start and end time

SELECT
    r.request_id,
    pt.user_concurrent_program_name program_name,
    r.actual_start_date,
    r.actual_completion_date,
    ROUND((r.actual_completion_date - r.actual_start_date) * 24 * 60, 2) elapsed_minutes,
    r.phase_code,
    r.status_code,
    r.logfile_name,
    r.outfile_name
FROM apps.fnd_concurrent_requests r,
     apps.fnd_concurrent_programs_tl pt
WHERE r.concurrent_program_id = pt.concurrent_program_id
  AND r.program_application_id = pt.application_id
  AND pt.language = USERENV('LANG')
  AND r.request_id = &REQUEST_ID;

This gives you the exact window:

actual_start_date     = request DB/application execution start
actual_completion_date = request completion time

You will use this window to search ASH/AWR.

2. Find SQL_ID from completed request window using ASH

This is the most useful query.

SELECT
    ash.sql_id,
    ash.sql_plan_hash_value,
    COUNT(*) ash_samples,
    ROUND(COUNT(*) * 10 / 60, 2) approx_active_minutes,
    MIN(ash.sample_time) first_seen,
    MAX(ash.sample_time) last_seen,
    MAX(ash.module) module,
    MAX(ash.action) action,
    MAX(ash.program) program
FROM dba_hist_active_sess_history ash
WHERE ash.sample_time BETWEEN
      (SELECT actual_start_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND (SELECT actual_completion_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND ash.session_type = 'FOREGROUND'
  AND ash.sql_id IS NOT NULL
GROUP BY
    ash.sql_id,
    ash.sql_plan_hash_value
ORDER BY ash_samples DESC;

The SQL_ID with the highest ASH_SAMPLES is usually the main SQL that consumed time.

3. Better query: include wait event and wait class

Use this to understand why it took time.

SELECT
    ash.sql_id,
    ash.sql_plan_hash_value,
    NVL(ash.event, 'ON CPU') event,
    ash.wait_class,
    COUNT(*) ash_samples,
    ROUND(COUNT(*) * 10 / 60, 2) approx_active_minutes,
    ROUND(100 * COUNT(*) / SUM(COUNT(*)) OVER (), 2) pct,
    MIN(ash.sample_time) first_seen,
    MAX(ash.sample_time) last_seen
FROM dba_hist_active_sess_history ash
WHERE ash.sample_time BETWEEN
      (SELECT actual_start_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND (SELECT actual_completion_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND ash.session_type = 'FOREGROUND'
  AND ash.sql_id IS NOT NULL
GROUP BY
    ash.sql_id,
    ash.sql_plan_hash_value,
    NVL(ash.event, 'ON CPU'),
    ash.wait_class
ORDER BY ash_samples DESC;

Interpretation:

Wait/EventMeaning
ON CPUSQL consumed CPU; check logical reads and plan
db file scattered readFull table scan / large multiblock reads
db file sequential readIndex/table single block reads
direct path read tempTEMP spill due to sort/hash
direct path write tempTEMP writing
gc cr requestRAC global cache wait
enq: TX - row lock contentionBlocking/locking
log file syncCommit wait

4. Get SQL text for the SQL_ID

First try AWR SQL text:

SELECT
    sql_id,
    sql_text
FROM dba_hist_sqltext
WHERE sql_id = '&SQL_ID';

If not available in AWR, try cursor cache:

SELECT
    inst_id,
    sql_id,
    child_number,
    sql_fulltext
FROM gv$sql
WHERE sql_id = '&SQL_ID';

For very long SQL text:

SET LONG 1000000
SET LONGCHUNKSIZE 1000000
SET PAGESIZE 50000
SET LINESIZE 300

SELECT sql_fulltext
FROM gv$sql
WHERE sql_id = '&SQL_ID'
  AND ROWNUM = 1;

5. Get execution plan of the SQL_ID

From AWR:

SELECT *
FROM TABLE(DBMS_XPLAN.DISPLAY_AWR('&SQL_ID', NULL, NULL,
'ALL +PEEKED_BINDS +OUTLINE +ALIAS +NOTE'));

If you know the plan hash value:

SELECT *
FROM TABLE(DBMS_XPLAN.DISPLAY_AWR('&SQL_ID', &PLAN_HASH_VALUE, NULL,
'ALL +PEEKED_BINDS +OUTLINE +ALIAS +NOTE'));

If SQL is still in memory:

SELECT *
FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR('&SQL_ID', NULL,
'ALLSTATS LAST +PEEKED_BINDS +OUTLINE +ALIAS +NOTE'));

6. Get AWR SQL performance numbers

This proves whether SQL was CPU-heavy, I/O-heavy, or RAC-heavy.

SELECT
    sn.begin_interval_time,
    sn.end_interval_time,
    s.instance_number,
    s.plan_hash_value,
    s.executions_delta executions,
    ROUND(s.elapsed_time_delta / 1000000, 2) elapsed_sec,
    ROUND(s.cpu_time_delta / 1000000, 2) cpu_sec,
    ROUND(s.iowait_delta / 1000000, 2) io_wait_sec,
    ROUND(s.clwait_delta / 1000000, 2) cluster_wait_sec,
    ROUND(s.apwait_delta / 1000000, 2) app_wait_sec,
    ROUND(s.ccwait_delta / 1000000, 2) concurrency_wait_sec,
    s.buffer_gets_delta,
    s.disk_reads_delta,
    s.rows_processed_delta
FROM dba_hist_sqlstat s,
     dba_hist_snapshot sn
WHERE s.dbid = sn.dbid
  AND s.snap_id = sn.snap_id
  AND s.instance_number = sn.instance_number
  AND s.sql_id = '&SQL_ID'
  AND sn.begin_interval_time <=
      (SELECT actual_completion_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND sn.end_interval_time >=
      (SELECT actual_start_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
ORDER BY sn.begin_interval_time, s.instance_number;

7. Find object/table involved in the delay

SELECT
    o.owner,
    o.object_name,
    o.object_type,
    COUNT(*) ash_samples,
    ROUND(COUNT(*) * 10 / 60, 2) approx_active_minutes
FROM dba_hist_active_sess_history ash
LEFT JOIN dba_objects o
       ON ash.current_obj# = o.object_id
WHERE ash.sample_time BETWEEN
      (SELECT actual_start_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND (SELECT actual_completion_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND ash.sql_id = '&SQL_ID'
GROUP BY
    o.owner,
    o.object_name,
    o.object_type
ORDER BY ash_samples DESC;

This helps you say:

SQL_ID xxxx spent maximum time on table/index ABC.XYZ.

8. Check whether the SQL plan changed

SELECT
    s.sql_id,
    s.plan_hash_value,
    COUNT(DISTINCT s.snap_id) snap_count,
    MIN(sn.begin_interval_time) first_seen,
    MAX(sn.end_interval_time) last_seen,
    SUM(s.executions_delta) executions,
    ROUND(SUM(s.elapsed_time_delta) / 1000000, 2) elapsed_sec,
    ROUND(SUM(s.cpu_time_delta) / 1000000, 2) cpu_sec,
    SUM(s.buffer_gets_delta) buffer_gets,
    SUM(s.disk_reads_delta) disk_reads
FROM dba_hist_sqlstat s,
     dba_hist_snapshot sn
WHERE s.dbid = sn.dbid
  AND s.snap_id = sn.snap_id
  AND s.instance_number = sn.instance_number
  AND s.sql_id = '&SQL_ID'
GROUP BY
    s.sql_id,
    s.plan_hash_value
ORDER BY first_seen;

If more than one PLAN_HASH_VALUE is seen, check for plan regression.

9. Check if request waited in concurrent manager queue

Sometimes the request did not take time in SQL. It waited before execution.

SELECT
    request_id,
    requested_start_date,
    actual_start_date,
    actual_completion_date,
    ROUND((actual_start_date - requested_start_date) * 24 * 60, 2) queue_wait_minutes,
    ROUND((actual_completion_date - actual_start_date) * 24 * 60, 2) execution_minutes
FROM apps.fnd_concurrent_requests
WHERE request_id = &REQUEST_ID;

If queue wait is high, RCA is:

The delay was due to concurrent manager queue wait, not database SQL execution.

10. Check blocking during request execution

SELECT
    ash.sample_time,
    ash.instance_number,
    ash.session_id waiting_sid,
    ash.session_serial# waiting_serial,
    ash.sql_id waiting_sql_id,
    ash.event,
    ash.blocking_inst_id,
    ash.blocking_session,
    ash.blocking_session_serial#,
    ash.blocking_session_status
FROM dba_hist_active_sess_history ash
WHERE ash.sample_time BETWEEN
      (SELECT actual_start_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND (SELECT actual_completion_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND ash.sql_id = '&SQL_ID'
  AND ash.blocking_session IS NOT NULL
ORDER BY ash.sample_time;

If rows are returned, use this RCA:

The request was delayed due to blocking/locking. ASH shows SQL_ID xxxx waiting on event xxxx and blocked by session xxxx.

11. Check TEMP spill

SELECT
    NVL(event, 'ON CPU') event,
    wait_class,
    COUNT(*) ash_samples,
    ROUND(COUNT(*) * 10 / 60, 2) approx_minutes
FROM dba_hist_active_sess_history
WHERE sql_id = '&SQL_ID'
  AND sample_time BETWEEN
      (SELECT actual_start_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND (SELECT actual_completion_date
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND (
        event LIKE '%temp%'
     OR event LIKE 'direct path read temp'
     OR event LIKE 'direct path write temp'
      )
GROUP BY event, wait_class
ORDER BY ash_samples DESC;

If TEMP is high:

The SQL spilled to TEMP due to large sort/hash operation, causing direct path read/write temp waits.

12. Check historical runtime of same concurrent program

SELECT
    r.request_id,
    r.actual_start_date,
    r.actual_completion_date,
    ROUND((r.actual_completion_date - r.actual_start_date) * 24 * 60, 2) elapsed_minutes,
    r.phase_code,
    r.status_code,
    r.argument_text
FROM apps.fnd_concurrent_requests r
WHERE r.concurrent_program_id =
      (SELECT concurrent_program_id
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND r.program_application_id =
      (SELECT program_application_id
         FROM apps.fnd_concurrent_requests
        WHERE request_id = &REQUEST_ID)
  AND r.actual_start_date >= SYSDATE - 30
  AND r.actual_completion_date IS NOT NULL
ORDER BY r.actual_start_date DESC;

This helps compare:

Normal runtime: 2 minutes
Issue runtime: 4 hours

13. One master query: completed request to SQL_ID mapping

Use this first in real RCA.

SELECT
    r.request_id,
    pt.user_concurrent_program_name program_name,
    r.actual_start_date,
    r.actual_completion_date,
    ROUND((r.actual_completion_date - r.actual_start_date) * 24 * 60, 2) request_elapsed_min,
    ash.sql_id,
    ash.sql_plan_hash_value,
    NVL(ash.event, 'ON CPU') event,
    ash.wait_class,
    COUNT(*) ash_samples,
    ROUND(COUNT(*) * 10 / 60, 2) approx_active_minutes,
    MAX(ash.module) module,
    MAX(ash.action) action,
    MAX(ash.program) program
FROM apps.fnd_concurrent_requests r,
     apps.fnd_concurrent_programs_tl pt,
     dba_hist_active_sess_history ash
WHERE r.concurrent_program_id = pt.concurrent_program_id
  AND r.program_application_id = pt.application_id
  AND pt.language = USERENV('LANG')
  AND ash.sample_time BETWEEN r.actual_start_date AND r.actual_completion_date
  AND r.request_id = &REQUEST_ID
  AND ash.session_type = 'FOREGROUND'
  AND ash.sql_id IS NOT NULL
GROUP BY
    r.request_id,
    pt.user_concurrent_program_name,
    r.actual_start_date,
    r.actual_completion_date,
    ash.sql_id,
    ash.sql_plan_hash_value,
    NVL(ash.event, 'ON CPU'),
    ash.wait_class
ORDER BY ash_samples DESC;

14. RCA wording template

RCA for Completed Concurrent Request

Request ID: <REQUEST_ID>
Program Name: <PROGRAM_NAME>
Start Time: <ACTUAL_START_DATE>
Completion Time: <ACTUAL_COMPLETION_DATE>
Total Runtime: <X minutes>

Finding:
The request completed successfully, but it took longer than expected.

SQL_ID Evidence:
ASH analysis for the request execution window shows SQL_ID <SQL_ID> consumed the highest database active time.
Plan Hash Value: <PLAN_HASH_VALUE>
Approximate DB active time from ASH: <X minutes>

Wait Evidence:
Top wait event: <EVENT>
Top wait class: <WAIT_CLASS>

SQL Text:
<short SQL text summary>

Performance Evidence:
AWR SQL statistics show:
- Elapsed time: <X sec>
- CPU time: <X sec>
- I/O wait: <X sec>
- Buffer gets: <X>
- Disk reads: <X>
- Rows processed: <X>

Conclusion:
The delay was mainly due to <CPU / I/O / TEMP / RAC / blocking / plan change / queue wait>.

Recommended Action:
1. Review execution plan for SQL_ID <SQL_ID>.
2. Validate object statistics on involved tables/indexes.
3. Compare current plan with previous good plan.
4. Check whether data volume or request parameters were abnormal.
5. If plan regression is confirmed, evaluate SQL Plan Baseline after testing.

15. Important point for Apps DBA

For a completed request, there is no direct always-available column in FND_CONCURRENT_REQUESTS that stores all SQL_IDs.

You find it using this relationship:

FND_CONCURRENT_REQUESTS
        gives request start/end time

DBA_HIST_ACTIVE_SESS_HISTORY
        gives active SQL_IDs during that time

DBA_HIST_SQLTEXT / GV$SQL
        gives SQL text

DBA_HIST_SQLSTAT
        gives elapsed, CPU, I/O, reads, rows

DBMS_XPLAN.DISPLAY_AWR
        gives execution plan

Best practical RCA flow:

Request ID 
→ Start/End Time 
→ ASH SQL_ID 
→ SQL Text 
→ AWR SQL Stats 
→ Execution Plan 
→ Wait Events 
→ Object Evidence 
→ RCA
Posted by at

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)