########################################################################################################### ## This file is part of http://www.gplivna.eu/papers/v$session_longops.htm ## Preparing table and data ########################################################################################################### SQL> set timing on SQL> set arraysize 100 SQL> select sid, serial# from v$session where username = 'GINTS'; SID SERIAL# ---------- ---------- 140 12 Elapsed: 00:00:00.06 SQL> create table big as select * from dba_source; Table created. Elapsed: 00:00:06.23 SQL> insert /*+ append */ into big select * from big; 280753 rows created. Elapsed: 00:00:05.59 SQL> commit; Commit complete. Elapsed: 00:00:00.14 SQL> insert /*+ append */ into big select * from big; 561506 rows created. Elapsed: 00:00:09.51 SQL> commit; Commit complete. Elapsed: 00:00:00.01 SQL> insert /*+ append */ into big select * from big; 1123012 rows created. Elapsed: 00:00:16.90 SQL> commit; Commit complete. Elapsed: 00:00:00.01 SQL> insert /*+ append */ into big select * from big; 2246024 rows created. Elapsed: 00:00:56.50 SQL> commit; Commit complete. Elapsed: 00:00:00.01 SQL> exec dbms_stats.gather_table_stats(user, 'big', cascade =>false) PL/SQL procedure successfully completed. Elapsed: 00:00:32.59 ########################################################################################################### ## Now making case ONE ## A simple select ########################################################################################################### SQL> select count(*) from v$session_longops; COUNT(*) ---------- 18 Elapsed: 00:00:00.04 SQL> set autotrace traceonly SQL> select * from big; 4492048 rows selected. Elapsed: 00:01:39.75 Execution Plan ---------------------------------------------------------- Plan hash value: 3907642201 -------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 4376K| 479M| 20827 (1)| 00:04:10 | | 1 | TABLE ACCESS FULL| BIG | 4376K| 479M| 20827 (1)| 00:04:10 | -------------------------------------------------------------------------- Statistics ---------------------------------------------------------- 1 recursive calls 0 db block gets 138077 consistent gets 89704 physical reads 0 redo size 552862398 bytes sent via SQL*Net to client 494505 bytes received via SQL*Net from client 44922 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 4492048 rows processed SQL> set autot off SQL> select count(*) from v$session_longops; COUNT(*) ---------- 19 Elapsed: 00:00:00.01 ########################################################################################################### ## As you can see one more long operation than before last select ## We will get the last long operation ## Elapsed seconds are 100 which is approx the same as 1 minute and 39.75 secs according to sqlplus timing ########################################################################################################### SQL> select * from ( 2 select opname, target, totalwork, units, 3 elapsed_seconds, message 4 from v$session_longops 5 where sid = 140 and serial# = 12 6 order by start_time desc) 7 where rownum <= 1; OPNAME ---------------------------------------------------------------- TARGET TOTALWORK ---------------------------------------------------------------- ---------- UNITS ELAPSED_SECONDS -------------------------------- --------------- MESSAGE -------------------------------------------------------------------------------- Table Scan GINTS.BIG 94577 Blocks 100 Table Scan: GINTS.BIG: 94577 out of 94577 Blocks done Elapsed: 00:00:00.03 SQL> set autotrace traceonly ########################################################################################################### ## Now making case TWO ## A select with filter ########################################################################################################### SQL> select * from big where length(text) = 100; 784 rows selected. Elapsed: 00:00:29.23 Execution Plan ---------------------------------------------------------- Plan hash value: 3907642201 -------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 43766 | 4915K| 20862 (1)| 00:04:11 | |* 1 | TABLE ACCESS FULL| BIG | 43766 | 4915K| 20862 (1)| 00:04:11 | -------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(LENGTH("TEXT")=100) Statistics ---------------------------------------------------------- 1 recursive calls 0 db block gets 94127 consistent gets 89506 physical reads 0 redo size 74320 bytes sent via SQL*Net to client 462 bytes received via SQL*Net from client 9 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 784 rows processed SQL> set autot off SQL> select count(*) from v$session_longops; COUNT(*) ---------- 20 ############################################################################################### ## As you can see one more long operation than before last select ## We will get the last long operation ## Elapsed seconds are 30 which is approx the same as 29.23 secs according to sqlplus timing ############################################################################################### Elapsed: 00:00:00.00 SQL> select * from ( 2 select opname, target, totalwork, units, 3 elapsed_seconds, message 4 from v$session_longops 5 where sid = 140 and serial# = 12 6 order by start_time desc) 7 where rownum <= 1; OPNAME ---------------------------------------------------------------- TARGET TOTALWORK ---------------------------------------------------------------- ---------- UNITS ELAPSED_SECONDS -------------------------------- --------------- MESSAGE -------------------------------------------------------------------------------- Table Scan GINTS.BIG 94577 Blocks 30 Table Scan: GINTS.BIG: 94577 out of 94577 Blocks done Elapsed: 00:00:00.01 ########################################################################################################### ## Now making case THREE ## Index creation ########################################################################################################### SQL> create index big_idx on big (owner, name, line); Index created. Elapsed: 00:01:21.90 SQL> select count(*) from v$session_longops; COUNT(*) ---------- 22 Elapsed: 00:00:00.00 ########################################################################################################### ## This time we have two long operations Table Scan and Sort Output ## We will get the last 2 long operations ## Elapsed seconds are 48 + 33 which is approx the same as 1 min and 21.90 secs according to sqlplus timing ########################################################################################################### SQL> select * from ( 2 select opname, target, totalwork, units, 3 elapsed_seconds, message 4 from v$session_longops 5 where sid = 140 and serial# = 12 6 order by start_time desc) 7 where rownum <= 2; OPNAME ---------------------------------------------------------------- TARGET TOTALWORK ---------------------------------------------------------------- ---------- UNITS ELAPSED_SECONDS -------------------------------- --------------- MESSAGE -------------------------------------------------------------------------------- Sort Output 24138 Blocks 48 Sort Output: : 24138 out of 24138 Blocks done Table Scan GINTS.BIG 94577 Blocks 33 Table Scan: GINTS.BIG: 94577 out of 94577 Blocks done Elapsed: 00:00:00.04 ########################################################################################################### ## Now making case FOUR ## Alter table modify column from NULL to NOT NULL ########################################################################################################### SQL> alter table big modify (owner not null); Table altered. Elapsed: 00:00:20.10 SQL> select count(*) from v$session_longops; COUNT(*) ---------- 23 Elapsed: 00:00:00.01 ############################################################################################### ## As you can see one more long operation than before last example ## We will get the last long operation ## Elapsed seconds are 21 which is approx the same as 20.10 secs according to sqlplus timing ############################################################################################### SQL> select * from ( 2 select opname, target, totalwork, units, 3 elapsed_seconds, message 4 from v$session_longops 5 where sid = 140 and serial# = 12 6 order by start_time desc) 7 where rownum <= 1; OPNAME ---------------------------------------------------------------- TARGET TOTALWORK ---------------------------------------------------------------- ---------- UNITS ELAPSED_SECONDS -------------------------------- --------------- MESSAGE -------------------------------------------------------------------------------- Table Scan GINTS.BIG 94577 Blocks 21 Table Scan: GINTS.BIG: 94577 out of 94577 Blocks done Elapsed: 00:00:00.03 ############################################################################################### ## Now lets make another table for nested loops ############################################################################################### SQL> create table objects as 2 select * from ( 3 select distinct owner, name from dba_source) 4 where rownum <=100; Table created. Elapsed: 00:00:01.23 SQL> create index obj_idx on objects (name, owner); Index created. Elapsed: 00:00:00.07 SQL> alter table objects modify (name not null, owner not null); Table altered. Elapsed: 00:00:00.04 SQL> exec dbms_stats.gather_table_stats(user, 'objects'); PL/SQL procedure successfully completed. Elapsed: 00:00:00.67 ############################################################################################### ## See how many long ops before this example ############################################################################################### SQL> select count(*) from v$session_longops; COUNT(*) ---------- 24 Elapsed: 00:00:00.01 SQL> set autot trace ########################################################################################################### ## Now making case FIVE ## FULL SCAN of the BIG table with Nested loops join to obj_idx index ########################################################################################################### SQL> select /*+ full (big) use_nl(big, objects) */ * 2 from big, objects 3 where big.name = objects.name; 551648 rows selected. Elapsed: 00:01:16.98 Execution Plan ---------------------------------------------------------- Plan hash value: 1114503144 ------------------------------------------------------------------------------ | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | 671K| 80M| 23436 (12)| 00:04:42 | | 1 | NESTED LOOPS | | 671K| 80M| 23436 (12)| 00:04:42 | | 2 | TABLE ACCESS FULL| BIG | 4376K| 479M| 20827 (1)| 00:04:10 | |* 3 | INDEX RANGE SCAN | OBJ_IDX | 1 | 11 | 1 (0)| 00:00:01 | ------------------------------------------------------------------------------ Predicate Information (identified by operation id): --------------------------------------------------- 3 - access("BIG"."NAME"="OBJECTS"."NAME") Statistics ---------------------------------------------------------- 195 recursive calls 0 db block gets 110544 consistent gets 91545 physical reads 0 redo size 61682552 bytes sent via SQL*Net to client 61061 bytes received via SQL*Net from client 5518 SQL*Net roundtrips to/from client 5 sorts (memory) 0 sorts (disk) 551648 rows processed SQL> set autot off ############################################################################################### ## As you can see one more long operation than before last example ## We will get the last long operation ## Elapsed seconds are 78 which is approx the same as 1 min and 16.98 secs according to sqlplus timing ############################################################################################### SQL> select count(*) from v$session_longops; COUNT(*) ---------- 25 Elapsed: 00:00:00.00 SQL> select * from ( 2 select opname, target, totalwork, units, 3 elapsed_seconds, message 4 from v$session_longops 5 where sid = 140 and serial# = 12 6 order by start_time desc) 7 where rownum <= 1; OPNAME ---------------------------------------------------------------- TARGET TOTALWORK ---------------------------------------------------------------- ---------- UNITS ELAPSED_SECONDS -------------------------------- --------------- MESSAGE -------------------------------------------------------------------------------- Table Scan GINTS.BIG 94577 Blocks 78 Table Scan: GINTS.BIG: 94577 out of 94577 Blocks done Elapsed: 00:00:00.03 ########################################################################################################### ## Now making case SIX ## Cursor which includes FULL SCAN of table BIG ########################################################################################################### SQL> declare 2 cursor c is select * from big; 3 i number; 4 begin 5 for v in c loop 6 i:= i + 1; 7 end loop; 8 end; 9 / PL/SQL procedure successfully completed. Elapsed: 00:00:41.92 ############################################################################################### ## As you can see one more long operation than before last example ## We will get the last long operation ## Elapsed seconds are 40 which is approx the same as 41.92 secs according to sqlplus timing ############################################################################################### SQL> select count(*) from v$session_longops; COUNT(*) ---------- 26 Elapsed: 00:00:00.00 SQL> select * from ( 2 select opname, target, totalwork, units, 3 elapsed_seconds, message 4 from v$session_longops 5 where sid = 140 and serial# = 12 6 order by start_time desc) 7 where rownum <= 1; OPNAME ---------------------------------------------------------------- TARGET TOTALWORK ---------------------------------------------------------------- ---------- UNITS ELAPSED_SECONDS -------------------------------- --------------- MESSAGE -------------------------------------------------------------------------------- Table Scan GINTS.BIG 94577 Blocks 40 Table Scan: GINTS.BIG: 94577 out of 94577 Blocks done Elapsed: 00:00:00.03