Hi Tom

I know you are out of the country this week hopefully
you'll get to read this whenever you can find time.

I've gone through all the v$session_longops threads
and read the chapters in your book on dbms_app_info as well.

problem:
we have a feature in our third party software that allows
for importing data through a functionality called Lockbox.

When we have large files for importing through this module,
(approx 10,000 rows)...the entire system appears to just 
hang. When we have smaller files(100,600,1000 rows) the
function performs with no problems(or so it seems in the
foreground).

I copied the dbms_application_info and showsql scripts
from here(website)and tried to apply them via reading
your instructions in appendix A of your book.
Not sure if I am using them correctly however I am
pasting the results here:
============================================================
SQL> declare
  2   l_owner varchar2(30) default 'GUI';
  3   cnt number default 0;
  4  begin
  5    dbms_application_info.set_client_info('owner= '||l_owner);
  6    for x in(select * from user_jobs where user=l_owner)
  7     Loop
  8       cnt := cnt + 1;
  9       dbms_application_info.set_action('processing row '||cnt);
 10     End Loop;
 11  end;
 12  /
SQL> show errors;
No errors.
SQL> @showsql

USERNAME               SID    SERIAL# PROCESS   STATUS
--------------- ---------- ---------- --------- ----------
GUI                      7        319           ACTIVE
GUI                     16        915 1664:316  ACTIVE
--------------------
GUI(16,915) ospid = 1664:316 program = SQLPLUSW.EXE
Wednesday 10:40  Wednesday 10:42 last et = 0
SELECT USERNAME || '('  || SID  || ','  || SERIAL#  || ') ospid = '  || PROCESS
|| ' program = '  || PROGRAM  USERNAME,TO_CHAR(LOGON_TIME,' Day HH24:MI')
LOGON_TIME,TO_CHAR(SYSDATE,' Day HH24:MI') CURRENT_TIME,SQL_ADDRESS,LAST_CALL_ET
FROM V$SESSI
--------------------
GUI(7,319) ospid =  program =
Wednesday 10:32  Wednesday 10:42 last et = 526
SELECT  distinct(p.idnumber)  FROM phone ph, salutations s1, salutations s2,
additional_demographics ad, prospect p, address_view a  WHERE p.idnumber !=
:p_id    and p.salutcode = s1.salutcode(+) and p.csalutcode = s2.salutcode(+)
and p.idnumber = ad

USERNAME        MODULE          ACTION          CLIENT_INFO
--------------- --------------- --------------- ------------------------------
GUI(16,915)     01@ showsql.sql                 owner= GUI
SQL> /

USERNAME        MODULE          ACTION          CLIENT_INFO
--------------- --------------- --------------- ------------------------------
GUI(16,915)     SQL*Plus                        owner= GUI
SQL> 
============================================================

The session in question (7,319)...doesn't appear to be doing
anything although it says 'ACTIVE'.

I also ran a trace and tkprof, here is the result:

TKPROF: Release 8.1.7.0.0 - Production on Wed Jan 14 11:00:07 2004

(c) Copyright 2000 Oracle Corporation.  All rights reserved.

Trace file: ora00184.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

alter session set sql_trace true


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.01       0.01          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.01       0.01          0          0          0           0

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 12     (recursive depth: 1)
********************************************************************************

BEGIN dbms_session.set_sql_trace(TRUE); END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          2          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          2          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 12  
********************************************************************************

select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1 
from
 obj$ where owner#=:1 and name=:2 and namespace=:3 and(remoteowner=:4 or 
  remoteowner is null and :4 is null)and(linkname=:5 or linkname is null and 
  :5 is null)and(subname=:6 or subname is null and :6 is null)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          5          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          0          5          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

select /*+ index(idl_sb4$ i_idl_sb41) +*/ max(version)   
from
 idl_sb4$ where obj#=:1 and version<=:2 and   (part=0 or part=2) and piece#=0
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          4          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          4          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece 
from
 idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        3      0.00       0.00          1          8          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          1          8          0           2

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece 
from
 idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          1          5          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          1          5          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece 
from
 idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.02          1          5          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.02          1          5          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece 
from
 idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          1          7          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          1          7          0           2

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

select col#, grantee#, privilege#,max(nvl(option$,0)) 
from
 objauth$ where obj#=:1 and col# is not null group by privilege#, col#, 
  grantee# order by col#, grantee#


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          2          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          2          0           0

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

select grantee#,privilege#,nvl(col#,0),max(nvl(option$,0)) 
from
 objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by 
  grantee#


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          3          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************

declare
 l_owner varchar2(30) default 'GUI';
 cnt number default 0;
begin
  dbms_application_info.set_client_info('owner= '||l_owner);
  for x in(select * from all_objects where user=l_owner)
   Loop
     cnt := cnt + 1;
     dbms_application_info.set_action('processing row '||cnt);
   End Loop;
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.05       0.06          0          0          0           0
Execute      1     24.74      44.76          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3     24.79      44.82          0          0          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 12  
********************************************************************************

select node,owner,name 
from
 syn$ where obj#=:1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          3          0           1

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 2)
********************************************************************************

SELECT *   
FROM
 ALL_OBJECTS  WHERE USER = :b1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch    36571     14.18      14.36         53     602663          8       36570
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    36575     14.18      14.36         53     602663          8       36570

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 12     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
  34895  FILTER 
  35015   FILTER 
  35014    NESTED LOOPS 
     63     TABLE ACCESS FULL USER$ 
  35014     TABLE ACCESS BY INDEX ROWID OBJ$ 
  35076      INDEX RANGE SCAN (object id 34)
      1   FIXED TABLE FULL X$KZSPR 
      0   FIXED TABLE FULL X$KZSPR 
      0   FIXED TABLE FULL X$KZSPR 
      0   FIXED TABLE FULL X$KZSPR 
      0   FIXED TABLE FULL X$KZSPR 
      0   FIXED TABLE FULL X$KZSPR 
      0   FIXED TABLE FULL X$KZSPR 
      1   FIXED TABLE FULL X$KZSPR 
      1   FIXED TABLE FULL X$KZSPR 
      1   FIXED TABLE FULL X$KZSPR 
      1   FIXED TABLE FULL X$KZSPR 
      1   FIXED TABLE FULL X$KZSPR 
      1   FIXED TABLE FULL X$KZSPR 
      1   FIXED TABLE FULL X$KZSPR 
  21641   NESTED LOOPS 
 252189    FIXED TABLE FULL X$KZSRO 
 238861    TABLE ACCESS BY INDEX ROWID OBJAUTH$ 
 238861     INDEX RANGE SCAN (object id 101)
   2993   TABLE ACCESS BY INDEX ROWID IND$ 
   3008    INDEX UNIQUE SCAN (object id 36)

********************************************************************************

select distinct(-privilege#),nvl(option$,0) 
from
 sysauth$ where grantee#=:1 and privilege#<0


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        9      0.00       0.00          0          0          0           0
Execute      9      0.00       0.00          0          0          0           0
Fetch      157      0.00       0.00          0         19          0         148
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      175      0.00       0.00          0         19          0         148

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: SYS   (recursive depth: 2)



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.05       0.06          0          0          0           0
Execute      2     24.74      44.76          0          2          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     24.79      44.82          0          2          0           2

Misses in library cache during parse: 0


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       20      0.00       0.00          0          0          0           0
Execute     22      0.01       0.01          0          0          0           0
Fetch    36744     14.18      14.38         57     602724          8       36728
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    36786     14.19      14.39         57     602724          8       36728

Misses in library cache during parse: 0

    6  user  SQL statements in session.
   18  internal SQL statements in session.
   24  SQL statements in session.
********************************************************************************
Trace file: ora00184.trc
Trace file compatibility: 8.00.04
Sort options: default

       1  session in tracefile.
       6  user  SQL statements in trace file.
      18  internal SQL statements in trace file.
      24  SQL statements in trace file.
      14  unique SQL statements in trace file.
   73525  lines in trace file.
============================================================
I know this is lengthy and you are very busy...whenever
you get a chance to look this over and help me decipher
what this output means that would be great and extremely
helpful.

take care..
















 

do you mean the code needs to be inserted within the package
body that executes the Lockbox procedure or process?...
trying to get the hang of this stuff.

thanks for taking the time to respond..

Hi Tom,
I ran the following SQL.

select * from v$sql,v$session_longops where sql_address = address and sql_hash_value = hash_value order by totalwork desc
Snap shot of results..

For some SQL's
TOTALWORK = 15038520810882992217
START_TIME = 1-Jan-1988 12:00:01 AM
MESSAGE = : !šp : 15038520810882992217 out of 15038520810882992217 ø done
TIME_REMAINING = 0
etc..

1) What is this TOTALWORK and why is this so high ? Is some thing wrong with the query.
2) START_TIME is 1988 , the project was not een started at that time. For some SQL's I see start_time as 2021. Who sets this parameter.
3)We rebooted Database server recently than why it is still showing dated 1988 SQL's.
4) Am i running the correct query to find out long running queries.

Thanks in advance.

Hi, Tom,
I am using dbms_application_info to show user how many "cases" were processed and it works fine as long as nobody does anything in different session. When somebody runs something in another session v$session_longops view gets overwritten by whatever another session does and I have no information on job in question.
Here is a piece of code I found in your book that I used for our application:

l_nohint NUMBER DEFAULT dbms_application_info.set_session_longops_nohint;
l_rindex NUMBER DEFAULT l_nohint;
l_slno NUMBER;
rindex BINARY_INTEGER;
slno BINARY_INTEGER;
totalwork NUMBER;
sofar NUMBER;
obj BINARY_INTEGER;
begin

.....
--I have some logic here including incremented x to count number of "cases" processed, but this logic is not relevant to my question so I am omitting it...

--v12.2 Call dbms_application_info to load module
--name, #case that had been processed, number of
--cases already
--processed and number of cases to be processed

dbms_application_info.set_session_longops
( rindex => l_rindex,
slno => l_slno,
op_name => 'Gen_Tdl',
target => case_rec.case_id,
target_desc => 'Case: ',
context => 0,
sofar => x,
totalwork => intCandCnt,
units => 'cases');

Did I miss something? Is it possible to force v$session_longops to write info only on a job I need to monitor?

Thank you

If I run the following in two different sessions -- I get two different entries in v$session_longops.

what do you see?

ops$tkyte@ORA9IR2> declare
  2      l_nohint number default dbms_application_info.set_session_longops_nohint;
  3      l_rindex number default l_nohint;
  4      l_slno   number;
  5  begin
  6      for i in 1 .. 10
  7      loop
  8          dbms_lock.sleep(2);
  9          dbms_application_info.set_session_longops
 10          ( rindex =>  l_rindex,
 11            slno   =>  l_slno,
 12            op_name => 'my long running operation',
 13            target  =>  1234,
 14            target_desc => '"msg description"',
 15            context     => 0,
 16            sofar       => i,
 17            totalwork   => 10,
 18            units       => 'loops'
 19          );
 20      end loop;
 21  end;
 22  /


use:

select * from v$session_longops where time_remaining > 0

to monitor them..
 

Tom, thank you, I can now see information on my run even though I am running another process in a different session, BUT v$session_longops returns not the last entry, but multiple rows (until today it returned only one row). I have a view based on v$session_longops:

CREATE OR REPLACE VIEW GEN_PROGRESS ( OPNAME,
AMESSAGE, BMESSAGE, CMESSAGE ) AS select RPAD(opname,10,' '),RPAD('Case '||target||
' had been processed',35,' ') Amessage,
RPAD(sofar||' of '||totalwork||' cases done',25,' ') Bmessage,
RPAD(totalwork-sofar||' cases left',16, ' ') Cmessage
from v$session_longops l, v$session s
where l.sid=s.sid and l.serial# = s.serial#
AND L.username='IPVFB_TEST'
AND TRUNC(L.LAST_UPDATE_TIME)=TRUNC(SYSDATE)
AND opname IN('Gen_Tdl', 'Ceload');

And here is an example of what results I am getting now:

select opname, amessage, bmessage from GEN_PROGRESS where rownum<10

OPNAME AMESSAGE BMESSAGE
Gen_Tdl Case 200 had been processed 1 of 3512 cases done
Gen_Tdl Case 5200 had been processed 2 of 3512 cases done
Gen_Tdl Case 6100 had been processed 3 of 3512 cases done
Gen_Tdl Case 6800 had been processed 4 of 3512 cases done
Gen_Tdl Case 7400 had been processed 5 of 3512 cases done
Gen_Tdl Case 7500 had been processed 6 of 3512 cases done
Gen_Tdl Case 7600 had been processed 7 of 3512 cases done
Gen_Tdl Case 7800 had been processed 8 of 3512 cases done
Gen_Tdl Case 9300 had been processed 9 of 3512 cases done

Until today, this view would return only one row - the last one.

Am I doing something wrong again?

Thank you

When I run your code in one session and "my" code in another session - "my code" I modified by calling
dbms_lock.sleep(2); - I do not see information on my main run, but see information on "your" run

Tom,
I was not able to reproduce it by writing small codes. We have 4 very large packages, thousands lines of code that do hundreds of different things. But I can tell you what it does and what I noticed about v$session_longops. The Application runs "cases" case by case ("Case loop") and process each customer in a case ("Customer loop") and populates one or another group of tables depending on flag - one group for valued data and another group for data errors. Cases may have from 1 to 100 000 customers. I call dbms_session_info after case is processed in a "case loop". When I started working on it I noticed that if Oracle performs full table scan then v$session_longops gets overwritten with information on this query. I got rid of full scans and everything went beautifully. The view I sent to you shows to the user how many cases were processed and which case had just been processed. Yesterday I was doing something else in DEV and so did my team lead and after I started application I saw that my view was empty. I looked in v$session_longops and noticed that it was full of crap and did not have any information on application I ran. After I added dbms_lock.sleep(2) call, information appeared, but it was not one row as before, but many rows - for each case (I sent you an example). When I ran your little code from another session, information on the "main" process was suppressed by this run. When I ran your code from 2 different sessions v$session_longops showed data first on one session and then on another, I mean it was always 1 row, not 2. Although Prod runs fine I will do everything to understand exactly what v$session_longops does and how it behaves depending on the process. I don't want you to spend time on it, but if you have an idea or "suspicion" I would very much appreciate it.
Thank you

Tom,
I am in complete darkness. 
Everything bad started happening after - as I found out looking at trc files - somebody rebounced db. Who did what I don't know. Our DBA team says it weren't them. 
I noticed error in trc:
Errors in file h:\oracle\admin\ipvd\udump\ORA01444.TRC:
ORA-00604: error occurred at recursive SQL level 1
ORA-04031: unable to allocate 4032 bytes of shared memory ("shared pool","java/lang/StringSYS","joxlod: in ehe","ioc_allocate_pal")
ORA-06512: at "SYS.DBMS_JAVA", line 0
ORA-06512: at line 2

Our DBA corrected it and rebounced db. After that I started getting multiply records as the day before yesterday when I first emailed you. It was easy to reproduce, so here is test:

create table f(g number);

Table created.

create or replace procedure long_proc as
rindex       pls_integer := dbms_application_info.set_session_longops_nohint;
 slno         pls_integer; 
                                        -- Name of task
op_name      varchar2(64) := 'long_proc';

   target       pls_integer := 0;        -- ie. The object being worked on
    context      pls_integer;             -- Any info
     sofar        number;                  -- how far proceeded
   totalwork    number := 1000000;       -- finished when sofar=totalwork
 
                                           -- desc of target
      target_desc  varchar2(32) := 'A long running procedure';
 
      units        varchar2(32) := 'inserts';                -- unit of sofar and totalwork
   begin
  
  dbms_application_info.set_module('long_proc',null);

   dbms_application_info.set_session_longops (
     rindex,
     slno);
 
   for sofar in 0..totalwork loop
  
     insert into f values (sofar);
 
      if mod(sofar,1000) = 0 then
       dbms_application_info.set_session_longops (
         rindex,
          slno,
         op_name,
         target,
         context,
          sofar,
          totalwork,
          target_desc,
         units);
   
     end if;
  
    end loop;
  end long_proc;
  /

Procedure created.

exec SQL> EXEC  long_proc;

----------------------------
another session:

select time_remaining,sofar,elapsed_seconds 
from v$session_longops l, v$session s 
where l.sid=s.sid and l.serial# = s.serial# and s.module='long_proc'


TIME_REMAINING    SOFAR    ELAPSED_SECONDS
0    1    0
0    2    0
0    3    0
0    4    0
0    5    0
0    6    0
0    7    0
0    8    0
0    9    0
0    10    0
0    11    0
0    12    0
0    13    0
0    14    0
0    15    0
0    16    0
0    17    0
0    18    0
0    19    0
0    20    0
0    21    0
0    22    0
0    23    0
0    24    0
0    25    0
0    26    0
0    27    0
0    28    0
0    29    0
0    30    0
0    31    0
0    32    0
0    33    0
0    34    0
0    35    0
0    36    0
0    37    0
0    38    0
0    297076716    515939805
0    1    0
0    2    0
0    3    0
0    4    0
0    5    0
0    6    0
0    7    0
0    8    0
0    9    0
0    10    0
0    0    515939994
0    1    0
0    283494596    515522199
0    2    0
0    297121460    515939997
0    3    0
0    4    0
0    5    0
0    6    0
0    7    0
0    8    0
0    0    0


SQL> EXEC  long_proc;

PL/SQL procedure successfully completed.

 

as stated:

you want to add "and time_remaining > 0" for sure to that (else you see junk for 
sessions that reuse sids or sids that finished the job)


you will see complete GARBARGE in there unless you add that predicate.


ops$tkyte@ORA9IR2> select count(*) from v$session_longops where time_remaining > 0;
 
  COUNT(*)
----------
         1
 
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> exec print_table( 'select * from v$session_longops where time_remaining > 0')
SID                           : 10
SERIAL#                       : 530
OPNAME                        : No Op
TARGET                        :
TARGET_DESC                   : unknown target
SOFAR                         : 717000
TOTALWORK                     : 1000000
UNITS                         :
START_TIME                    : 07-may-2004 13:22:24
LAST_UPDATE_TIME              : 07-may-2004 13:22:55
TIME_REMAINING                : 12
ELAPSED_SECONDS               : 31
CONTEXT                       : 131072
MESSAGE                       : No Op: unknown target : 717000 out of
1000000  done
USERNAME                      : OPS$TKYTE
SQL_ADDRESS                   : 59CB6714
SQL_HASH_VALUE                : 1742325902
QCSID                         : 0
-----------------
 
PL/SQL procedure successfully completed.
 
is what I observe. 

Tom,
When I do
and time_remaining > 0;
I have this (code is still running):

TIME_REMAINING SOFAR ELAPSED_SECONDS
0 0 0
0 0 0

Yes!
Bug:1568589> 3164688 RDBMS: V$SESSION_LONGOPS may show garbage data or core dump (in ksuglop) if hash joins are used anywhere on the system

But the bug is not viewable by the public. Outstanding.

Hi, Tom,
v$session_longops no longer works properly after latest Microsoft hotfixes were applied. Metalink got correct results running the code I sent to them on the same Oracle version. You think it is OK if I use v$session instead? Right now it works great in DEV (I call dbms_application_info.set_module and dbms_application_info.set_client_info), but I am concerned about "unintended consequences".
What do you think?

Hello Tom,

is it possible to have more than one entry in v$session_longops for a single session (using set_session_longop)?

Here is my test case: I produce one record (with OPNAME='opname2'), then I try to produce another record (OPNAME='opname', and *not* using the RINDEX from the previous record), but if I query v$session_longops after that, the first record has disappeared from the view.

I would expect there to be two rows in v$session_longops, one for opname and the other for opname2.

Thanks in advance,
Ekkehard


> sqlplus test

SQL*Plus: Release 8.1.7.0.0 - Production on Di Mär 8 20:30:58 2005
...
Connected to:
Oracle8i Enterprise Edition Release 8.1.7.0.1 - Production
With the Partitioning option
JServer Release 8.1.7.0.1 - Production

test@TESTING.APP> select opname from v$session_longops where time_remaining>0;

no rows selected

test@TESTING.APP> declare
2 rindex integer:= dbms_application_info.set_session_longops_nohint;
3 slno integer;
4 begin
5 dbms_application_info.set_session_longops(
6 rindex => rindex,
7 slno => slno,
8 op_name => 'opname2',
9 target => 0,
10 target_desc => 'N/A',
11 context => 0,
12 sofar => 1,
13 totalwork => 10,
14 units => 'units'
15 );
16 dbms_lock.sleep(5);
17 dbms_application_info.set_session_longops(
18 rindex => rindex,
19 slno => slno,
20 op_name => 'opname2',
21 target => 0,
22 target_desc => 'N/A',
23 context => 0,
24 sofar => 5,
25 totalwork => 10,
26 units => 'units'
27 );
28 end;
29 /
show errors

PL/SQL procedure successfully completed.

test@TESTING.APP> No errors.
test@TESTING.APP> select opname from v$session_longops where time_remaining>0;

OPNAME
----------------------------------------------------------------
opname2

test@TESTING.APP> declare
2 rindex integer:= dbms_application_info.set_session_longops_nohint;
3 slno integer;
4 begin
5 dbms_application_info.set_session_longops(
6 rindex => rindex,
7 slno => slno,
8 op_name => 'opname',
9 target => 0,
10 target_desc => 'N/A',
11 context => 0,
12 sofar => 1,
13 totalwork => 10,
14 units => 'units'
15 );
16 dbms_lock.sleep(5);
17 dbms_application_info.set_session_longops(
18 rindex => rindex,
19 slno => slno,
20 op_name => 'opname',
21 target => 0,
22 target_desc => 'N/A',
23 context => 0,
24 sofar => 5,
25 totalwork => 10,
26 units => 'units'
27 );
28 end;
29 /
show errors

PL/SQL procedure successfully completed.

test@TESTING.APP> No errors.
test@TESTING.APP> select opname from v$session_longops where time_remaining>0;

OPNAME
----------------------------------------------------------------
opname

test@TESTING.APP> declare
2 rindex integer:= dbms_application_info.set_session_longops_nohint;
3 slno integer;
4 begin
5 dbms_application_info.set_session_longops(
6 rindex => rindex,
7 slno => slno,
8 op_name => 'opname2',
9 target => 0,
10 target_desc => 'N/A',
11 context => 0,
12 sofar => 1,
13 totalwork => 10,
14 units => 'units'
15 );
16 dbms_lock.sleep(5);
17 dbms_application_info.set_session_longops(
18 rindex => rindex,
19 slno => slno,
20 op_name => 'opname2',
21 target => 0,
22 target_desc => 'N/A',
23 context => 0,
24 sofar => 5,
25 totalwork => 10,
26 units => 'units'
27 );
28 end;
29 /
show errors

PL/SQL procedure successfully completed.

test@TESTING.APP> No errors.
test@TESTING.APP> select opname from v$session_longops where time_remaining>0;

OPNAME
----------------------------------------------------------------
opname2

test@TESTING.APP>

i fired one query which updates 3 million rows in a table,after that i realized that i made some mistake on that.so how can i identify&kill the long running query

i fired one query which updates 3 million rows in a table,after that i realized that i made some mistake on that.so how can i identify&kill the long running query

sorry for my english

Hello Tom,

There is certainly an issue with inerweaving (nested?) calls to
DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS on Ora 8.1.7.4.1 (EE).
Here is my test script:

DECLARE
iLONGOPSRow1 BINARY_INTEGER;
nSLNo1 BINARY_INTEGER;
iLONGOPSRow2 BINARY_INTEGER;
nSLNo2 BINARY_INTEGER;
BEGIN
iLONGOPSRow1 := DBMS_APPLICATION_INFO.set_session_longops_nohint;
iLONGOPSRow2 := DBMS_APPLICATION_INFO.set_session_longops_nohint;
FOR I IN 1..3 LOOP
DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS(
iLONGOPSRow1
,nSLNo1
,'OP 1'
,target => NULL
,context => 1
,sofar => I*10
,totalwork => 100
,target_desc => 'Target 1'
,units => 'units 1'
);
IF I = 1 THEN
DBMS_OUTPUT.Put_Line('iLONGOPSRow1 = ' || iLONGOPSRow1);
END IF;
FOR J IN 1..10 LOOP
DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS(
iLONGOPSRow2
,nSLNo2
,'OP 2'
,target => NULL
,context => 2
,sofar => I*10 + J
,totalwork => 101
,target_desc => 'Target 2'
,units => 'units 2'
);
IF J = 1 THEN
DBMS_OUTPUT.Put_Line('iLONGOPSRow2 = ' || iLONGOPSRow2);
END IF;
-- DBMS_LOCK.SLEEP(2);
-- I used home-made dummy instead of SLEEP:
P.P2;
END LOOP;
END LOOP;
END;
/

COLUMN OPNAME FOR A10
COLUMN TARGET FOR A10
COLUMN TARGET_DESC FOR A10
COLUMN CONTEXT FOR 999
COLUMN SOFAR FOR 999999999999
COLUMN TOTALWORK FOR 999999999999
COLUMN UNITS FOR A10
COLUMN REMAINING FOR 999999999
COLUMN ELAPSED FOR 999999999
SELECT
OPNAME
,TARGET
,TARGET_DESC
,CONTEXT
,SOFAR
,TOTALWORK
,UNITS
,START_TIME
,LAST_UPDATE_TIME
,TIME_REMAINING REMAINING
,ELAPSED_SECONDS ELAPSED
FROM V$SESSION_LONGOPS
WHERE
(
-- TIME_REMAINING could be NULL if SOFAR > TOTALWORK on Ora9i:
(L.TIME_REMAINING IS NOT NULL
AND L.TIME_REMAINING <> 0
)
OR L.SOFAR > L.TOTALWORK
)
ORDER L.OPNAME
;

********************************************************************************
That's what I've got on Ora8:

-- After block was finished (row numbers are the same for different calls
-- to SET_SESSION_LONGOPS):

iLONGOPSRow1 = 1
iLONGOPSRow2 = 1
iLONGOPSRow2 = 1
iLONGOPSRow2 = 1

PL/SQL procedure successfully completed.

EMNETT@UTV8>


-- At some point during block execution.
-- V$SESSION_LONGOPS rows are merged and corrupted:

SYSTEM@UTV8> r
1 SELECT ....FROM V$SESSION_LONGOPS L
.........

OPNAME TARGET TARGET_DES CONTEXT SOFAR TOTALWORK UNITS
---------- ---------- ---------- ------- ------------- ------------- ----------
\0 SYS.C_OBJ# 2 29 101 ¥´Õ{eL
²\Ìe

********************************************************************************
And that's what I've got on Ora 9.2.0.6.0

-- After block was finished (row numbers are different for different calls
-- to SET_SESSION_LONGOPS):

iLONGOPSRow1 = 198
iLONGOPSRow2 = 199
iLONGOPSRow2 = 199
iLONGOPSRow2 = 199

PL/SQL procedure successfully completed.

-- At some point during block execution. V$SESSION_LONGOPS has distinct rows:
SYSTEM@TEST9> r
1 SELECT ....FROM V$SESSION_LONGOPS L
.........

OPNAME TARGET TARGET_DES CONTEXT SOFAR TOTALWORK UNITS .....
---------- ---------- ---------- ------- ------------- ------------- -------
OP 1 Target 1 1 30 100 units 1 .......
OP 2 110494401 Target 2 2 33 101 units 2


Is there any workaround for Ora8?

Thanks is advance

"data in v$session_longops hangs out until those slots are needed for reuse"

We are planning to use dbms_application_info and v$session_longops for tracking the current status of our batch processes.

1. But is it a safe to assume that info from one session will not be overwritten by another?

2. What is the limit of data one session can enter in v$session_longops?

This can be tested but I am a bit worried about stress testing our client's dev database, not sure if it will mess with the dictionary. So would like to know the theory behind this.

Thanks

</code> http://groups.google.co.uk/groups?hl=en&lr=&th=966be6d1aef53fc1 <code>

Hello,

Column TARGET in V$SESSION_LONGOPS is VARCHAR2(64), but Procedure DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS wants a BINARY_INTEGER (Oracle 9.2.0.6 on SuSE Linux SLES8). Why? Do you know of any (wrapped) Package/Procedure supplied by Oracle or an other Company, which takes a VARCHAR2 instead of a NUMBER for Column TARGET? The Target in our Web-Application is sometimes a Charcter-String (for example "4_3_1_2" or "4.2.5.4", of course with changing TARGET_DESC) and I don't want to give the User the ID for Information instead (Column MESSAGE).

Thank you
Markus

Hi Tom,

When we run 1 batch job, it works fine for 30-40 mins(means it does some DMLs, select..), after that it just runs 2 SQLs and does lots of PIO and LIO and it runs for forever...does that mean it got stuck in some loop or something else ?
Here is the output of v$session_longops.

begin
print_table('select b.* from v$session a, v$session_longops b where a.sid = b.sid and a.serial# = b.serial#');
end;

SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11790
TOTALWORK : 11790
UNITS : Blocks
START_TIME : 14-sep-2005 00:14:18
LAST_UPDATE_TIME : 14-sep-2005 00:14:27
TIME_REMAINING : 0
ELAPSED_SECONDS : 9
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11790 out of 11790 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11539
TOTALWORK : 11539
UNITS : Blocks
START_TIME : 13-sep-2005 03:00:32
LAST_UPDATE_TIME : 13-sep-2005 03:00:50
TIME_REMAINING : 0
ELAPSED_SECONDS : 18
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11539 out of 11539 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11496
TOTALWORK : 11496
UNITS : Blocks
START_TIME : 12-sep-2005 23:36:38
LAST_UPDATE_TIME : 12-sep-2005 23:36:45
TIME_REMAINING : 0
ELAPSED_SECONDS : 7
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11496 out of 11496 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11246
TOTALWORK : 11246
UNITS : Blocks
START_TIME : 12-sep-2005 03:00:23
LAST_UPDATE_TIME : 12-sep-2005 03:00:42
TIME_REMAINING : 0
ELAPSED_SECONDS : 19
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11246 out of 11246 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11821
TOTALWORK : 11821
UNITS : Blocks
START_TIME : 14-sep-2005 03:00:28
LAST_UPDATE_TIME : 14-sep-2005 03:00:40
TIME_REMAINING : 0
ELAPSED_SECONDS : 12
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11821 out of 11821 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11491
TOTALWORK : 11491
UNITS : Blocks
START_TIME : 12-sep-2005 23:04:26
LAST_UPDATE_TIME : 12-sep-2005 23:04:36
TIME_REMAINING : 0
ELAPSED_SECONDS : 10
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11491 out of 11491 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11507
TOTALWORK : 11507
UNITS : Blocks
START_TIME : 13-sep-2005 00:11:49
LAST_UPDATE_TIME : 13-sep-2005 00:11:58
TIME_REMAINING : 0
ELAPSED_SECONDS : 9
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11507 out of 11507 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Index Fast Full Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 9859
TOTALWORK : 9859
UNITS : Blocks
START_TIME : 13-sep-2005 00:11:31
LAST_UPDATE_TIME : 13-sep-2005 00:11:40
TIME_REMAINING : 0
ELAPSED_SECONDS : 9
CONTEXT : 0
MESSAGE : Index Fast Full Scan: DORIS.CAP_ENTITY_WORK: 9859 out of 9859 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF74A0
SQL_HASH_VALUE : 4239771088
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Index Fast Full Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 9859
TOTALWORK : 9859
UNITS : Blocks
START_TIME : 12-sep-2005 23:04:14
LAST_UPDATE_TIME : 12-sep-2005 23:04:26
TIME_REMAINING : 0
ELAPSED_SECONDS : 12
CONTEXT : 0
MESSAGE : Index Fast Full Scan: DORIS.CAP_ENTITY_WORK: 9859 out of 9859 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF74A0
SQL_HASH_VALUE : 4239771088
QCSID : 0

But if i kill that session above statement returns 0 rows..

Thanks
kapil

Hi Tom,

When we run 1 batch job, it works fine for 30-40 mins(means it does some DMLs, select..), after that it just runs 2 SQLs and does lots of PIO and LIO and it runs for forever...does that mean it got stuck in some loop or something else ?
Here is the output of v$session_longops.

begin
print_table('select b.* from v$session a, v$session_longops b where a.sid = b.sid and a.serial# = b.serial#');
end;

SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11790
TOTALWORK : 11790
UNITS : Blocks
START_TIME : 14-sep-2005 00:14:18
LAST_UPDATE_TIME : 14-sep-2005 00:14:27
TIME_REMAINING : 0
ELAPSED_SECONDS : 9
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11790 out of 11790 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11539
TOTALWORK : 11539
UNITS : Blocks
START_TIME : 13-sep-2005 03:00:32
LAST_UPDATE_TIME : 13-sep-2005 03:00:50
TIME_REMAINING : 0
ELAPSED_SECONDS : 18
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11539 out of 11539 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11496
TOTALWORK : 11496
UNITS : Blocks
START_TIME : 12-sep-2005 23:36:38
LAST_UPDATE_TIME : 12-sep-2005 23:36:45
TIME_REMAINING : 0
ELAPSED_SECONDS : 7
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11496 out of 11496 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11246
TOTALWORK : 11246
UNITS : Blocks
START_TIME : 12-sep-2005 03:00:23
LAST_UPDATE_TIME : 12-sep-2005 03:00:42
TIME_REMAINING : 0
ELAPSED_SECONDS : 19
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11246 out of 11246 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11821
TOTALWORK : 11821
UNITS : Blocks
START_TIME : 14-sep-2005 03:00:28
LAST_UPDATE_TIME : 14-sep-2005 03:00:40
TIME_REMAINING : 0
ELAPSED_SECONDS : 12
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11821 out of 11821 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11491
TOTALWORK : 11491
UNITS : Blocks
START_TIME : 12-sep-2005 23:04:26
LAST_UPDATE_TIME : 12-sep-2005 23:04:36
TIME_REMAINING : 0
ELAPSED_SECONDS : 10
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11491 out of 11491 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Table Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 11507
TOTALWORK : 11507
UNITS : Blocks
START_TIME : 13-sep-2005 00:11:49
LAST_UPDATE_TIME : 13-sep-2005 00:11:58
TIME_REMAINING : 0
ELAPSED_SECONDS : 9
CONTEXT : 0
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11507 out of 11507 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF6F70
SQL_HASH_VALUE : 3418523209
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Index Fast Full Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 9859
TOTALWORK : 9859
UNITS : Blocks
START_TIME : 13-sep-2005 00:11:31
LAST_UPDATE_TIME : 13-sep-2005 00:11:40
TIME_REMAINING : 0
ELAPSED_SECONDS : 9
CONTEXT : 0
MESSAGE : Index Fast Full Scan: DORIS.CAP_ENTITY_WORK: 9859 out of 9859 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF74A0
SQL_HASH_VALUE : 4239771088
QCSID : 0
-----------------
SID : 14
SERIAL# : 561
OPNAME : Index Fast Full Scan
TARGET : DORIS.CAP_ENTITY_WORK
TARGET_DESC :
SOFAR : 9859
TOTALWORK : 9859
UNITS : Blocks
START_TIME : 12-sep-2005 23:04:14
LAST_UPDATE_TIME : 12-sep-2005 23:04:26
TIME_REMAINING : 0
ELAPSED_SECONDS : 12
CONTEXT : 0
MESSAGE : Index Fast Full Scan: DORIS.CAP_ENTITY_WORK: 9859 out of 9859 Blocks done
USERNAME : DORIS
SQL_ADDRESS : 0700000035AF74A0
SQL_HASH_VALUE : 4239771088
QCSID : 0

But if i kill that session above statement returns 0 rows..

Thanks
kapil

Thanks for your response,I am surprised too that why no of blocks are changing like this:

MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11790 out of 11790 Blocks done
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11539 out of 11539 Blocks done
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11496 out of 11496 Blocks done
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11246 out of 11246 Blocks done
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11821 out of 11821 Blocks done
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11491 out of 11491 Blocks done
MESSAGE : Table Scan: DORIS.CAP_ENTITY_WORK: 11507 out of 11507 Blocks done
MESSAGE : Index Fast Full Scan: DORIS.CAP_ENTITY_WORK: 9859 out of 9859 Blocks done
MESSAGE : Index Fast Full Scan: DORIS.CAP_ENTITY_WORK: 9859 out of 9859 Blocks done

Could you please tell me that in what circumstances it happens like this ?

Thanks
kaps

About table, what ? Could you please eleborate your question a bit.


Thanks

CREATE TABLE CAP_ENTITY_WORK (
SEQ_CCALC_ID NUMBER (9) NOT NULL,
SEQ_CAP_ENTITY_WORK NUMBER (9) NOT NULL,
SEQ_CAP_ELIG_WORK NUMBER (9),
SEQ_PROV_ID NUMBER (9),
SEQ_VEND_ID NUMBER (9),
CAP_ENTITY_CODE VARCHAR2 (3),
CURRENT_RETRO CHAR (1),
CAP_ENTITY_ID VARCHAR2 (3),
SEQ_CAP_VEND_ADDRESS NUMBER (9),
SEQ_PROV_CONTRACT NUMBER,
MAX_ENROLL_LMT NUMBER,
EXCLUDE_INCENTIVE CHAR (1) DEFAULT 'Y',
ACCESS_PROGRAM_ELIGIBLE CHAR (1) DEFAULT 'N',
CONSTRAINT P_CAP_ENTITY_WORK#SQ_CP_ENT_W
PRIMARY KEY ( SEQ_CAP_ENTITY_WORK )
USING INDEX
TABLESPACE CAPWORKIDX PCTFREE 10
STORAGE ( INITIAL 41943040 NEXT 20971520 PCTINCREASE 0 ))
TABLESPACE DIAMOND NOLOGGING
PCTFREE 10
PCTUSED 40
INITRANS 1
MAXTRANS 255
STORAGE (
INITIAL 419430400
NEXT 131072
PCTINCREASE 0
MINEXTENTS 1
MAXEXTENTS 2147483645
FREELISTS 5 FREELIST GROUPS 1 )
NOCACHE;


CREATE INDEX IDX1_CAP_ENTITY_WORK ON
"DORIS".CAP_ENTITY_WORK(SEQ_CCALC_ID, CURRENT_RETRO)
TABLESPACE CAPWORKIDX PCTFREE 10 STORAGE(INITIAL 1048576 NEXT 20971520 PCTINCREASE 0 )
;

CREATE INDEX IDX2_CAP_ENTITY_WORK ON
"DORIS".CAP_ENTITY_WORK(SEQ_CCALC_ID, SEQ_VEND_ID)
TABLESPACE CAPWORKIDX PCTFREE 10 STORAGE(INITIAL 1048576 NEXT 20971520 PCTINCREASE 0 )
;

CREATE INDEX IDX4_CAP_ENTITY_WORK ON
"DORIS".CAP_ENTITY_WORK(SEQ_CCALC_ID, CAP_ENTITY_CODE)
TABLESPACE CAPWORKIDX PCTFREE 10 STORAGE(INITIAL 1048576 NEXT 20971520 PCTINCREASE 0 )
;

CREATE INDEX IDX5_CAP_ENTITY_WORK ON
"DORIS".CAP_ENTITY_WORK(SEQ_PROV_ID, CAP_ENTITY_CODE, CURRENT_RETRO, SEQ_CCALC_ID)
TABLESPACE CAPWORKIDX PCTFREE 10 STORAGE(INITIAL 1048576 NEXT 20971520 PCTINCREASE 0 )
;

CREATE INDEX IDX6_CAP_ENTITY_WORK ON
"DORIS".CAP_ENTITY_WORK(SEQ_PROV_ID, CAP_ENTITY_CODE, SEQ_CCALC_ID, SEQ_VEND_ID)
TABLESPACE DIAMIDX PCTFREE 10 STORAGE(INITIAL 4194304 NEXT 131072 PCTINCREASE 0 )
;

CREATE INDEX IDX7_CAP_ENTITY_WORK ON
"DORIS".CAP_ENTITY_WORK(SEQ_CAP_ENTITY_WORK, CAP_ENTITY_CODE, SEQ_PROV_ID, SEQ_VEND_ID)
TABLESPACE CAPWORKIDX PCTFREE 10 STORAGE(INITIAL 1048576 NEXT 20971520 PCTINCREASE 0 )
;

CREATE INDEX PS_NDX_CAP_ENTITY_WK ON
"DORIS".CAP_ENTITY_WORK(SEQ_CCALC_ID, SEQ_CAP_ELIG_WORK)
TABLESPACE CAPWORKIDX PCTFREE 10 STORAGE(INITIAL 1048576 NEXT 20971520 PCTINCREASE 0 )
;

CREATE INDEX ZIDX01_CAP_ENTY_W#SQ_CALC_ID ON
"DORIS".CAP_ENTITY_WORK(SEQ_CCALC_ID)
TABLESPACE CAPWORKIDX PCTFREE 60 STORAGE(INITIAL 4194304 NEXT 20971520 PCTINCREASE 0 )
;

Before starting the batch process table get truncated, and then that process does lots of insert and lots od select from it.. it grows upto 5-6 million rows. I don't know how to deal with stats/histogram for these kinda of tables.
any suggestion for indexes also ?

thanks
kaps

we truncate just before starting the batch job.
so these are after insert/select and when the batch job is in is in kind of hang stage.
whwn we run the process, it does several stuff like insert/select blah blah.... I could see it through shoqsql.sql. but after an hour or so it just shows that this process is doing 2 sqls only, and lots of PIO and LIO. Above different blocksizes are in that situation....it seems that batch job is doing nothing but just 2 sqls and stuck in some loop...

thanks
kaps

This is what I just did now :)

will post u the result.. Any output from guess mode ? :)

would you suggest to use dbms_profiler also or not ?

thanks

I apologize for using "u" , consider it as "you" please.

Following is the excerpt from the instrumented code:
LOOP
FETCH cur_distinct_entity INTO ls_entity_code, ls_entity_id;
EXIT WHEN cur_distinct_entity%NOTFOUND;
cnt1 := cnt1 + 1;
totwork1 := cur_distinct_entity%rowcount;
l_rindex := 1;

dbms_application_info.set_session_longops(
rindex => l_rindex, slno => l_slno,
op_name => '1st long running operation',
target => 1234, target_desc => '"Distinct Entity"',
context => 0,
sofar => cnt1,
totalwork => totwork1,
units => 'loops' );
---------------------------------------
LOOP
FETCH cur_distinct_vendor INTO li_seq_vend_id;
EXIT WHEN cur_distinct_vendor%NOTFOUND;
hsd_messages.sp_prcssing_mssgs_ctl (
ls_grouping,
ls_procedure_name,
ls_key_name,
ls_key_value,
li_seq_vend_id,
NULL,
NULL,
22494,
TRUE
);
cnt2 := cnt2 + 1;
totwork2 := cur_distinct_vendor%rowcount;
l_rindex := 2;
dbms_application_info.set_session_longops(
rindex => l_rindex, slno => l_slno,
op_name => '2nd long running operation',
target => 1235, target_desc => '"Distinct Vendor"',
context => 0,
sofar => cnt2,
totalwork => totwork2,
units => 'loops' );
-------------------------------------------
actually we put dbms_application_info in all the major loops, following is the output from v$session_longops(it is just 5% of total output)

SID : 10
SERIAL# : 9459
OPNAME : 1st long running operation
TARGET : 1234
TARGET_DESC : "Distinct Entity"
SOFAR : 1
TOTALWORK : 1
UNITS : loops
START_TIME : 15-sep-2005 21:57:06
LAST_UPDATE_TIME : 15-sep-2005 21:57:06
TIME_REMAINING : 0
ELAPSED_SECONDS : 0
CONTEXT : 0
MESSAGE : 1st long running operation: "Distinct Entity" 1234: 1 out of 1 loops done
USERNAME : DORIS
SQL_ADDRESS : 0700000035F7C8B0
SQL_HASH_VALUE : 596181504
QCSID : 0
-----------------
SID : 10
SERIAL# : 9459
OPNAME : 1st long running operation
TARGET : 1234
TARGET_DESC : "Distinct Entity"
SOFAR : 1
TOTALWORK : 1
UNITS : loops
START_TIME : 15-sep-2005 21:45:15
LAST_UPDATE_TIME : 15-sep-2005 21:45:15
TIME_REMAINING : 0
ELAPSED_SECONDS : 0
CONTEXT : 0
MESSAGE : 1st long running operation: "Distinct Entity" 1234: 1 out of 1 loops done
USERNAME : DORIS
SQL_ADDRESS : 0700000035F7C8B0
SQL_HASH_VALUE : 596181504
QCSID : 0
-----------------
SID : 10
SERIAL# : 9459
OPNAME : 1st long running operation
TARGET : 1234
TARGET_DESC : "Distinct Entity"
SOFAR : 1
TOTALWORK : 1
UNITS : loops
START_TIME : 15-sep-2005 21:14:56
LAST_UPDATE_TIME : 15-sep-2005 21:14:56
TIME_REMAINING : 0
ELAPSED_SECONDS : 0
CONTEXT : 0
MESSAGE : 1st long running operation: "Distinct Entity" 1234: 1 out of 1 loops done
USERNAME : DORIS
SQL_ADDRESS : 0700000035F7C8B0
SQL_HASH_VALUE : 596181504
QCSID : 0
-----------------
SID : 10
SERIAL# : 9459
OPNAME : 1st long running operation
TARGET : 1234
TARGET_DESC : "Distinct Entity"
SOFAR : 1
TOTALWORK : 1
UNITS : loops
START_TIME : 15-sep-2005 21:11:29
LAST_UPDATE_TIME : 15-sep-2005 21:11:29
TIME_REMAINING : 0
ELAPSED_SECONDS : 0
CONTEXT : 0
MESSAGE : 1st long running operation: "Distinct Entity" 1234: 1 out of 1 loops done
USERNAME : DORIS
SQL_ADDRESS : 0700000035F7C8B0
SQL_HASH_VALUE : 596181504
QCSID : 0
-----------------
SID : 10
SERIAL# : 9459
OPNAME : 1st long running operation
TARGET : 1234
TARGET_DESC : "Distinct Entity"
SOFAR : 1
TOTALWORK : 1
UNITS : loops
START_TIME : 15-sep-2005 21:23:29
LAST_UPDATE_TIME : 15-sep-2005 21:23:29
TIME_REMAINING : 0
ELAPSED_SECONDS : 0
CONTEXT : 0
MESSAGE : 1st long running operation: "Distinct Entity" 1234: 1 out of 1 loops done
USERNAME : DORIS
SQL_ADDRESS : 0700000035F7C8B0
SQL_HASH_VALUE : 596181504
QCSID : 0
-----------------
SID : 10
SERIAL# : 9459
OPNAME : 1st long running operation
TARGET : 1234
TARGET_DESC : "Distinct Entity"
SOFAR : 1
TOTALWORK : 1
UNITS : loops
START_TIME : 15-sep-2005 21:37:29
LAST_UPDATE_TIME : 15-sep-2005 21:37:29
TIME_REMAINING : 0
ELAPSED_SECONDS : 0
CONTEXT : 0
MESSAGE : 1st long running operation: "Distinct Entity" 1234: 1 out of 1 loops done
USERNAME : DORIS
SQL_ADDRESS : 0700000035F7C8B0
SQL_HASH_VALUE : 596181504
QCSID : 0
-----------------
SID : 10
SERIAL# : 9459
OPNAME : 1st long running operation
TARGET : 1234
TARGET_DESC : "Distinct Entity"
SOFAR : 1
TOTALWORK : 1
UNITS : loops
START_TIME : 15-sep-2005 22:03:57
LAST_UPDATE_TIME : 15-sep-2005 22:03:57
TIME_REMAINING : 0
ELAPSED_SECONDS : 0
CONTEXT : 0
MESSAGE : 1st long running operation: "Distinct Entity" 1234: 1 out of 1 loops done
USERNAME : DORIS
SQL_ADDRESS : 0700000035F7C8B0
SQL_HASH_VALUE : 596181504
QCSID : 0
-----------------
i just greped start_time which is :
grep START_TIME sess_longops.lst
START_TIME : 15-sep-2005 21:57:06
START_TIME : 15-sep-2005 21:45:15
START_TIME : 15-sep-2005 22:12:27
START_TIME : 15-sep-2005 22:09:03
START_TIME : 15-sep-2005 22:20:44
START_TIME : 15-sep-2005 21:37:29
START_TIME : 15-sep-2005 22:22:08
START_TIME : 15-sep-2005 21:48:38
START_TIME : 15-sep-2005 21:55:02
START_TIME : 15-sep-2005 22:07:42
START_TIME : 15-sep-2005 21:59:09
START_TIME : 15-sep-2005 22:26:15
START_TIME : 15-sep-2005 21:41:35
START_TIME : 15-sep-2005 21:38:11
START_TIME : 15-sep-2005 21:38:50
START_TIME : 15-sep-2005 21:57:48
START_TIME : 15-sep-2005 22:28:57
START_TIME : 15-sep-2005 22:20:03
START_TIME : 15-sep-2005 22:05:18
START_TIME : 15-sep-2005 22:14:30
START_TIME : 15-sep-2005 22:16:39
START_TIME : 15-sep-2005 21:55:45
START_TIME : 15-sep-2005 22:21:26
START_TIME : 15-sep-2005 22:03:15
START_TIME : 15-sep-2005 21:47:56
START_TIME : 15-sep-2005 22:18:00
START_TIME : 15-sep-2005 22:13:09
START_TIME : 15-sep-2005 22:30:57
START_TIME : 15-sep-2005 22:04:36
START_TIME : 15-sep-2005 22:11:06
START_TIME : 15-sep-2005 22:23:30
START_TIME : 15-sep-2005 22:01:54
START_TIME : 15-sep-2005 22:29:37
START_TIME : 15-sep-2005 21:54:20
START_TIME : 15-sep-2005 22:18:39
START_TIME : 15-sep-2005 21:53:29
START_TIME : 15-sep-2005 21:42:17
START_TIME : 15-sep-2005 21:35:23
START_TIME : 15-sep-2005 21:47:17
START_TIME : 15-sep-2005 21:43:50
START_TIME : 15-sep-2005 22:22:48
START_TIME : 15-sep-2005 22:02:34
START_TIME : 15-sep-2005 22:31:39
START_TIME : 15-sep-2005 22:15:12
START_TIME : 15-sep-2005 21:49:59
START_TIME : 15-sep-2005 22:24:12
START_TIME : 15-sep-2005 21:52:47
----------------------------------------
I am totally confused while looking at above output. Kindly shed some light on it ? Is it stuck in just first loop ?why ? what is the remedy ?

Thanks

BEGIN

ls_key_value := pi_seq_ccalc_id;
ld_max_term_date := TO_DATE ('01-JAN-2099', 'DD-MON-YYYY');
ld_min_eff_date := TO_DATE ('01-JAN-1950', 'DD-MON-YYYY');
lb_record_found := FALSE;

hsd_messages.sp_prcssing_mssgs_ctl (
ls_grouping,
ls_procedure_name,
ls_key_name,
ls_key_value,
ls_procedure_name,
TO_CHAR (SYSDATE, gs_dateformat || ' HH:MI:SS'),
NULL,
22365,
TRUE
);
COMMIT;


ld_earliest_retro_month := ADD_MONTHS (pi_run_month, -pi_retro_months);

cnt1 := 0; -- CQ 13472 temp;
cnt2 := 0; -- CQ 13472 temp;
cnt3 := 0; -- CQ 13472 temp;
cnt4 := 0; -- CQ 13472 temp;
cnt5 := 0; -- CQ 13472 temp;
distentcnt := 0; -- CQ 13472 temp
distvendcnt := 0; -- CQ 13472 temp
distprovcnt := 0; -- CQ 13472 temp
totvendcnt := 0; -- CQ 13472 temp

OPEN cur_cap_rate_search_type;

LOOP
FETCH cur_cap_rate_search_type INTO ls_rate_search_type;
EXIT WHEN cur_cap_rate_search_type%NOTFOUND;
li_rate_type_cnt := li_rate_type_cnt + 1;
ls_rate_search_type_tbl (li_rate_type_cnt) := ls_rate_search_type;
END LOOP;

li_rate_type_max := li_rate_type_cnt;
OPEN cur_distinct_entity;

/* CQ 13472 temp */
ls_time := to_char(sysdate,'HH:MI:SS');
sp_wrerr('BEFORE DISTINCT ENTITY START : '||ls_time);
/* CQ 13472 temp */

LOOP
FETCH cur_distinct_entity INTO ls_entity_code, ls_entity_id;
EXIT WHEN cur_distinct_entity%NOTFOUND;

/* CQ 13472 temp */
cnt1 := cnt1 + 1;
totwork1 := cur_distinct_entity%rowcount;
l_rindex := 1;

dbms_application_info.set_session_longops(
rindex => l_rindex, slno => l_slno,
op_name => '1st long running operation',
target => 1234, target_desc => '"Distinct Entity"',
context => 0,
sofar => cnt1,
totalwork => totwork1,
units => 'loops' );
/* CQ 13472 temp */

hsd_messages.sp_prcssing_mssgs_ctl (
ls_grouping,
ls_procedure_name,
ls_key_name,
ls_key_value,
ls_entity_code,
ls_entity_id,
NULL,
22493,
TRUE
);
OPEN cur_distinct_vendor;

/* CQ 13472 temp */
ls_time := to_char(sysdate,'HH:MI:SS');
ld_start_vend := sysdate;
sp_wrerr('BEFORE DISTINCT VENDOR START : '||ls_time);
cnt2 := 0; -- CQ 13472 temp;
/* CQ 13472 temp */

LOOP
FETCH cur_distinct_vendor INTO li_seq_vend_id;
EXIT WHEN cur_distinct_vendor%NOTFOUND;
hsd_messages.sp_prcssing_mssgs_ctl (
ls_grouping,
ls_procedure_name,
ls_key_name,
ls_key_value,
li_seq_vend_id,
NULL,
NULL,
22494,
TRUE
);

/* CQ 13472 temp */
cnt2 := cnt2 + 1;
totwork2 := cur_distinct_vendor%rowcount;
l_rindex := 2;

dbms_application_info.set_session_longops(
rindex => l_rindex, slno => l_slno,
op_name => '2nd long running operation',
target => 1235, target_desc => '"Distinct Vendor"',
context => 0,
sofar => cnt2,
totalwork => totwork2,
units => 'loops' );
/* CQ 13472 temp */


OPEN cur_distinct_prov_id;

/* CQ 13472 temp */
ls_time := to_char(sysdate,'HH:MI:SS');
ld_start_prov := sysdate;
sp_wrerr('BEFORE DISTINCT PROV START : '||ls_time);
cnt3 := 0; -- CQ 13472 temp;
/* CQ 13472 temp */


LOOP
FETCH cur_distinct_prov_id INTO li_seq_prov_id;
EXIT WHEN cur_distinct_prov_id%NOTFOUND;

hsd_messages.sp_prcssing_mssgs_ctl (
ls_grouping,
ls_procedure_name,
ls_key_name,
ls_key_value,
li_seq_prov_id,
NULL,
NULL,
22495,
TRUE
);


/* CQ 13472 temp */
cnt3 := cnt3 + 1;
totwork3 := cur_distinct_prov_id%rowcount;
l_rindex := 3;

dbms_application_info.set_session_longops(
rindex => l_rindex, slno => l_slno,
op_name => '3rd long running operation',
target => 1236, target_desc => '"Distinct Prov"',
context => 0,
sofar => cnt3,
totalwork => totwork3,
units => 'loops' );
/* CQ 13472 temp */


lb_first_time_thru_loop := TRUE; --9404

OPEN cur_cap_entity_work;

/* CQ 13472 temp */
ls_time := to_char(sysdate,'HH:MI:SS');
ld_start_ent_wrk := sysdate;
sp_wrerr('BEFORE CAP ENTITY WRK START : '||ls_time);
cnt4 := 0; -- CQ 13472 temp;
/* CQ 13472 temp */

LOOP
FETCH cur_cap_entity_work INTO lrec_cap_entity_work;
EXIT WHEN cur_cap_entity_work%NOTFOUND;

lb_asterix_mask_1 := FALSE;
lb_asterix_mask_2 := FALSE;
lb_asterix_mask_3 := FALSE;
hsd_messages.sp_prcssing_mssgs_ctl (
ls_grouping,
ls_procedure_name,
ls_key_name,
ls_key_value,
li_seq_prov_id,
NULL,
NULL,
22495,
TRUE
);


/* CQ 13472 temp */
cnt4 := cnt4 + 1;
totwork4 := cur_cap_entity_work%rowcount;
l_rindex := 4;

dbms_application_info.set_session_longops(
rindex => l_rindex, slno => l_slno,
op_name => '4th long running operation',
target => 1237, target_desc => '"Cap Entity Wrk"',
context => 0,
sofar => cnt4,
totalwork => totwork4,
units => 'loops' );
/* CQ 13472 temp */

----------------------------------------
above is the code, where you can see opened cursor.
i spooled :
begin
print_table( 'select b.*
from v$session a, v$session_longops b
where a.sid = b.sid
and a.serial# = b.serial#');
end;
/
and then grepped just the start_time.

Thanks
kaps

From your book :
RINDEX &#8208; Tells the server which row to modify in the V$SESSION_LONGOPS view. If you set this value to
DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS_NOHINT, a new row
will be allocated in this view for you, and the index of this row will be returned in RINDEX. Subsequent calls to SET_SESSION_LONGOPS with the same value for RINDEX will update this already existing row.

• SLNO &#8208; An internal value. You should initially pass a Null number in, and ignore its value otherwise. You should pass the same value in with each call.

Ok I will change that, but what I understand is that just RINDEX should be different for each call ? Isn't it ?

any other thing you doubt about code ? Only values for "Distinct Entity" is getting populated in v$session_longops and no other values ... why ?

thnaks

Actually I don't have control over code but I will suggest to application guys :)
you didn't answer the other questions about RINDEX and SLNO, Should I set different pair for each call ?? and
for "Distinct Entity" is getting populated in v$session_longops and not other values ... why ?

thanks

Hi Tom,

Assume I have a 3-million row table t, if I want to issue:

update t set date_modified = sysdate;

and I want to see how many rows have been updated so far at any given point. What should I do?

thanks,

If I query v$session_longops table in 8174 on AIX, I'm getting garbage values as a part of units & message column.

Secondly, the tables mentioned in the message are not part of query executed under SID=25,

Last, even after execution is finished, query returns same result, where as SELECT * FROM v$session WHERE sid = 25 returns blank.

Am I hitting Bug 1568589 - V$SESSION_LONGOPS ?

SELECT SID, units, message FROM V$SESSION_LONGOPS WHERE sid=25

SID UNITS MESSAGE

25 Blocks Table Scan: PROD.TAHIST: 10370 out of 10370 Blocks done
25 x t t@d= h@ : : 13 out of 13 x t t@d= h@ done
25 Blocks Table Scan: PROD.TAHIST: 14744 out of 14744 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 17828 out of 17828 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 13804 out of 13804 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 17006 out of 17006 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 17828 out of 17828 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 13804 out of 13804 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 12108 out of 12108 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 17533 out of 17533 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 17366 out of 17366 Blocks done
25 P : 1196577680: 1086453376 out of 1086453376 P done
25 Blocks Table Scan: PROD.TAHIST: 17533 out of 17533 Blocks done
25 Blocks Table Scan: PROD.ISALE: 62108 out of 62108 Blocks done
25 Blocks Table Scan: PROD.ISALE: 62108 out of 62108 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 14744 out of 14744 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 14052 out of 14052 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 12596 out of 12596 Blocks done
25 Blocks Table Scan: PROD.TAHIST: 10252 out of 10252 Blocks done
25 Blocks Table Scan: PROD.ISALE: 62108 out of 62108 Blocks done

So is it Bug 1568589 - V$SESSION_LONGOPS?

Output of

SELECT * FROM V$SESSION_LONGOPS WHERE sid=20 AND TIME_REMAINING > 0 is no rows

Query is still executing ...

Hi Tom,

I have a long running simple select query from a large table (100M rows) that does not have an entry in v$session_longops.

Do you have any ideas why no information is available?
Are there any other ways to estimate execution time?

Many Thanks.

Can you have any idea, for what purpose the below query is used?

The below query is at the top of my top 10 queries list.

select /*+ index(idl_sb4$ i_idl_sb41) +*/ max(version) from idl_sb4$ where obj#=:1 and version<=:2 and (part=0 or part=2)

parse calls = 239909.00
parses = 0.06
executions = 239874.00
CPU (s) = 31.38
Elapsed (s) = 243.39
fetches = 239829.00

database info is as under:
Oracle9i Enterprise Edition Release 9.2.0.5.0 - 64bit Production
PL/SQL Release 9.2.0.5.0 - Production
CORE 9.2.0.6.0 Production
TNS for IBM/AIX RISC System/6000: Version 9.2.0.5.0 - Production
NLSRTL Version 9.2.0.5.0 - Production

Thanks in advance

In an earlier post in this thread, Kapil gave code that included the following:

totwork1 := cur_distinct_entity%rowcount;
l_rindex := 1;

dbms_application_info.set_session_longops(
rindex => l_rindex, slno => l_slno,
op_name => '1st long running operation',
target => 1234, target_desc => '"Distinct Entity"',
context => 0,
sofar => cnt1,
totalwork => totwork1,
units => 'loops' );

Of particular interest to me is his use of ROWCOUNT to determine the amount of total work. I don't believe this works, since ROWCOUNT returns only the number of rows fetched at that point, not the total number of rows. So then my question is, what's the best way to do what he's trying to do? The only way I can think of is to SELECT COUNT(*) for the same exact query before looping.

Hi Tom,

This is a problem that i usually face and even i don't have answer when somebody ask me about this.

Why table scan suddenly taking time?

My problem is v$session_longops scans one table sch_t. It scans 70,000 blocks and its scans first 50,000 blocks very fast and time_remaining it shows is 600 and then after 50,000 it slows down, scanning 1 block in 5 mins and then it take hours to complete the table scan and also time_remaining increases. Why this is so? why its taking so much time to scan last 20,000 blocks?

In one case, we were using table sch_t with date condition >= and <= and it was showing table scan going on fast for first 50,000 blocks and then suddendly it almost become dead and scanning 1 block in 5 min then what we did, created separate table as

create table sch_t_new as select * from sch_t where date <= and >= and with this table scan on new table become fast.

Is this due to fragematation or might be due to HWM is set high but not much data is there i.e. deletion of rows?

Please clear this thing as it will help us a lot to tune any query.

Thanks all for your help
Chandan Singh

It seems to me that v$session_longops.time_remaining is extrapolated from elapsed_time, sofar, and totalwork. When you guess totalwork too high, time_remaining never goes to 0. In this circumstance, I don't see a way to tell that the longop is done other than requerying to see if time_elapsed changed. In an earlier response, you said:

<quote>I usually use time_remaining > 0 if I want to see all currently active ones</quote>

but these inactive ones would not be filtered out. How else can you filter out the inactive ones?

That developer would be me, but the procedure is theoretical at the moment. I've only been experimenting. Still, you are the one who said that I should "guess" in regards to the totalwork when looping through a cursor. How can you now say that it's a bug to "guess" wrong? If you know of a way to perfectly "guess" the number, please let me know.

If you don't, how about this for reviewing only the active?

select sl.*
from v$session_longops sl
join v$session s on (s.SID = sl.SID and s.serial# = sl.serial#)
where s.status = 'ACTIVE'
order by sl.start_time desc;

Will this show only active longops?

OK, great. Now I understand what you're saying the bug is. At the end of the longop, regardless of the actual sofar, I should set it to the totalwork.

However, I did find an anomaly. If the totalwork is underestimated, an extra record in v$session_longops appears.

Here's some code to illustrate:

DECLARE
lnIndex BINARY_INTEGER;
lnTotal INTEGER := 9;
lnSLNO BINARY_INTEGER;
lnObj BINARY_INTEGER;
BEGIN
lnIndex := DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS_NOHINT;
FOR i in 1 .. 11 LOOP
DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS(lnIndex, lnSLNO, 'Test', lnObj, 100*i/lnTotal, i, lnTotal, 'Nothing', 'Units');
END LOOP;
DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS(lnIndex, lnSLNO, 'Test', lnObj, 100, lnTotal, lnTotal, 'Nothing', 'Units');
END;
/

We are seeing a discrepancy between v$session_longops and the 10046 trace.
The tkprof from a 10046 trace contradicts this.


1. When I read the tkprof below I see the major bottlen on TABLE_C_IDX01 and the nested loop.
2. when we execute

select message
from v$session_longops
where time_remaining > 0
and sid = mySid

This shows that Oracle spending alot of time full table scanning TABLE A

3. We ran a test where we just joined TABLE A and TABLE B. We got the same hash join and it ran in 1 second where this query can take 20-30 minutes
depending on if it has to do physical IO. To me this again shows the bottleneck is on TABLE C

Why would v$session_longops show that Oracle is spending alot of table doing a full table scan of TABLE A? We kept requerying it and we
slowly saw the blocks increment for TABLE A, but nothing with table C? I believe the OEM uses this view when you look at
poorly performing queries.


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.01 0.02 0 0 0 0
Fetch 2 84.84 82.85 0 3058196 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 84.86 82.87 0 3058196 0 1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: 65

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=3058196 pr=0 pw=0 time=82853038 us)
405706 TABLE ACCESS BY LOCAL INDEX ROWID TABLE_C (cr=3058196 pr=0 pw=0 time=83223163 us)
3260924 NESTED LOOPS (cr=562966 pr=0 pw=0 time=26121206 us)
132949 HASH JOIN (cr=15136 pr=0 pw=0 time=2047193 us)
7 TABLE ACCESS FULL TABLE_A (cr=1231 pr=0 pw=0 time=25596 us)
132949 TABLE ACCESS FULL TABLE_B(cr=13905 pr=0 pw=0 time=1065586 us)
3127974 PARTITION RANGE ITERATOR PARTITION: KEY KEY (cr=547830 pr=0 pw=0 time=16219413 us)
3127974 INDEX RANGE SCAN TABLE_C_IDX01 PARTITION: KEY KEY (cr=547830 pr=0 pw=0 time=11599523 us)(object id 128961)

We see a Table Scan occurring in V$SESSION_LONGOPS, but it seems to be slow..

Looking at the MESSAGE field, in five seconds it scans 13 blocks.

Given an 8k block size, this would seem to point to
13*8k/5= 21299 bytes/sec.

Would this be normal on a fairly large production system? It seems fairly slowwww..

any chance that v$session_longops gets a new column
PARTITION_NAME ?

Could be very helpful when TARGET is partitioned and, for example
OPNAME = 'Table Scan'

I've filed an enhancement request

I ran a very big query, it started, and after some
time, it showed me a TABLE SCAN t1 long operation on OEM, console, and the blue bar progressing, it progresses
for some time and then it is stopped for a long long time,
then progress a bit more and then stopped for a long time,
and so on.

When it stops, I see the wait events in dbconsole,
it shows me (surprisingly) that it was waiting for "db file sequential read" event on object t2.

The question is, the long operation of scanning T1 is in
progress then how can scanning of t2 come in between before
t1 is finished.

Here is the query, next I will upload the autotrace plan. Sorry for so big query, but I will tell exactly
where to look.

The table scan long operation is on ci_prem_char table,
and when ever it stops scanning it for a while, the db file sequential wait event shown in dbcosole are on the following
objects:-

1- ci_sa
2- ci_ft
3- ci_fg_gl

As ci_prem_char appears several times in this query, I cannot not tell for which one the oem is showing TABLESCAN
LONG OPERATION. By the way how can we know that which step of the plan is the long operation belonging to when there
are same objects appearing several times in the query.


select a.CUSTOMER_CLASS,
a.PREM_UNIT,
a.PREM_ZONE,
a.PREM_AREA,
sum(a.OPENING_BAL),
a.ACCOUNT_HEADER,
a.ACC_TYPE,
sum(a.CM_CREDIT),
sum(a.CM_DEBIT),
sum(a.MMBTU_CREDIT),
sum(a.MMBTU_DEBIT),
a.GL_ACCOUNT,
sum(a.AMOUNT),
sum(a.DEBIT),
sum(a.CREDIT),
sum(a.CLOSING_BAL)
from
(select substr(acct.cust_cl_cd,1,3) "CUSTOMER_CLASS",
decode(substr(ft_gl.gl_acct,1,2),'01','A','21','B','41','Q',substr(ft_gl.gl_acct,1,2)) "PREM_UNIT",
cv.DESCR "PREM_ZONE",
prem.postal "PREM_AREA",
0 "OPENING_BAL",
cv3.descr "ACCOUNT_HEADER",
2 "ACC_TYPE",
0 "CM_CREDIT",
0 "CM_DEBIT",
0 "MMBTU_CREDIT",
0 "MMBTU_DEBIT",
dst.descr "GL_ACCOUNT",
ft_gl.AMOUNT "AMOUNT",
(case when ft_gl.AMOUNT > 0 then AMOUNT else 0 end) "DEBIT",
(case when ft_gl.AMOUNT < 0 then AMOUNT else 0 end) "CREDIT",
0 "CLOSING_BAL"
from ci_acct acct,
ci_sa sa,
ci_sa_type sat,
ci_sa_type_char satc,
ci_ft ft,
ci_ft_gl ft_gl,
ci_cal_period cp,
ci_prem prem,
ci_prem_char pc,
ci_char_val_l cv,
ci_dst_code_l dst,
ci_char_val_l cv3
where acct.ACCT_ID = sa.acct_id
and sa.sa_type_cd = sat.sa_type_cd
and sa.cis_division = sat.cis_division
and sa.sa_id = ft.sa_id
and sa.cis_division = satc.cis_division
and sa.sa_type_cd = satc.sa_type_cd
and satc.char_type_cd = 'GLTYPE'
and cv3.char_type_cd = satc.char_type_cd
and cv3.char_val = satc.char_val
and cv3.language_cd = 'ENG'
and ft.freeze_sw = 'Y'
and ft.gl_distrib_status = 'D'
and ft.ft_id = ft_gl.FT_ID
and ft_gl.dst_id <> sat.dst_id
and ft.ACCOUNTING_DT between cp.begin_dt and cp.end_dt
and cp.calendar_id = 'F1'
and cp.fiscal_year = &FISCAL_YEAR
and cp.accounting_period = &ACCOUNTING_PERIOD
and sa.CHAR_PREM_ID = prem.prem_id
and prem.prem_id = pc.prem_id
and pc.char_type_cd = 'ZONE'
and pc.char_type_cd = cv.char_type_cd
and pc.char_val = cv.CHAR_VAL
and cv.language_cd = 'ENG'
and ft_gl.dst_id = dst.dst_id
and dst.language_cd = 'ENG'
and acct.cust_cl_cd = 'DOM'
UNION
select substr(acct.cust_cl_cd,1,3) "CUSTOMER_CLASS",
decode(substr(ft_gl.gl_acct,1,2),'01','A','21','B','41','Q',substr(ft_gl.gl_acct,1,2)) "PREM_UNIT",
cv.DESCR "PREM_ZONE",
prem.postal "PREM_AREA",
0 "OPENING_BAL",
cv3.descr "ACCOUNT_HEADER",
2 "ACC_TYPE",
0 "CM_CREDIT",
0 "CM_DEBIT",
0 "MMBTU_CREDIT",
0 "MMBTU_DEBIT",
dst.descr "GL_ACCOUNT",
ft_gl.AMOUNT "AMOUNT",
(case when ft_gl.AMOUNT > 0 then AMOUNT else 0 end) "DEBIT",
(case when ft_gl.AMOUNT < 0 then AMOUNT else 0 end) "CREDIT",
0 "CLOSING_BAL"
from ci_acct acct,
ci_sa sa,
ci_sa_type sat,
ci_sa_type_char satc,
ci_ft ft,
ci_ft_gl ft_gl,
ci_cal_period cp,
ci_prem prem,
ci_prem_char pc,
ci_char_val_l cv,
ci_dst_code_l dst,
ci_sa sa_high,
ci_char_val_l cv3
where acct.ACCT_ID = sa.acct_id
and sa.sa_type_cd = sat.sa_type_cd
and sa.cis_division = sat.cis_division
and sa.CHAR_PREM_ID = ' '
and sa.cis_division = satc.cis_division
and sa.sa_type_cd = satc.sa_type_cd
and satc.char_type_cd = 'GLTYPE'
and cv3.char_type_cd = satc.char_type_cd
and cv3.char_val = satc.char_val
and cv3.language_cd = 'ENG'
and sa.sa_id = ft.sa_id
and ft.freeze_sw = 'Y'
and ft.gl_distrib_status = 'D'
and ft.ft_id = ft_gl.FT_ID
and ft_gl.dst_id <> sat.dst_id
and ft.ACCOUNTING_DT between cp.begin_dt and cp.end_dt
and cp.calendar_id = 'F1'
and cp.fiscal_year = &FISCAL_YEAR
and cp.accounting_period = &ACCOUNTING_PERIOD
and sa_high.sa_id = (select max(sa_id)
from ci_sa sa2 where sa2.acct_id = sa.acct_id
and char_prem_id <> ' '
and sa_status_flg in ('20','30','40','50','60')
and sa2.start_dt = (select max(start_dt)
from ci_sa sa3
where sa3.acct_id = sa.acct_id
and char_prem_id <> ' '
and sa_status_flg in ('20','30','40','50','60')))
and sa_high.CHAR_PREM_ID = prem.prem_id
and prem.prem_id = pc.prem_id
and pc.char_type_cd = 'ZONE'
and pc.char_type_cd = cv.char_type_cd
and pc.char_val = cv.CHAR_VAL
and cv.language_cd = 'ENG'
and ft_gl.dst_id = dst.dst_id
and dst.language_cd = 'ENG'
and acct.cust_cl_cd = 'DOM'
UNION
select substr(acct.cust_cl_cd,1,3) "CUSTOMER_CLASS",
substr(pc2.char_val,1,1) "PREM_UNIT",
cv.DESCR "PREM_ZONE",
prem.postal "PREM_AREA",
nvl((select sum(tot_amt) from ci_ft ft where ft.sa_id = sa.sa_id and redundant_sw = 'N' and ft.accounting_dt < cp.begin_dt and ft.gl_distrib_status = 'D'),0) "OPENING_BAL",
cv3.descr "ACCOUNT_HEADER",
1 "ACC_TYPE",
nvl((select sum(bill_sq) from ci_bseg_sq bs, ci_ft ft1 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'TOT-SCM' and bs.bseg_id = ft1.sibling_id and ft_type_flg = 'BS' and ft1.sa_id = sa.sa_id and ft1.accounting_dt between cp.begin_dt and cp.end_dt and ft1.gl_distrib_status = 'D' ),0) "CM_CREDIT",
nvl((select sum(-1 * bill_sq) from ci_bseg_sq bs, ci_ft ft2 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'TOT-SCM' and bs.bseg_id = ft2.sibling_id and ft_type_flg = 'BX' and ft2.sa_id = sa.sa_id and ft2.accounting_dt between cp.begin_dt and cp.end_dt and ft2.gl_distrib_status = 'D' ),0) "CM_DEBIT",
nvl((select sum(bill_sq) from ci_bseg_sq bs, ci_ft ft3 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'MMBTU' and bs.bseg_id = ft3.sibling_id and ft_type_flg = 'BS' and ft3.sa_id = sa.sa_id and ft3.accounting_dt between cp.begin_dt and cp.end_dt and ft3.gl_distrib_status = 'D' ),0) "MMBTU_CREDIT",
nvl((select sum(-1 * bill_sq) from ci_bseg_sq bs, ci_ft ft4 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'MMBTU' and bs.bseg_id = ft4.sibling_id and ft_type_flg = 'BX' and ft4.sa_id = sa.sa_id and ft4.accounting_dt between cp.begin_dt and cp.end_dt and ft4.gl_distrib_status = 'D' ),0) "MMBTU_DEBIT",
' ' "GL_ACCOUNT",
0 "AMOUNT",
0 "DEBIT",
0 "CREDIT",
nvl((select sum(tot_amt) from ci_ft ft where ft.sa_id = sa.sa_id and redundant_sw = 'N' and ft.accounting_dt <= cp.end_dt and ft.gl_distrib_status = 'D'),0) "CLOSING_BAL"
from ci_acct acct,
ci_sa sa,
ci_sa_type_char satc,
ci_cal_period cp,
ci_prem prem,
ci_prem_char pc,
ci_prem_char pc2,
ci_char_val_l cv,
ci_char_val_l cv3
where acct.ACCT_ID = sa.acct_id
and sa.sa_type_cd = satc.sa_type_cd
and sa.cis_division = satc.cis_division
and satc.char_type_cd = 'GLTYPE'
and cv3.char_type_cd = satc.char_type_cd
and cv3.char_val = satc.char_val
and cv3.language_cd = 'ENG'
and cp.calendar_id = 'F1'
and cp.fiscal_year = &FISCAL_YEAR
and cp.accounting_period = &ACCOUNTING_PERIOD
and sa.CHAR_PREM_ID = prem.prem_id
and prem.prem_id = pc.prem_id
and pc.char_type_cd = 'ZONE'
and pc.char_type_cd = cv.char_type_cd
and pc.char_val = cv.CHAR_VAL
and cv.language_cd = 'ENG'
and prem.prem_id = pc2.prem_id
and pc2.char_type_cd = 'UNIT'
and acct.cust_cl_cd = 'DOM'
UNION
select substr(acct.cust_cl_cd,1,3) "CUSTOMER_CLASS",
substr(pc2.char_val,1,1) "PREM_UNIT",
cv.DESCR "PREM_ZONE",
prem.postal "PREM_AREA",
nvl((select sum(tot_amt) from ci_ft ft where ft.sa_id = sa.sa_id and redundant_sw = 'N' and ft.accounting_dt < cp.begin_dt and ft.gl_distrib_status = 'D'),0) "OPENING_BAL",
cv3.descr "ACCOUNT_HEADER",
1 "ACC_TYPE",
nvl((select sum(bill_sq) from ci_bseg_sq bs, ci_ft ft1 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'TOT-SCM' and bs.bseg_id = ft1.sibling_id and ft_type_flg = 'BS' and ft1.sa_id = sa.sa_id and ft1.accounting_dt between cp.begin_dt and cp.end_dt and ft1.gl_distrib_status = 'D' ),0) "CM_CREDIT",
nvl((select sum(-1 * bill_sq) from ci_bseg_sq bs, ci_ft ft2 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'TOT-SCM' and bs.bseg_id = ft2.sibling_id and ft_type_flg = 'BX' and ft2.sa_id = sa.sa_id and ft2.accounting_dt between cp.begin_dt and cp.end_dt and ft2.gl_distrib_status = 'D' ),0) "CM_DEBIT",
nvl((select sum(bill_sq) from ci_bseg_sq bs, ci_ft ft3 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'MMBTU' and bs.bseg_id = ft3.sibling_id and ft_type_flg = 'BS' and ft3.sa_id = sa.sa_id and ft3.accounting_dt between cp.begin_dt and cp.end_dt and ft3.gl_distrib_status = 'D' ),0) "MMBTU_CREDIT",
nvl((select sum(-1 * bill_sq) from ci_bseg_sq bs, ci_ft ft4 where bs.UOM_CD = ' ' and tou_cd = ' 'and sqi_cd = 'MMBTU' and bs.bseg_id = ft4.sibling_id and ft_type_flg = 'BX' and ft4.sa_id = sa.sa_id and ft4.accounting_dt between cp.begin_dt and cp.end_dt and ft4.gl_distrib_status = 'D' ),0) "MMBTU_DEBIT",
' ' "GL_ACCOUNT",
0 "AMOUNT",
0 "DEBIT",
0 "CREDIT",
nvl((select sum(tot_amt) from ci_ft ft where ft.sa_id = sa.sa_id and redundant_sw = 'N' and ft.accounting_dt <= cp.end_dt and ft.gl_distrib_status = 'D'),0) "CLOSING_BAL"
from ci_acct acct,
ci_sa sa,
ci_sa_type_char satc,
ci_cal_period cp,
ci_prem prem,
ci_prem_char pc,
ci_prem_char pc2,
ci_char_val_l cv,
ci_char_val_l cv3,
ci_sa sa_high
where acct.ACCT_ID = sa.acct_id
and sa.sa_type_cd = satc.sa_type_cd
and sa.cis_division = satc.cis_division
and satc.char_type_cd = 'GLTYPE'
and cv3.char_type_cd = satc.char_type_cd
and cv3.char_val = satc.char_val
and cv3.language_cd = 'ENG'
and cp.calendar_id = 'F1'
and cp.fiscal_year = &FISCAL_YEAR
and cp.accounting_period = &ACCOUNTING_PERIOD
and sa.CHAR_PREM_ID = ' '
and sa_high.sa_id = (select max(sa_id)
from ci_sa sa2 where sa2.acct_id = sa.acct_id
and char_prem_id <> ' '
and sa_status_flg in ('20','30','40','50','60')
and sa2.start_dt = (select max(start_dt)
from ci_sa sa3
where sa3.acct_id = sa.acct_id
and char_prem_id <> ' '
and sa_status_flg in ('20','30','40','50','60')))
and prem.prem_id = sa_high.char_prem_id
and prem.prem_id = pc.prem_id
and pc.char_type_cd = 'ZONE'
and pc.char_type_cd = cv.char_type_cd
and pc.char_val = cv.CHAR_VAL
and cv.language_cd = 'ENG'
and prem.prem_id = pc2.prem_id
and pc2.char_type_cd = 'UNIT'
and acct.cust_cl_cd = 'DOM') a
group by a.CUSTOMER_CLASS,
a.PREM_UNIT,
a.PREM_ZONE,
a.PREM_AREA,
a.ACCOUNT_HEADER,
a.ACC_TYPE,
a.GL_ACCOUNT
order by
a.CUSTOMER_CLASS,
a.PREM_UNIT,
a.PREM_ZONE,
a.PREM_AREA,
a.ACCOUNT_HEADER,
a.ACC_TYPE,
a.GL_ACCOUNT

Here is the autotrace traceonly explain.

Assuming that its the first appearing ci_prem_char table
for the long operation. I am surprised that how can it
go for ci_sa, ci_ft and ci_ft_gl before completing the
full scan of ci_prem_char and then hash joining it as it
appears in the plan.

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=94626 Card=1370 Byte
s=323320)

1 0 SORT (GROUP BY) (Cost=94626 Card=1370 Bytes=323320)
2 1 VIEW (Cost=94625 Card=1370 Bytes=323320)
3 2 SORT (UNIQUE) (Cost=94625 Card=1370 Bytes=452044)
4 3 UNION-ALL
5 4 HASH JOIN (Cost=34025 Card=72 Bytes=32616)
6 5 TABLE ACCESS (BY INDEX ROWID) OF 'CI_DST_CODE_L'
(TABLE) (Cost=1 Card=68 Bytes=3264)

7 6 INDEX (RANGE SCAN) OF 'XC162P0' (INDEX (UNIQUE
)) (Cost=1 Card=68)

8 5 TABLE ACCESS (BY INDEX ROWID) OF 'CI_FT_GL' (TAB
LE) (Cost=1 Card=3 Bytes=171)

9 8 NESTED LOOPS (Cost=34024 Card=127 Bytes=51435)
10 9 NESTED LOOPS (Cost=34004 Card=50 Bytes=17400
)

11 10 HASH JOIN (Cost=33999 Card=50 Bytes=16400)
12 11 TABLE ACCESS (FULL) OF 'CI_SA_TYPE' (TAB
LE) (Cost=3 Card=60 Bytes=1560)

13 11 TABLE ACCESS (BY INDEX ROWID) OF 'CI_FT'
(TABLE) (Cost=2 Card=1 Bytes=36)

14 13 NESTED LOOPS (Cost=33995 Card=50 Bytes
=15100)

15 14 HASH JOIN (Cost=31421 Card=1286 Byte
s=342076)

16 15 TABLE ACCESS (BY INDEX ROWID) OF '
CI_CHAR_VAL_L' (TABLE) (Cost=1 Card=4 Bytes=180)

17 16 INDEX (RANGE SCAN) OF 'XC510P0'
(INDEX (UNIQUE)) (Cost=1 Card=4)

18 15 HASH JOIN (Cost=31419 Card=52979 B
ytes=11708359)

19 18 TABLE ACCESS (FULL) OF 'CI_SA_TY
PE_CHAR' (TABLE) (Cost=3 Card=60 Bytes=2460)

20 18 TABLE ACCESS (BY INDEX ROWID) OF
'CI_SA' (TABLE) (Cost=1 Card=3 Bytes=144)

21 20 NESTED LOOPS (Cost=31415 Card=
52979 Bytes=9536220)

22 21 NESTED LOOPS (Cost=25890 Car
d=18399 Bytes=2428668)

23 22 HASH JOIN (Cost=24054 Card
=18348 Bytes=1981584)

24 23 NESTED LOOPS (Cost=2 Car
d=33 Bytes=2343)

25 24 TABLE ACCESS (BY INDEX
ROWID) OF 'CI_CAL_PERIOD' (TABLE) (Cost=1 Card=1 Bytes=26)

26 25 INDEX (UNIQUE SCAN)
OF 'XC005P0' (INDEX (UNIQUE)) (Cost=1 Card=1)

27 24 TABLE ACCESS (BY INDEX
ROWID) OF 'CI_CHAR_VAL_L' (TABLE) (Cost=1 Card=33 Bytes=148
5)

28 27 INDEX (RANGE SCAN) O
F 'XC510P0' (INDEX (UNIQUE)) (Cost=1 Card=33)

29 23 TABLE ACCESS (FULL) OF '
CI_PREM_CHAR' (TABLE) (Cost=24027 Card=2201162 Bytes=8144299
4)

30 22 TABLE ACCESS (BY INDEX ROW
ID) OF 'CI_PREM' (TABLE) (Cost=1 Card=1 Bytes=24)

31 30 INDEX (UNIQUE SCAN) OF '
XM174P0' (INDEX (UNIQUE)) (Cost=1 Card=1)

32 21 INDEX (RANGE SCAN) OF 'XM199
S2' (INDEX) (Cost=1 Card=3)

33 14 INDEX (RANGE SCAN) OF 'XT112S1' (IND
EX) (Cost=1 Card=18)

34 10 TABLE ACCESS (BY INDEX ROWID) OF 'CI_ACCT'
(TABLE) (Cost=1 Card=1 Bytes=20)

35 34 INDEX (UNIQUE SCAN) OF 'XM148P0' (INDEX
(UNIQUE)) (Cost=1 Card=1)

36 9 INDEX (RANGE SCAN) OF 'XT113P0' (INDEX (UNIQ
UE)) (Cost=1 Card=3)

37 4 NESTED LOOPS (Cost=15 Card=1 Bytes=475)
38 37 NESTED LOOPS (Cost=14 Card=1 Bytes=430)
39 38 NESTED LOOPS (Cost=13 Card=1 Bytes=393)
40 39 NESTED LOOPS (Cost=12 Card=1 Bytes=369)
41 40 NESTED LOOPS (Cost=11 Card=1 Bytes=347)
42 41 NESTED LOOPS (Cost=10 Card=1 Bytes=299)
43 42 NESTED LOOPS (Cost=9 Card=1 Bytes=242)
44 43 NESTED LOOPS (Cost=8 Card=1 Bytes=22
2)

45 44 NESTED LOOPS (Cost=7 Card=1 Bytes=
196)

46 45 NESTED LOOPS (Cost=5 Card=1 Byte
s=160)

47 46 NESTED LOOPS (Cost=4 Card=13 B
ytes=1495)

48 47 NESTED LOOPS (Cost=2 Card=13
Bytes=962)

49 48 TABLE ACCESS (BY INDEX ROW
ID) OF 'CI_CAL_PERIOD' (TABLE) (Cost=1 Card=1 Bytes=26)

50 49 INDEX (UNIQUE SCAN) OF '
XC005P0' (INDEX (UNIQUE)) (Cost=1 Card=1)

51 48 TABLE ACCESS (BY INDEX ROW
ID) OF 'CI_SA' (TABLE) (Cost=1 Card=13 Bytes=624)

52 51 INDEX (RANGE SCAN) OF 'X
M199S2' (INDEX) (Cost=1 Card=13)

53 47 TABLE ACCESS (BY INDEX ROWID
) OF 'CI_SA_TYPE_CHAR' (TABLE) (Cost=1 Card=1 Bytes=41)

54 53 INDEX (UNIQUE SCAN) OF 'XC
323P0' (INDEX (UNIQUE)) (Cost=1 Card=1)

55 46 TABLE ACCESS (BY INDEX ROWID)
OF 'CI_CHAR_VAL_L' (TABLE) (Cost=1 Card=1 Bytes=45)

56 55 INDEX (UNIQUE SCAN) OF 'XC51
0P0' (INDEX (UNIQUE)) (Cost=1 Card=1)

57 45 TABLE ACCESS (BY INDEX ROWID) OF
'CI_FT' (TABLE) (Cost=2 Card=1 Bytes=36)

58 57 INDEX (RANGE SCAN) OF 'XT112S1
' (INDEX) (Cost=1 Card=18)

59 44 TABLE ACCESS (BY INDEX ROWID) OF '
CI_SA_TYPE' (TABLE) (Cost=1 Card=1 Bytes=26)

60 59 INDEX (UNIQUE SCAN) OF 'XC209P0'
(INDEX (UNIQUE)) (Cost=1 Card=1)

61 43 TABLE ACCESS (BY INDEX ROWID) OF 'CI
_ACCT' (TABLE) (Cost=1 Card=1 Bytes=20)

62 61 INDEX (UNIQUE SCAN) OF 'XM148P0' (
INDEX (UNIQUE)) (Cost=1 Card=1)

63 42 TABLE ACCESS (BY INDEX ROWID) OF 'CI_F
T_GL' (TABLE) (Cost=1 Card=3 Bytes=171)

64 63 INDEX (RANGE SCAN) OF 'XT113P0' (IND
EX (UNIQUE)) (Cost=1 Card=3)

65 41 TABLE ACCESS (BY INDEX ROWID) OF 'CI_DST
_CODE_L' (TABLE) (Cost=1 Card=1 Bytes=48)

66 65 INDEX (UNIQUE SCAN) OF 'XC162P0' (INDE
X (UNIQUE)) (Cost=1 Card=1)

67 40 TABLE ACCESS (BY INDEX ROWID) OF 'CI_SA' (
TABLE) (Cost=1 Card=1 Bytes=22)

68 67 INDEX (UNIQUE SCAN) OF 'XM199P0' (INDEX
(UNIQUE)) (Cost=1 Card=1)

69 68 SORT (AGGREGATE)
70 69 FILTER
71 70 TABLE ACCESS (BY INDEX ROWID) OF '
CI_SA' (TABLE) (Cost=1 Card=3 Bytes=132)

72 71 INDEX (RANGE SCAN) OF 'XM199S1'
(INDEX) (Cost=1 Card=3)

73 70 SORT (AGGREGATE)
74 73 TABLE ACCESS (BY INDEX ROWID) OF
'CI_SA' (TABLE) (Cost=1 Card=3 Bytes=99)

75 74 INDEX (RANGE SCAN) OF 'XM199S1
' (INDEX) (Cost=1 Card=3)

76 39 TABLE ACCESS (BY INDEX ROWID) OF 'CI_PREM' (
TABLE) (Cost=1 Card=1 Bytes=24)

77 76 INDEX (UNIQUE SCAN) OF 'XM174P0' (INDEX (U
NIQUE)) (Cost=1 Card=1)

78 38 TABLE ACCESS (BY INDEX ROWID) OF 'CI_PREM_CHAR
' (TABLE) (Cost=1 Card=1 Bytes=37)

79 78 INDEX (RANGE SCAN) OF 'XM175P0' (INDEX (UNIQ
UE)) (Cost=1 Card=1)

80 37 TABLE ACCESS (BY INDEX ROWID) OF 'CI_CHAR_VAL_L'
(TABLE) (Cost=1 Card=1 Bytes=45)

81 80 INDEX (UNIQUE SCAN) OF 'XC510P0' (INDEX (UNIQU
E)) (Cost=1 Card=1)

82 4 TABLE ACCESS (BY INDEX ROWID) OF 'CI_PREM_CHAR' (T
ABLE) (Cost=1 Card=1 Bytes=37)

83 82 NESTED LOOPS (Cost=31807 Card=1296 Bytes=418608)
84 83 NESTED LOOPS (Cost=31550 Card=1286 Bytes=36779
6)

85 84 HASH JOIN (Cost=31421 Card=1286 Bytes=342076
)

86 85 TABLE ACCESS (BY INDEX ROWID) OF 'CI_CHAR_
VAL_L' (TABLE) (Cost=1 Card=4 Bytes=180)

87 86 INDEX (RANGE SCAN) OF 'XC510P0' (INDEX (
UNIQUE)) (Cost=1 Card=4)

88 85 HASH JOIN (Cost=31419 Card=52979 Bytes=117
08359)

89 88 TABLE ACCESS (FULL) OF 'CI_SA_TYPE_CHAR'
(TABLE) (Cost=3 Card=60 Bytes=2460)

90 88 TABLE ACCESS (BY INDEX ROWID) OF 'CI_SA'
(TABLE) (Cost=1 Card=3 Bytes=144)

91 90 NESTED LOOPS (Cost=31415 Card=52979 By
tes=9536220)

92 91 NESTED LOOPS (Cost=25890 Card=18399
Bytes=2428668)

93 92 HASH JOIN (Cost=24054 Card=18348 B
ytes=1981584)

94 93 NESTED LOOPS (Cost=2 Card=33 Byt
es=2343)

95 94 TABLE ACCESS (BY INDEX ROWID)
OF 'CI_CAL_PERIOD' (TABLE) (Cost=1 Card=1 Bytes=26)

96 95 INDEX (UNIQUE SCAN) OF 'XC00
5P0' (INDEX (UNIQUE)) (Cost=1 Card=1)

97 94 TABLE ACCESS (BY INDEX ROWID)
OF 'CI_CHAR_VAL_L' (TABLE) (Cost=1 Card=33 Bytes=1485)

98 97 INDEX (RANGE SCAN) OF 'XC510
P0' (INDEX (UNIQUE)) (Cost=1 Card=33)

99 93 TABLE ACCESS (FULL) OF 'CI_PREM_
CHAR' (TABLE) (Cost=24027 Card=2201162 Bytes=81442994)

100 92 TABLE ACCESS (BY INDEX ROWID) OF '
CI_PREM' (TABLE) (Cost=1 Card=1 Bytes=24)

101 100 INDEX (UNIQUE SCAN) OF 'XM174P0'
(INDEX (UNIQUE)) (Cost=1 Card=1)

102 91 INDEX (RANGE SCAN) OF 'XM199S2' (IND
EX) (Cost=1 Card=3)

103 84 TABLE ACCESS (BY INDEX ROWID) OF 'CI_ACCT' (
TABLE) (Cost=1 Card=1 Bytes=20)

104 103 INDEX (UNIQUE SCAN) OF 'XM148P0' (INDEX (U
NIQUE)) (Cost=1 Card=1)

105 83 INDEX (RANGE SCAN) OF 'XM175P0' (INDEX (UNIQUE
)) (Cost=1 Card=1)

106 4 NESTED LOOPS (Cost=11 Card=1 Bytes=345)
107 106 NESTED LOOPS (Cost=10 Card=1 Bytes=300)
108 107 NESTED LOOPS (Cost=9 Card=1 Bytes=263)
109 108 NESTED LOOPS (Cost=8 Card=1 Bytes=226)
110 109 NESTED LOOPS (Cost=7 Card=1 Bytes=202)
111 110 NESTED LOOPS (Cost=6 Card=1 Bytes=180)
112 111 NESTED LOOPS (Cost=5 Card=1 Bytes=160)
113 112 NESTED LOOPS (Cost=4 Card=13 Bytes=1
495)

114 113 NESTED LOOPS (Cost=2 Card=13 Bytes
=962)

115 114 TABLE ACCESS (BY INDEX ROWID) OF
'CI_CAL_PERIOD' (TABLE) (Cost=1 Card=1 Bytes=26)

116 115 INDEX (UNIQUE SCAN) OF 'XC005P
0' (INDEX (UNIQUE)) (Cost=1 Card=1)

117 114 TABLE ACCESS (BY INDEX ROWID) OF
'CI_SA' (TABLE) (Cost=1 Card=13 Bytes=624)

118 117 INDEX (RANGE SCAN) OF 'XM199S2
' (INDEX) (Cost=1 Card=13)

119 113 TABLE ACCESS (BY INDEX ROWID) OF '
CI_SA_TYPE_CHAR' (TABLE) (Cost=1 Card=1 Bytes=41)

120 119 INDEX (UNIQUE SCAN) OF 'XC323P0'
(INDEX (UNIQUE)) (Cost=1 Card=1)

121 112 TABLE ACCESS (BY INDEX ROWID) OF 'CI
_CHAR_VAL_L' (TABLE) (Cost=1 Card=1 Bytes=45)

122 121 INDEX (UNIQUE SCAN) OF 'XC510P0' (
INDEX (UNIQUE)) (Cost=1 Card=1)

123 111 TABLE ACCESS (BY INDEX ROWID) OF 'CI_A
CCT' (TABLE) (Cost=1 Card=1 Bytes=20)

124 123 INDEX (UNIQUE SCAN) OF 'XM148P0' (IN
DEX (UNIQUE)) (Cost=1 Card=1)

125 110 TABLE ACCESS (BY INDEX ROWID) OF 'CI_SA'
(TABLE) (Cost=1 Card=1 Bytes=22)

126 125 INDEX (UNIQUE SCAN) OF 'XM199P0' (INDE
X (UNIQUE)) (Cost=1 Card=1)

127 126 SORT (AGGREGATE)
128 127 FILTER
129 128 TABLE ACCESS (BY INDEX ROWID) OF
'CI_SA' (TABLE) (Cost=1 Card=3 Bytes=132)

130 129 INDEX (RANGE SCAN) OF 'XM199S1
' (INDEX) (Cost=1 Card=3)

131 128 SORT (AGGREGATE)
132 131 TABLE ACCESS (BY INDEX ROWID)
OF 'CI_SA' (TABLE) (Cost=1 Card=3 Bytes=99)

133 132 INDEX (RANGE SCAN) OF 'XM199
S1' (INDEX) (Cost=1 Card=3)

134 109 TABLE ACCESS (BY INDEX ROWID) OF 'CI_PREM'
(TABLE) (Cost=1 Card=1 Bytes=24)

135 134 INDEX (UNIQUE SCAN) OF 'XM174P0' (INDEX
(UNIQUE)) (Cost=1 Card=1)

136 108 TABLE ACCESS (BY INDEX ROWID) OF 'CI_PREM_CH
AR' (TABLE) (Cost=1 Card=1 Bytes=37)

137 136 INDEX (RANGE SCAN) OF 'XM175P0' (INDEX (UN
IQUE)) (Cost=1 Card=1)

138 107 TABLE ACCESS (BY INDEX ROWID) OF 'CI_PREM_CHAR
' (TABLE) (Cost=1 Card=1 Bytes=37)

139 138 INDEX (RANGE SCAN) OF 'XM175P0' (INDEX (UNIQ
UE)) (Cost=1 Card=1)

140 106 TABLE ACCESS (BY INDEX ROWID) OF 'CI_CHAR_VAL_L'
(TABLE) (Cost=1 Card=1 Bytes=45)

141 140 INDEX (UNIQUE SCAN) OF 'XC510P0' (INDEX (UNIQU
E)) (Cost=1 Card=1)




SQL>

Hi Tom,

I am able to monitor the execution of any Insert/Update queries etc...

But whenever I run something like
Create table t1 as
select a,b,c from t2,t3...joins and other conditions.
I do not see any entries in V$session_longops for this statement.

Can we not track the SQL being used to create the table.

Thanks,
Dheeraj

hash join
  full scan t1
  full scan t2

nested loops
   table access by index rowid t2
      index range scan
   table access by index rowid t1
      index range scan

Thanks Tom,

Just wanted to rule out that " Create table..." is not cuainsg it to not appear in the v$session_longops.

The version is 8i and OS: Windows.

Does the "Create index ..." or any other create statement for that matter...also appears in the v$session_longops table?

~Dheeraj

.SID                          : 17
.SERIAL#                      : 1088
.OPNAME                       : Table Scan
.TARGET                       : OPS$TKYTE.BIG_TABLE
.TARGET_DESC                  :
.SOFAR                        : 5155
.TOTALWORK                    : 14321
.UNITS                        : Blocks
.START_TIME                   : 04-jan-2008 12:19:10
.LAST_UPDATE_TIME             : 04-jan-2008 12:19:32
.TIME_REMAINING               : 39
.ELAPSED_SECONDS              : 22
.CONTEXT                      : 0
.MESSAGE                      : Table Scan:  OPS$TKYTE.BIG_TABLE: 5155 out of
14321 Blocks done
.USERNAME                     : OPS$TKYTE
.SQL_ADDRESS                  : 01A815C4
.SQL_HASH_VALUE               : 0
.QCSID                        : 0
-----------------

.SID                          : 17
.SERIAL#                      : 1094
.OPNAME                       : Table Scan
.TARGET                       : OPS$TKYTE.TT
.TARGET_DESC                  :
.SOFAR                        : 4069
.TOTALWORK                    : 14317
.UNITS                        : Blocks
.START_TIME                   : 04-jan-2008 12:21:29
.LAST_UPDATE_TIME             : 04-jan-2008 12:21:38
.TIME_REMAINING               : 23
.ELAPSED_SECONDS              : 9
.CONTEXT                      : 0
.MESSAGE                      : Table Scan:  OPS$TKYTE.TT: 4069 out of 14317
Blocks done
.USERNAME                     : OPS$TKYTE
.SQL_ADDRESS                  : 01A83B48
.SQL_HASH_VALUE               : 0
.QCSID                        : 0
-----------------

Tom, can I grab serial# in a trigger? The following trigger compiles, but fails at execution time.

CREATE OR REPLACE TRIGGER CDW.INDEX_SAVE_B_DI_R
BEFORE INSERT OR DELETE ON CDW.INDEX_SAVE
FOR EACH ROW
DECLARE
v_sid NUMBER;
v_serial# number;
BEGIN

v_sid := sys_context('USERENV', 'SID');

select serial#
into v_serial
from v$session
where sid = sys_context('USERENV', 'SID');

IF INSERTING THEN
INSERT INTO cdw_index_save_hist
VALUES (:NEW.owner, :NEW.index_name, :NEW.table_name, :NEW.column_names, :NEW.row_user_id, :NEW.row_task_id,
SYSDATE, SYSDATE, :NEW.index_type, 'DROP INDEX', v_sid, v_serial#);
ELSIF DELETING THEN
INSERT INTO cdw_index_save_hist
VALUES (:OLD.owner, :OLD.index_name, :OLD.table_name, :OLD.column_names, :OLD.row_user_id, :OLD.row_task_id,
SYSDATE, SYSDATE, :OLD.index_type, 'CREATE INDEX', v_sid, v_serial#);
END IF;

END INDEX_SAVE_B_DI_R ;
/

BEFORE INSERT OR DELETE ON CDW.INDEX_SAVE
                               *
ERROR at line 2:
ORA-00942: table or view does not exist

DECLARE
    v_sid NUMBER;<b>
    v_serial# number;</b>
BEGIN

    v_sid := sys_context('USERENV', 'SID');

    select serial# <b>
        into v_serial</b>
        from v$session  
        where sid = sys_context('USERENV', 'SID');

ops$tkyte%ORA10GR2> create table t ( x int );

Table created.

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> CREATE OR REPLACE TRIGGER INDEX_SAVE_B_DI_R
  2  BEFORE INSERT OR DELETE ON t
  3  FOR EACH ROW
  4  DECLARE
  5      v_sid NUMBER;
  6      v_serial# number;
  7  BEGIN
  8      v_sid := sys_context('USERENV', 'SID');
  9      select serial#
 10          into v_serial#
 11          from v$session
 12          where sid = sys_context('USERENV', 'SID');
 13          dbms_output.put_line( 'v_serial = ' || v_serial# );
 14  END INDEX_SAVE_B_DI_R ;
 15  /

Trigger created.

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> insert into t values(0);
v_serial = 706

1 row created.

Tom, thanks for your help on this issue; turns out the session account did not have Data Dictionary visibility.

hi tom

can V$SESSION_LONGOPS can show me how much import has completed. Here is my problem. I am trying to import through an imp command a dump file. Both the database versions are oracle 10g release 2. so no versions problem. also i am ziping the export in windows environment and unziping it in linux environments or window environments so no file size problem. but when i perform import from my system( window xp connect to linux on which database resides) with file on my systm the import hangs and does not give any error. the same import command on linux system when the file(dump file) is on the linux system works fine.

I was thinking that it may be due to busy network but i have no way to trace how much import is completed. Can V$SESSION_LONGOPS help me in this regard

I used the following query (check it against your version, I didn't use it since 2001 or 2002):

Select substr(sql_text,14,instr(sql_text,'(')-16) table_name, 
       rows_processed, 
       round((sysdate
              - to_date(first_load_time,'yyyy-mm-dd hh24:mi:ss'))
             *24*60, 1) minutes, 
       trunc(rows_processed / 
                ((sysdate-to_date(first_load_time,'yyyy-mm-dd hh24:mi:ss'))
             *24*60)) rows_per_min 
from v$sqlarea 
where upper(sql_text) like 'INSERT INTO "%' 
  and command_type = 2 
  and open_versions > 0;

Of course, it only works if you never imported the same table or didn't import it (or use the same statement) since this statement has been aged out sqlarea.

Regards
Michel

hi tom
by looking at V$SESSION_LONGOPS, I could see some long running sqls,and see how much work is done.

But I couldnt see all of the long runn¿ng sqls.
For instance I have a long running procedure but I couldnt see it from the V$SESSION_LONGOPS.
Why not?

As Tom already said only some operations are recorded in v$session_longops by default, for example, hash joins, full table scans, index fast full scans etc. It is also possible that Oracle performs many other operations during the long operation, for example for each record in table full scan calculates some costly user defined function or something like that. So it means that much work can be done behind the scenes. Oracle assumes your long operation is linear, but in reality it is not always that way, so one can sometimes spot long operations giving wrong predictions, because oracle assumes the process is linear but in reality it is not.
On the other hand some long operations e.g. nested loops are not recorded there. I've written an article about v$session_longops here http://gplivna.eu/papers/v$session_longops.htm giving examples and explanations of some of these cases.

Hi Tom;
I guess I w¿ll use the below query.
Do I insert this query inside my procedures?

ops$tkyte@ORA9IR2> declare
2 l_nohint number default dbms_application_info.set_session_longops_nohint;
3 l_rindex number default l_nohint;
4 l_slno number;
5 begin
6 for i in 1 .. 10
7 loop
8 dbms_lock.sleep(2);
9 dbms_application_info.set_session_longops
10 ( rindex => l_rindex,
11 slno => l_slno,
12 op_name => 'my long running operation',
13 target => 1234,
14 target_desc => '"msg description"',
15 context => 0,
16 sofar => i,
17 totalwork => 10,
18 units => 'loops'
19 );
20 end loop;
21 end;
22 /



I mean if my sql is like
select sysdate into t from dual;
Do I insert it under the loop of the above query?

hi Tom,

Can we estimate the execution time of the package when will that end.. Once I fire the package, I would run the query and could see what is approximate time of execution..

I have a long running job and watching the status in v$session_longops confuses me ...

I run with parallel 4, so I see 4 entries in longops .. great ... it tells me how long it's expected to take ... great ...
I monitor it, and about 12 min later the processes start to finish .. I watch the original session ... still going ...

I look back to longops ... now there's 8 entries. 4 are "done" (ie time remaining = 0), and now there are 4 new entries ... with new estimates on time remaining .. Huh ?

These ones, however, take about 30 min ...

ok .. so I wait .. they finish ... 4 more get created ... estimate: 50 min ...

What's going on? Why does a single (parallel) job keep spawning new entries in longops once the current processes are complete? Is Oracle just breaking the work down into chunks?

I've looked at "sofar_blocks" .. and with block size of 8192, each process appears to work on about 100M of data. (8192* ~14,000 sofar blocks)
I'm querying about 6G of data .. so we should expect 60 of these entries before I'm done?

Am I understanding this properly? Or is there something else I should check?

That's what I thought ... it was definitely what I was witnessing ... I was worried something else "nefarious" was going on :)

Thanks again!

Can you explain me what is "SOFAR" and "TOTALWORK" column ?
And "start_time" column is means operation start date but last update time is alternative to operation stop date?

Dear Tom, Kindly clear the error below mentioned query

Update tblsession set session_strStatus='I' where session_lngsessionid=