Skip to Main Content

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question.

Asked: November 29, 2000 - 3:02 pm UTC

Last updated: September 13, 2017 - 7:59 am UTC

Version: 8.1.6

Viewed 10K+ times! This question is

You Asked

Tom:

when i query v$session_longops, i got the following result:

select username ,sid,serial# from v$session_longops;
SYS 12 1
John 28 438
HP_DBSPI 42 39
HP_DBSPI 42 39
HP_DBSPI 40 74

what should i do if i want to kill john's longops?
Alter system kill session '28,438';
ERROR at line 1:
ORA-00030: User session ID does not exist.

when i query v$session,
select username,sid,serial# from v$session where sid=28;
USERNAME SID SERIAL#
------------------------------ ---------- ----------
mike 28 3762

and select count(0) from v$session where username='HP_DBSPI'
return 0.
seems it is totally irrelevant between this v$session and
v$session_longops.

and we said...

data in v$session_longops hangs out until those slots are needed for reuse. You should approach v$session_longops with specific sid,serial#'s -- you do not query the table by itself. You can join this to v$session or whatnot.

You should ignore rows in there that are not for current sessions. You cannot clear them.

Rating

  (63 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Using v$session_longops with large batch posting

Denise, January 14, 2004 - 11:24 am UTC

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..
















 

Tom Kyte
January 14, 2004 - 4:03 pm UTC

the dbms_application_info calls sort of need to be in the LONG running process. not in a loop that loops over i and does nothing...

thanks Tom...

Denise, January 14, 2004 - 4:51 pm UTC

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..




Tom Kyte
January 14, 2004 - 5:57 pm UTC

yes. exactly -- if you want to instrument the code, you need to instrument the CODE.

long running queries.

Wor, February 26, 2004 - 4:36 pm UTC

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.

Tom Kyte
February 26, 2004 - 6:14 pm UTC

only entries that have a valid SID mean anything here (I usually use time_remaining > 0 if I want to see all currently active ones but the view is meant to be looked up by SID -- to monitor a sid)

the other entries are either

a) leftover from some previous run
b) totally uninitialized garbage


to find "long running stuff in current sessions", use last_call_et in v$session along with "status = 'ACTIVE'" last_call_et (with timed statistics=true) will tell you how long they've been doing whatever they last submitted. You can search this site for showsql.sql to see how to marry up v$session with v$sql to see what SQL they are executing and last_call_et will tell you how long they've been doing it.

v$session_longops problem

Vera, May 05, 2004 - 3:31 pm UTC

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

Tom Kyte
May 05, 2004 - 3:35 pm UTC

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..
 

v$session_longops problem

Vera, May 05, 2004 - 5:33 pm UTC

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


Tom Kyte
May 05, 2004 - 7:57 pm UTC

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)

not sure why it "just started working".

Addition to the previous

Vera, May 05, 2004 - 5:59 pm UTC

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 Kyte
May 05, 2004 - 8:12 pm UTC

you'll have to help "me" reproduce. give me a test case to work with..

v$session_longops

A reader, May 06, 2004 - 11:19 am UTC

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 Kyte
May 06, 2004 - 2:57 pm UTC

then the code in the bigger package is not the same -- they must be using the same

9 dbms_application_info.set_session_longops
10 ( rindex => l_rindex,
11 slno => l_slno,

values (thats the slot info)......

Oracle will use v$session_longops itself --but each session should get its own slot.

v$session_longops

A reader, May 07, 2004 - 12:56 pm UTC

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.

 

Tom Kyte
May 07, 2004 - 1:22 pm UTC

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. 

v$session_longops

Vera, May 07, 2004 - 2:19 pm UTC

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

Tom Kyte
May 07, 2004 - 2:44 pm UTC

you are saying you


select * from v$session_longops where time_remaining > 0

and you are getting those rows? if so, please contact support.

V$SESSION_LONGOPS

Vera, May 07, 2004 - 4:47 pm UTC

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.


v$session

Vera, May 20, 2004 - 5:49 pm UTC

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?

Tom Kyte
May 20, 2004 - 8:43 pm UTC

if an os patch breaks something, that would be a "bug". Needs to be fixed one way or the other -- I don't see how an OS patch would affect us like this, and if it does -- who knows what else its done..

dbms_application_info is safe to use with the client_info/set_module

Multiple LONGOPS per session?

Ekkehard Kraemer, March 08, 2005 - 2:42 pm UTC

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>





Tom Kyte
March 08, 2005 - 3:32 pm UTC

9205 worked for me, 8174 worked as well.

salee, March 09, 2005 - 5:42 am UTC

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

Tom Kyte
March 09, 2005 - 7:50 am UTC

use v$session to see the sessions, search this site for showsql to see a script that shows you the sessions and the sql they are running.


any gui tool that manages the database would be able to show you this as well.


salee, March 09, 2005 - 5:43 am UTC

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

Issue with SET_SESSION_LONGOPS on Ora 8.1.7.4.1

SFT, April 05, 2005 - 5:16 am UTC

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

Tom Kyte
April 05, 2005 - 7:33 am UTC

I'll have to refer you to support as for me on 8174 EE on solaris I am not able to reproduce.

Clarifications on "slots" in v$session_longops

Pratap, April 26, 2005 - 3:50 am UTC

"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


Tom Kyte
April 26, 2005 - 7:27 am UTC

1) you allocate a slot and it is yours.
2) you basically rewrite the same row over and over. You would not typically be using more than one row?

Jonathan Lewis has an answer to this

Pratap, April 27, 2005 - 3:20 am UTC

Column "TARGET" in V$SESSION_LONGOPS

Markus Schwabe, July 28, 2005 - 3:25 am UTC

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

Tom Kyte
July 28, 2005 - 8:52 am UTC

I don't know why, you'd have to ask support if they can track down any reason.

Target is going to be a binary integer as per the specification of this package.

v$session_longops.

A reader, September 14, 2005 - 6:19 pm UTC

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


Tom Kyte
September 14, 2005 - 8:28 pm UTC

strange to see the total number of blocks in the table go UP and then DOWN

tell us more - what is the logic here?

v$session_longops.

kapil, September 14, 2005 - 6:23 pm UTC

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


kapil, September 15, 2005 - 12:51 pm UTC

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

Tom Kyte
September 15, 2005 - 1:04 pm UTC

I'm in guess mode, tell us about the table.

A reader, September 15, 2005 - 2:13 pm UTC

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


Thanks

Tom Kyte
September 15, 2005 - 2:39 pm UTC

tell us about the table you are full scanning -- how is is created, what in general is going on with it.

Tell us about that table.

kapil, September 15, 2005 - 3:15 pm UTC

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



Tom Kyte
September 15, 2005 - 4:34 pm UTC

so, these different blocksizes are after truncates/inserts??

Kapil, September 15, 2005 - 4:57 pm UTC

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

Tom Kyte
September 15, 2005 - 5:07 pm UTC

did you try tracing the batch job?

you can instruement this batch job as well with dbms_application_info

search for

set_session_longops

Kapil, September 15, 2005 - 5:20 pm UTC

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


Tom Kyte
September 15, 2005 - 5:36 pm UTC

No guesses, no idea what the batch is doing...

kapil, September 15, 2005 - 5:34 pm UTC

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

Tom Kyte
September 15, 2005 - 5:39 pm UTC

No worries, I typically answer them anyway after having a nice rant about not knowing that "u" guy ;)

kapil, September 15, 2005 - 11:50 pm UTC

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


Tom Kyte
September 16, 2005 - 8:07 am UTC

i don't see an open cur_distinct_vendor

I don't know that file you are grepping

Kapil, September 16, 2005 - 10:59 am UTC

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

Tom Kyte
September 16, 2005 - 1:53 pm UTC

Oh, I see - you are using the same

rindex => l_rindex, slno => l_slno,

over and over and over - don't you mean to have a separate slot for each? You are changing the meaning over and over

I think each of your calls would have a different pair of values - don't you?

Kapil, September 16, 2005 - 2:40 pm UTC

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

Tom Kyte
September 16, 2005 - 2:44 pm UTC

well, I can say that is execessively procedural code that could probably benefit from some nice big SET operations.

from the simple:

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;

should be

select ... BULK COLLECT nito ls_rate_search_type_tbl
from ....

(no code) IF in fact it should be in a table type at all -- databases were BORN to join, it is what they do best


To looking at things like hsd_messages.sp_prcssing_mssgs_ctl and asking yourself "could it just do a single big sql statement to process ALL of the data instead of being called over and over and over and over and over...

*think sets*



Kapil, September 16, 2005 - 3:26 pm UTC

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


Tom Kyte
September 16, 2005 - 3:43 pm UTC

actually, what I would recommend is using a single entry for the entire thing, maybe using dbms_application_info.set_module to set the action and module inside the tighter loops - just use one row from this view and don't have multiple descriptions (use action and module for that if you like)

they'd have their own rindex and slno

row count tracking

Charlie, October 21, 2005 - 11:38 am UTC

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,

Tom Kyte
October 21, 2005 - 11:43 am UTC

You won't see rows, you will see a full scan - you can monitor that in v$session_longops however.



Bug 1568589 - V$SESSION_LONGOPS

Yogesh, January 17, 2006 - 8:40 am UTC

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


Tom Kyte
January 17, 2006 - 9:09 am UTC

query only for rows where time_remaining > 0

the rest of them may well be

a) leftover from something old
b) uninitialized

Bug 1568589 - V$SESSION_LONGOPS

A reader, January 17, 2006 - 9:22 am UTC

So is it Bug 1568589 - V$SESSION_LONGOPS?

Tom Kyte
January 17, 2006 - 10:13 am UTC

remember, not all bugs are bugs. Everything is filed at a "bug", not all bugs are actually bugs.

But, tell us - if you retrieve only rows that MEAN something, where time_remaining>0, what do you see

a) correct valid information
b) incorrect, invalid information

?

Because ONLY the rows with time_remaining >0 are sensible to look at, the rest are meaningless and the values contained therein not relevant.

Bug 1568589 - V$SESSION_LONGOPS

Yogesh, January 17, 2006 - 10:38 am UTC

Output of

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

Query is still executing ...


Tom Kyte
January 17, 2006 - 4:01 pm UTC

then perhaps that query is not the type of query that appears in v$session_longops.

Many do not. A nested loops join for example - typically will not (no one big long operation - just millions or billions of short, small, hardly measurable ones).

So, are you running a query that in fact would normally appear in v$session longops.

(given that time remaining is not > 0, i would say "no")

no v$session_longops for large table query

David Lee, July 05, 2006 - 11:59 am UTC

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.

Tom Kyte
July 08, 2006 - 8:13 am UTC

v$session_longops measures long running operations.... Eg: a full scan is a long running operation.

But a nested loops join - nope, it is not. It is hundreds or millions or billions or whatever of "little" operations.

So, look at your query, if it is long running (must be), perhaps it is using an index when it really shouldn't be.

select /*+ index(idl_sb4$ i_idl_sb41) +*/ max(version) from idl_sb4$

Fayyaz ZAHEER, July 12, 2006 - 2:43 am UTC

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

Tom Kyte
July 12, 2006 - 4:23 pm UTC

so? it does not look like it used very many resources.

each execution took about 1/1000th of a second and 1/10,000th of a CPU second

Instead of looking at queries "run a lot", look at queries that "do a lot" - makes more sense right?




Progress through a Cursor

Yuan, July 24, 2006 - 3:10 pm UTC

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.

Tom Kyte
July 24, 2006 - 4:18 pm UTC

my favorite way is "guess"

guess - like google guesses (about NNNNNN - search and read it)

guess - like I guess (do some searches on my page, I say "about")

guess - it need not be perfect.

Why table scan suddenly taking time?

Chandan Singh, July 26, 2006 - 3:02 am UTC

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

Tom Kyte
July 26, 2006 - 10:41 am UTC

I'll bet that you are using "cooked files" (a regular file system)

You have run the scan and control-c'ed it.
When you run again, the table is cached in your secondary SGA - the OS File system cache :)

That is one guess. The other would be - we moved to a different set of disks and they are not quite as good as the first were.

If the IO rates vary - it is not because of Oracle, it is because the OS is taking longer at various points. Look to the disk.

Progress Through a Cursor (continued)

Yuan, July 26, 2006 - 11:32 am UTC

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?

Tom Kyte
July 26, 2006 - 12:01 pm UTC

well, by definition - they are not "done", as far as anyone is concerned, it is STILL GOING.

this is a bug in the program - when it is done, it must say "I am done"

Else, it is not done - by definition.

There cannot be a way to "filter this out", think about it :) Someone said "i have 100 things to do, I am currently working on thing 42". Now, suppose there were only 42 things - how does anyone (except the program calling longops to set the values) KNOW THAT IT IS IN FACT DONE. We don't, you don't, only they do.

Log a bug with the developer of that procedure, they have one.

Progress through a Cursor (continued #2)

Yuan, July 26, 2006 - 12:31 pm UTC

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?

Tom Kyte
July 26, 2006 - 1:36 pm UTC

think about this for a minute.

You and I are talking.

You start by telling me "I have one hundred things to do"
I say "great, thats nice"
You say "I am on thing 1"
I say "cool, very good"
You say ......
I say ....
You say "I am on thing 42"
I say "cool, very good"


Now, you stop telling me anything. Are you done?

When you answer that, then and only then will we know.



The bug is for them to NOT come back and say "I just finished thing 100"

That is what is buggy here. They said "100". They never came back and said "we just finished"

All they need to do is FINISH - tell us "we just finished thing 100"

Then, and only then, do we know "they are done"

Progress through a Cursor (continued #3)

Yuan, July 26, 2006 - 2:28 pm UTC

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.

Progress through a Cursor (continued #4)

Yuan, July 26, 2006 - 3:43 pm UTC

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;
/

Tom Kyte
July 26, 2006 - 4:14 pm UTC

I believe you ;)



discrepancy with v$session_longops and 10046 trace

Ryan, October 25, 2006 - 1:30 pm UTC

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)

Tom Kyte
October 25, 2006 - 4:06 pm UTC

longops times LONG OPERATIONS

you would never see table_c in longops - it is accessed A LOT but VERY QUICKLY (the range scan - fast, the table access index rowid - fast, do lots of very fast things A LOT and it is slow in the aggregate. Bottom line - table_c has NO LONG RUNNING OPERATIONS

let us say you execute:

select * from a, b where a.key = b.key and a.field > 0;

Say the plan is:

hash join
table access full a
table access full b

you'll likely see A and B in v$session long ops as the full scan takes more then 3 seconds (perhaps...)

Now say the plan is:

nested loops
table access A by index rowid
index range scan idx_a
table access B by index rowid
index range scan idx_b


you'll never see ANYTHING in v$session longops in the second case - there are no long running operations - just billions of short ones over and over and over...

Dave Martin, November 03, 2006 - 4:55 am UTC

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..

Tom Kyte
November 03, 2006 - 10:33 am UTC

depends on what is happening there.

for example, here is my true, actual output from v$session_longops:

.SID : 148
.SERIAL# : 1469
.OPNAME : Table Scan
.TARGET : BIG_TABLE.BIG_TABLE
.TARGET_DESC :
.SOFAR : 5
.TOTALWORK : 14623
.UNITS : Blocks
.START_TIME : 03-nov-2006 10:22:12
.LAST_UPDATE_TIME : 03-nov-2006 10:22:42
.TIMESTAMP :
.TIME_REMAINING : 87708
.ELAPSED_SECONDS : 30
.CONTEXT : 0
.MESSAGE : Table Scan: BIG_TABLE.BIG_TABLE: 5 out of
14623 Blocks done
.USERNAME : BIG_TABLE
.SQL_ADDRESS : 444531B4
.SQL_HASH_VALUE : 1986475899
.SQL_ID : cb8gdm5v6fdvv
.QCSID : 0


Now, that is 5 blocks in 30 seconds. That seems very very slow.

In fact, just came back and look:

.SID : 148
.SERIAL# : 1469
.OPNAME : Table Scan
.TARGET : BIG_TABLE.BIG_TABLE
.TARGET_DESC :
.SOFAR : 9
.TOTALWORK : 14623
.UNITS : Blocks
.START_TIME : 03-nov-2006 10:22:12
.LAST_UPDATE_TIME : 03-nov-2006 10:23:12
.TIMESTAMP :
.TIME_REMAINING : 97427
.ELAPSED_SECONDS : 60
.CONTEXT : 0
.MESSAGE : Table Scan: BIG_TABLE.BIG_TABLE: 9 out of
14623 Blocks done
.USERNAME : BIG_TABLE
.SQL_ADDRESS : 444531B4
.SQL_HASH_VALUE : 1986475899
.SQL_ID : cb8gdm5v6fdvv
.QCSID : 0


9 blocks in sixty seconds!!! IO problem right?

wrong..... here is the code processing this select:

big_table%ORA10GR2> create or replace procedure proc
2 as
3 begin
4 for x in ( select big_table.*, rownum from big_table )
5 loop
6 dbms_lock.sleep(0.1);
7 dbms_application_info.set_client_info( x.rownum );
8 end loop;
9 end;
10 /

Procedure created.

big_table%ORA10GR2>
big_table%ORA10GR2> exec proc


slow code, not slow full scan :)

v$session_longops and partition_name

Sokrates, February 26, 2007 - 6:18 am UTC

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'
Tom Kyte
February 26, 2007 - 3:07 pm UTC

v$session_longops would not need that - they can just pop that into the existing columns - the target description for example.

since - each partition is instrumented separately already (if you have an 8 partition table and each partition takes 2 seconds to full scan - no report in longops - if the same table is in two partitions and each takes 8 seconds to full scan - you'll have entries come and go in longops, one each for the partition)

all enhancements are filed via metalink however ;)

thx

Sokrates, February 27, 2007 - 4:01 am UTC

I've filed an enhancement request

long operation , table scan

abz, April 10, 2007 - 8:10 am UTC

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.

Tom Kyte
April 10, 2007 - 10:57 am UTC

without seeing the query - one can only surmise that you have a full scan that invokes yet another full scan - and hence you have two long running operations nested.

query

abz, April 10, 2007 - 12:44 pm UTC

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



the plan

abz, April 10, 2007 - 12:47 pm UTC

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>

Question on V$session_longops

DK, January 03, 2008 - 6:31 am UTC

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
Tom Kyte
January 03, 2008 - 11:35 am UTC

insert into t select * from t2;

that will appear in v$session_longops if t2 is long enough because a full scan of t2 will take more than 3-5 seconds....


insert into t select * from t1, t2 where <some condition> and <some join>

that MAY OR MAY NOT appear - if the plan is:

hash join
  full scan t1
  full scan t2


each of the full scans will likely appear as discrete long running steps in v$session_longops - however, if the plan is:

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


then it will NOT appear in v$session longops - since there is no single LONG RUNNING OPERATION, but potentially millions or billions of short ones.

long running queries do not appear in v$session_longops, long running discrete operations do. nested loops - not likely to appear in v$session_longops, full scans - yes.

so, it is likely your create table as select is using an inefficient plan and not full scanning, but is doing lots of smallish operations.


no mention of a release or version or os or anything...

DK, January 04, 2008 - 3:08 am UTC

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

Tom Kyte
January 04, 2008 - 11:57 am UTC

I just took a 1,000,000 row table and did a create table as select from it in 817 and v$session_longops was populated:

.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
-----------------


so, I think that your query with your create table as select is one that does lots of short things.

when I went to index this table:

.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
-----------------


was visible...

Thanks a lot Tom

DK, January 07, 2008 - 12:55 am UTC


serial#

Rick Davis, February 19, 2008 - 11:41 am UTC

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 ;
/


Tom Kyte
February 19, 2008 - 5:11 pm UTC

gee, for me, it won't compile :(

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


and even if I make it on a table I have, still no go

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');



but if I fix that, it seems to work ok

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.


when you say to someone "but it fails", it is generally useful to say "how", how it fails, the symptoms, what you observe

and to provide a test case they can run to see it too.

serial#

Rick Davis, February 20, 2008 - 11:14 am UTC

Tom, thanks for your help on this issue; turns out the session account did not have Data Dictionary visibility.
Tom Kyte
February 20, 2008 - 12:47 pm UTC

meaning, the trigger never compiled of course.

triggers run as owner/definer.
this trigger failed compilation.

This:

The following trigger compiles, but fails at execution time.


is not true.

V$SESSION_LONGOPS for import

Amir Riaz, February 20, 2008 - 1:41 pm UTC

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
Tom Kyte
February 20, 2008 - 2:41 pm UTC

how about feedback=100

that'll put out little dots as it is inserting into tables, show progress.

imp is not instrumented with calls to dbms_application_info unfortunately.

Import speed

Michel Cadot, February 20, 2008 - 3:06 pm UTC


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

ricardinho, July 08, 2008 - 10:01 am UTC

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?
Tom Kyte
July 08, 2008 - 10:22 am UTC

in your long running procedure, did you make calls to dbms_application_info.set_session_longops?

look for examples on this page.

If you did not, there will be nothing in there - you have to instrument your code if you want to see it in there - we don't know how many steps you have (only you do), we do not know when you complete a given step (only you do)

We instrument things we manage - we are just running your procedure, you need to tell us how far along you are (we don't know that until you are done)

Gints Plivna, July 08, 2008 - 10:40 am UTC

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.

ricardinho, July 09, 2008 - 4:46 am UTC

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?

Tom Kyte
July 09, 2008 - 10:40 am UTC

you need to

a) understand what set session longops does
b) what you are doing

and then - it'll be obvious.


if your sql is select sysdate into t from dual, it should be:

declare
t date := sysdate;
begin
null;
end;

instead - never select sysdate/user/whatever from dual, just assign. In any case, you will figure out how many times you will call set_session_longops (I used totalwork => 10, I will call it 10 times - no more, no less). You will figure out how many times YOU will call it - the answer is not 10, it is some number YOU figure out based on what you do

and then you call it that many times during your processing to let the outside world know how far along you are.

Execution time for Package

Abhisek, September 16, 2010 - 1:53 pm UTC

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..
Tom Kyte
September 16, 2010 - 2:39 pm UTC

think about this for a minute....


IF the programer used dbms_application_info.set_session_longops

AND if the programmer used it "intelligently"

AND if the program has predicable, same sized units of work it does

then - you might be able to (ctl-f for dbms_application_info.set_session_longops
on this page, examples are here)


Otherwise, we have no idea, you have no idea, no one has any idea how long a piece of code will be executing for...

Trying to understand longops ..

Ditto, March 10, 2011 - 10:25 am UTC

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?

Tom Kyte
March 10, 2011 - 10:50 am UTC

each individual long operation will get it's own entry in longops - it is not for the PROCESS - but for the steps within the process.

for example, if you have a plan like:

hash join
full scan A
full scan B


you MIGHT see a long ops for the scan of B, then you MIGHT see a long ops for a scan of A.

so, with the parallel operation, you'll see lots of "little BIG things" monitored, each one independent of the other.

If you want to monitor the overall execution of a query (even a parallel one) you'll need the new SQL monitoring tool in 11g - it shows you the overall execution of any *query* (not just a step in the query, the entire query) graphically in enterprise manager.


Thx

Ditto, March 10, 2011 - 11:03 am UTC

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

Thanks again!

David, September 09, 2017 - 5:28 am UTC

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?
Connor McDonald
September 13, 2017 - 7:59 am UTC

From the docs:

SOFAR
- Units of work done so far for the operation specified in the OPNAME column

TOTALWORK
- Total units of work for the operation specified in the OPNAME column

So if we're doing a full table scan, we might estimate (say) 1000 blocks to be read. That will be "TOTALWORK". If so far (hint) we have read 300 blocks, then SOFAR will be 300.

Hence SOFAR / TOTALWORK is a percentage completed.

Continuing the example, START_TIME is when we commenced the full scan, and LAST_UPDATE_TIME is the moment when we updated "SOFAR" (and other variables) to their current values. So as you near completion, LAST_UPDATE_TIME becomes closer to the final completion time.