v$session_longops

There’s a question on the Oracle developer forum at the moment asking how a tablescan could be reported as taking 94,000 seconds so far when a count(*) shows that it holds only a couple of hundred thousand rows (and it’s not storing megabytes of LOB per row if that’s your first guess).

I can think of a few reasons so I don’t know if I’ve supplied the correct explanation for the OP’s example, but it prompted me to point out that Oracle can provide several different perspectives on performance that can seem to be counter-intuitive or contradictory if you don’t realise what they’re trying to tell you.

The data supplied by the OP was initially not very readable so I’ll just point out that v$session_longops can report the sql_id, plan_hash_value and line_id for each operation, so when it reports a message like:

Table Scan: XXXXXXXXX: 158204 out of 204924 Blocks done

you can pull the query and execution plan from memory very easily.

This is the execution plan – with some cosmetic cleaning – supplied by the OP, with the comment that the tablescan reported by v$session_longops was operation 22 (highlighted):

SORT AGGREGATE
  VIEW 
    UNION-ALL 
      FILTER 
        HASH JOIN OUTER
          FILTER 
            HASH JOIN RIGHT OUTER
              INLIST ITERATOR 
                TABLE ACCESS BY INDEX ROWID BATCHED VAC_000087FD
                  INDEX RANGE SCAN I_220101_VAC_000087FD_1
              TABLE ACCESS FULL VLD_00008866
          TABLE ACCESS FULL CCH_00008868
      HASH JOIN ANTI SNA
        FILTER 
          NESTED LOOPS OUTER
            FILTER 
              HASH JOIN RIGHT OUTER
                VIEW 
                  HASH JOIN RIGHT ANTI SNA
                    INDEX FULL SCAN SYS_C00364276
                    TABLE ACCESS FULL VAC_00006D1B
                TABLE ACCESS FULL VLD_00006D22
            VIEW PUSHED PREDICATE 
              FILTER 
                MERGE JOIN ANTI NA
                  SORT JOIN
                    TABLE ACCESS BY INDEX ROWID BATCHED CCH_00007BB0
                      INDEX FULL SCAN SYS_C00353046
                  SORT UNIQUE
                    TABLE ACCESS FULL LNK_00008614
        INDEX FAST FULL SCAN SYS_C00364277
      HASH JOIN ANTI SNA
        FILTER 
          NESTED LOOPS OUTER
            FILTER 
              HASH JOIN RIGHT OUTER
                VIEW 
                  HASH JOIN ANTI SNA
                    TABLE ACCESS FULL VAC_00007C1D
                    INDEX FULL SCAN SYS_C00365638
                TABLE ACCESS FULL VLD_00007C24
            VIEW PUSHED PREDICATE 
              FILTER 
                MERGE JOIN ANTI NA
                  SORT JOIN
                    TABLE ACCESS BY INDEX ROWID BATCHED CCH_00007C26
                      INDEX FULL SCAN SYS_C00353233
                  SORT UNIQUE
                    TABLE ACCESS FULL LNK_00008787
        INDEX FAST FULL SCAN SYS_C00365640
      HASH JOIN ANTI SNA
        FILTER 
          HASH JOIN OUTER
            FILTER 
              HASH JOIN RIGHT OUTER
                VIEW 
                  HASH JOIN ANTI SNA
                    INLIST ITERATOR 
                      TABLE ACCESS BY INDEX ROWID BATCHED VAC_00006CC2
                        INDEX RANGE SCAN I_200101_VAC_00006CC2_1
                    INDEX FULL SCAN SYS_C00364113
                TABLE ACCESS FULL VLD_00006CC9
            VIEW 
              HASH JOIN RIGHT ANTI NA
                TABLE ACCESS FULL LNK_000084B2
                TABLE ACCESS FULL CCH_00007BAB
        INDEX FAST FULL SCAN SYS_C00364114
      HASH JOIN ANTI SNA
        FILTER 
          HASH JOIN OUTER
            FILTER 
              HASH JOIN RIGHT OUTER
                VIEW 
                  HASH JOIN RIGHT ANTI SNA
                    INDEX FULL SCAN SYS_C00364266
                    TABLE ACCESS FULL VAC_00006CE2
                TABLE ACCESS FULL VLD_00006CE9
            VIEW 
              HASH JOIN RIGHT ANTI NA
                TABLE ACCESS FULL LNK_000085F0
                TABLE ACCESS FULL CCH_00007BAC
        INDEX FAST FULL SCAN SYS_C00364267
      FILTER 
        HASH JOIN OUTER
          FILTER 
            HASH JOIN RIGHT OUTER
              TABLE ACCESS FULL VAC_00008613
              TABLE ACCESS FULL VLD_00008612
          TABLE ACCESS FULL CCH_00008617
      FILTER 
        HASH JOIN OUTER
          FILTER 
            HASH JOIN OUTER
              TABLE ACCESS FULL VLD_00008785
              TABLE ACCESS FULL VAC_00008786
          TABLE ACCESS FULL CCH_0000878A
      FILTER 
        HASH JOIN OUTER
          FILTER 
            HASH JOIN RIGHT OUTER
              TABLE ACCESS FULL VAC_000084B1
              TABLE ACCESS FULL VLD_000084B0
          TABLE ACCESS FULL CCH_000084B5
      FILTER 
        HASH JOIN OUTER
          FILTER 
            HASH JOIN OUTER
              TABLE ACCESS FULL VLD_000085EE
              TABLE ACCESS FULL VAC_000085EF
          TABLE ACCESS FULL CCH_000085F3

The quick answer to the OP’s question is that operation 22 is the second child to a hash join (operation 17) that passes its rowsource through a FILTER operation (16) to become the first child of a nested loop (operation 15).

This means operation 22 is passing its rows up the tree one row at a time (it’s the probe table, not the build table) and the time it takes to process each row is dictated by the second child of the nested loop join. In other words – it might take a tiny amount of work to do the tablescan, but the elapsed time for the tablescan to complete is dictated by the time it takes to call the view (operation 23) for every single row that survives the journey up to operation 15.

Demo

To demonstrate the principle that the “working time” for an operation and the elapsed time to completion can be dramatically different I’ll set up a two-table join and show that a “small tablescan” can (apparently) take a long time and get into v$session_longops because of “the other” table. As a quick and dirty trick I’ll create a function that calls dbms_session.sleep() – the function that should be used to replace calls to dbms_lock.sleep()– to sleep for 1/100 second.

create table t1
as
with generator as (
        select 
                rownum id
        from dual 
        connect by 
                level <= 1e4    -- > comment to avoid WordPress format issue
)
select
        rownum                          id,
        rownum                          n1,
        lpad(rownum,10,'0')             v1,
        lpad('x',100,'x')               padding
from
        generator       v1,
        generator       v2
where
        rownum <= 1e6   -- > comment to avoid WordPress format issue
;

create table t2 as select * from t1;
alter table t2 add constraint t2_pk primary key(id);


create or replace function waste_time(i_in number) return number
as
begin
        dbms_session.sleep(0.01);
        return i_in;
end;
/

With the data and function in place I’ll code (and hint) a nested loop join that starts with a full tablescan of t1 and probes t2 by primary key 1,000 times.

set timing on

select
        /*+ leading(t1 t2) full(t1) use_nl_with_index(t2) */
        sum(t1.id)
from
        t1, t2
where
        mod(t1.id,1000) = 0
and     t2.id  = t1.id
and     t2.n1 != 0
/

select
        /*+ leading(t1 t2) full(t1) use_nl_with_index(t2) */
        sum(t1.id)
from
        t1, t2
where
        mod(t1.id,1000) = 0
and     t2.id  = t1.id
and     waste_time(t2.n1) != 0
/

set timing off

Of course, thanks to the call to waste_time() passing in t2.n1 I expect the second version of the query to take at least 10 seconds longer than the first (given 1,000 waits of 0.01 seconds spent in the call).

SUM(T1.ID)
----------
 500500000

1 row selected.

Elapsed: 00:00:00.26

SUM(T1.ID)
----------
 500500000

1 row selected.

Elapsed: 00:00:14.39

So the question is – what does v$session_longops say about any “long operations” for my session? Query and result:

select 
        sql_id, 
        sql_plan_line_id,
        to_char(vsl.start_time,'dd hh24:mi:ss') start_time, 
        to_char(vsl.last_update_time,'dd hh24:mi:ss') last_time, 
        vsl.elapsed_seconds,
        vsl.message 
from 
        V$session_Longops vsl
where 
        vsl.sid = (select ms.sid from v$mystat ms where rownum = 1)
/

SQL_ID        SQL_PLAN_LINE_ID START_TIME                LAST_TIME   ELAPSED_SECONDS
------------- ---------------- ------------------------- ----------- ---------------
MESSAGE
------------------------------------------------------------------------------------------------------------------------------------
cqv88nkkvrwpv                4 13 09:56:21               13 09:56:35              14
Table Scan:  TEST_USER.T1: 18020 out of 18020 Blocks done

So that looks like 14 seconds to do a tablescan of just 18,020 blocks. The number is very similar to the elapsed time reported for the second of my two queries – but just to make sure let’s use the reported SQL ID to pull the query and plan from memory and check operation 4 for a tablescan of t1.

select * from table(dbms_xplan.display_cursor('cqv88nkkvrwpv', format=>'hint_report'));


PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  cqv88nkkvrwpv, child number 0
-------------------------------------
select  /*+ leading(t1 t2) full(t1) use_nl_with_index(t2) */
sum(t1.id) from  t1, t2 where  mod(t1.id,1000) = 0 and t2.id  = t1.id
and waste_time(t2.n1) != 0

Plan hash value: 1846150233

---------------------------------------------------------------------------------------
| Id  | Operation                     | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |       |       |       | 24956 (100)|          |
|   1 |  SORT AGGREGATE               |       |     1 |    15 |            |          |
|   2 |   NESTED LOOPS                |       | 10000 |   146K| 24956   (1)| 00:00:01 |
|   3 |    NESTED LOOPS               |       | 10000 |   146K| 24956   (1)| 00:00:01 |
|*  4 |     TABLE ACCESS FULL         | T1    | 10000 | 50000 |  4936   (2)| 00:00:01 |
|*  5 |     INDEX UNIQUE SCAN         | T2_PK |     1 |       |     1   (0)| 00:00:01 |
|*  6 |    TABLE ACCESS BY INDEX ROWID| T2    |     1 |    10 |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - filter(MOD("T1"."ID",1000)=0)
   5 - access("T2"."ID"="T1"."ID")
   6 - filter("WASTE_TIME"("T2"."N1")<>0)

Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 3
---------------------------------------------------------------------------

   1 -  SEL$1
           -  leading(t1 t2)

   4 -  SEL$1 / T1@SEL$1
           -  full(t1)

   5 -  SEL$1 / T2@SEL$1
           -  use_nl_with_index(t2)

Summary

When you see an entry in v$session_longops it is an indicator to an operation that took a “long” time to complete; but “completion” of the operation and “work done” by the operation are not the same thing. The operation may be the victim of a problem, not the cause. If the problem query is still in memory then v$session_long_ops gives you enough information to find the query (and check you’re looking at the right plan) so that you have a better chance of identifying the real offender.