Life Cycle of a Process Request

Oracle's Flashback Query facility lets you query a past version of a row by using the information in the undo segment.  The VERSIONS option lets you seen all the versions that are available. Thus, it is possible to write a simple query to retrieve the all values that changed on a process request record through its life cycle.

The Oracle parameter undo_retention determines how long that data remains in the undo segment. In my example, it is set to 900 seconds, so I can only query versions in the last 15 minutes. If I attempt to go back further than this I will get an error.

column prcsinstance heading 'P.I.' format 9999999
column rownum heading '#' format 9 
column versions_starttime format a22
column versions_endtime format a22

SELECT rownum, prcsinstance
, begindttm, enddttm
, runstatus, diststatus
, versions_operation, versions_xid
, versions_starttime, versions_endtime
FROM sysadm.psprcsrqst
VERSIONS BETWEEN timestamp
systimestamp - INTERVAL '15' MINUTE AND
systimestamp 
WHERE prcsinstance = 2920185
/

#     P.I. BEGINDTTM           ENDDTTM             RU DI V VERSIONS_XID     VERSIONS_STARTTIME    VERSIONS_ENDTIME
-- -------- ------------------- ------------------- -- -- - ---------------- --------------------- ----------------------
 1  2920185 10:51:13 11/06/2010 10:52:11 11/06/2010 9  5  U 000F00070017BD63 11-JUN-10 10.52.10 AM
 2  2920185 10:51:13 11/06/2010 10:52:11 11/06/2010 9  5  U 001A002C001CB1FF 11-JUN-10 10.52.10 AM 11-JUN-10 10.52.10 AM
 3  2920185 10:51:13 11/06/2010 10:52:11 11/06/2010 9  7  U 002C001F000F87C0 11-JUN-10 10.52.10 AM 11-JUN-10 10.52.10 AM
 4  2920185 10:51:13 11/06/2010 10:52:11 11/06/2010 9  1  U 000E000A001771CE 11-JUN-10 10.52.10 AM 11-JUN-10 10.52.10 AM
 5  2920185 10:51:13 11/06/2010 10:52:02 11/06/2010 9  1  U 002A000F00125D89 11-JUN-10 10.52.01 AM 11-JUN-10 10.52.10 AM
 6  2920185 10:51:13 11/06/2010                     7  1  U 0021000B00132582 11-JUN-10 10.51.10 AM 11-JUN-10 10.52.01 AM
 7  2920185                                         6  1  U 0004002000142955 11-JUN-10 10.51.10 AM 11-JUN-10 10.51.10 AM
 8  2920185                                         5  1  I 0022002E0013F260 11-JUN-10 10.51.04 AM 11-JUN-10 10.51.10 AM

Now, I can see each of the committed versions of the record. Note that each version is the result of a different transaction ID.
Reading up from the last and earliest row in the report, you can see the history of this process request record.

• At line 8 it was inserted (the value of psuedocolumn VERSION_OPERATION is 'I') at RUNSTATUS 5 (queued) by the component the operator used to submit the record.
• At line 7, RUNSTATUS was updated to status 6 (Initiated) by the process scheduler.
• At line 6 the process begins and updates the BEGINDTTM with the current database time, and sets RUNSTATUS to 7 (processing).
• At line 5 the process completes, updates ENDDTTM to the current database time, and sets RUNSTATUS to 9 (success).
• At line 4 the ENDDTTM is updated again. This update is performed by the Distribution Server process in the Process Scheduler domain as report output is posted to the report repository.  Note that the value is 1 second later than the VERSIONS_ENDTIME, therefore this time stamp is based on the operating system time for the host running the process scheduler. This server's clock is slightly out of sync with that of the database server.
• At lines 3 to 1 there are 3 further updates as the distribution status is updated twice more.

For me, the most interesting point is that ENDDTTM is updated twice; first with the database time at which the process ended, and then again with the time at which any report output was successfully completed.

I frequently want measure the performance of a processes. I often write script that calculate the duration of the process as being the difference between ENDDTTM and BEGINDTTM, but now it is clear that this includes the time taken to post the report and log files to the report repository.

For Application Engine processes, you can still recover the time when the process ended. If batch timings are enabled and written to the database, the BEGINDTTM and ENDDTTM are logged in PS_BAT_TIMINGS_LOG.

select * from ps_bat_timings_log where process_instance = 2920185

PROCESS_INSTANCE PROCESS_NAME OPRID                          RUN_CNTL_ID
---------------- ------------ ------------------------------ ------------------------------
BEGINDTTM           ENDDTTM             TIME_ELAPSED TIME_IN_PC TIME_IN_SQL TRACE_LEVEL
------------------- ------------------- ------------ ---------- ----------- -----------
TRACE_LEVEL_SAM
---------------
         2920185 XXX_XXX_XXXX 52630500                       16023
10:51:12 11/06/2010 10:52:02 11/06/2010        49850      35610       13730        1159
            128

You can see above that ENDDTTM is the time when the process ended.

That gives me some opportunities. For Application Engine programs, I can measure the amount of time taken to posting report content, separately from the process execution time.  This query shows me that this particular process took 49 seconds, but the report output took a further 9 seconds to post.

SELECT r.begindttm begindttm
, NVL(l.enddttm, r.enddttm) enddttm
, (NVL(l.enddttm, r.enddttm)-r.begindttm)*86400 exec_secs
, r.enddttm posttime
, (r.enddttm-NVL(l.enddttm, r.enddttm))*86400 post_secs
FROM sysadm.psprcsrqst r
    LEFT OUTER JOIN sysadm.ps_bat_timings_log l
    ON l.process_instance = r.prcsinstance
WHERE r.prcsinstance = 2920185

BEGINDTTM           ENDDTTM              EXEC_SECS POSTTIME             POST_SECS
------------------- ------------------- ---------- ------------------- ----------
10:51:13 11/06/2010 10:52:02 11/06/2010         49 10:52:11 11/06/2010          9  

For more detail on the Flashback Query syntax see the Oracle SQL Reference.