Instrumentation

Learnt something recently from oracle product documentation, its about setting use full session information for monitoring long running operation in v$session_longops dynamic table.

Session - 1

rajesh@ORCL> create or replace procedure p(p_limit in number)
  2  as
  3     l_rindex BINARY_INTEGER default dbms_application_info.set_session_longops_nohint;
  4     l_slno     BINARY_INTEGER default dbms_application_info.set_session_longops_nohint;
  5
  6  begin
  7     for x in 1..p_limit
  8     loop
  9             dbms_lock.sleep(x);
 10             dbms_application_info.set_session_longops(
 11                     rindex  => l_rindex,
 12                     slno    => l_slno,
 13                     op_name => 'Procedure p',
 14                     target  => p_limit,
 15                     context => x,
 16                     sofar   => x,
 17                     totalwork => p_limit,
 18                     target_desc => 'Working for procedure p',
 19                     units           => 'Seconds'
 20             );
 21     end loop;
 22  end p;
 23  /

Procedure created.

Elapsed: 00:00:00.06
rajesh@ORCL>
rajesh@ORCL>
rajesh@ORCL> select userenv('sid') from dual;

USERENV('SID')
--------------
            15

Elapsed: 00:00:00.00
rajesh@ORCL>
rajesh@ORCL>
rajesh@ORCL> exec p(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:55.06

Session - 2

rajesh@ORCL> select userenv('sid') from dual;

USERENV('SID')
--------------
             9

Elapsed: 00:00:00.00
rajesh@ORCL>
rajesh@ORCL> exec p(10);

PL/SQL procedure successfully completed.

Elapsed: 00:00:55.04

Session - 3

rajesh@ORCL> exec print_table (' select * from v$session_longops where time_remaining > 0 ');
     SID----------------- 9
     SERIAL#------------- 1565
     OPNAME-------------- Procedure p
     TARGET-------------- 10
     TARGET_DESC--------- Working for procedure p
     SOFAR--------------- 5
     TOTALWORK----------- 10
     UNITS--------------- Seconds
     START_TIME---------- 25-SEP-10
     LAST_UPDATE_TIME---- 25-SEP-10
     TIMESTAMP-----------
     TIME_REMAINING------ 13
     ELAPSED_SECONDS----- 13
     CONTEXT------------- 5
     MESSAGE------------- Procedure p: Working for procedure p 10: 5 out of 10 Seconds done
     USERNAME------------ RAJESH
     SQL_ADDRESS--------- 2576CE60
     SQL_HASH_VALUE------ 3124956440
     SQL_ID-------------- 32rn81yx4638s
     SQL_PLAN_HASH_VALUE- 0
     SQL_EXEC_START------ 25-SEP-10
     SQL_EXEC_ID--------- 16777217
     SQL_PLAN_LINE_ID----
     SQL_PLAN_OPERATION--
     SQL_PLAN_OPTIONS----
     QCSID--------------- 0

     SID----------------- 15
     SERIAL#------------- 961
     OPNAME-------------- Procedure p
     TARGET-------------- 10
     TARGET_DESC--------- Working for procedure p
     SOFAR--------------- 4
     TOTALWORK----------- 10
     UNITS--------------- Seconds
     START_TIME---------- 25-SEP-10
     LAST_UPDATE_TIME---- 25-SEP-10
     TIMESTAMP-----------
     TIME_REMAINING------ 14
     ELAPSED_SECONDS----- 9
     CONTEXT------------- 4
     MESSAGE------------- Procedure p: Working for procedure p 10: 4 out of 10 Seconds done
     USERNAME------------ RAJESH
     SQL_ADDRESS--------- 2576CE60
     SQL_HASH_VALUE------ 3124956440
     SQL_ID-------------- 32rn81yx4638s
     SQL_PLAN_HASH_VALUE- 0
     SQL_EXEC_START------ 25-SEP-10
     SQL_EXEC_ID--------- 16777218
     SQL_PLAN_LINE_ID----
     SQL_PLAN_OPERATION--
     SQL_PLAN_OPTIONS----
     QCSID--------------- 0


PL/SQL procedure successfully completed.