21 January, 2009

When NOT to use V$SESSION_LONGOPS

Many of us frequently use V$SESSION_LONGOPS to monitor long running SQL operations. This makes sense for long running *queries*. Be careful when you attempt to monitor DML operations (UPDATE or DELETE) on the table undergoing a FullTableScan. I've seen DBAs make the mistake of assuming that the time prediction from V$SESSION_LONGOPS is accurate and wondering why it seems to show that a particular session is running an operation that will take many hours to run.
V$SESSION_LONGOPS does report the FullTableScan. However, when executing DML like UPDATE and DELETE operations you must remember that *Indexes* on the table need to be updated. For every row that undergoes an UPDATE or DELETE, Index blocks need to be fetched (Oracle has to "walk" the Index to get to the correct leaf block in each case) and updated. UPDATEs require only Indexes on the modified columns. But DELETEs mean that Oracle must "update" every Index on the table.
The time spent to fetch the correct Index block and update it will not be accurately reflected in V$SESSION_LONGOPS which only monitors table blocks and attempts to predict the duration of the FullTableScan.

Here is a simple case study. I start with my TARGET_TABLE which is a "multiplied" copy of DBA_OBJECTS -- ie, I've repeatedly copied from DBA_OBJECTS into TARGET_TABLE to create a table with 7.3million rows.

23:20:10 SQL> select /*+ FULL (t) */ count(*) from target_table t;

COUNT(*)
----------
7353263

Elapsed: 00:00:19.44
23:20:30 SQL> select /*+ FULL (t) */ count(*) from target_table t where owner = 'SYS';

COUNT(*)
----------
5130305

Elapsed: 00:00:14.84
23:20:45 SQL> select /*+ FULL (t) */ count(*) from target_table t where owner = 'SYS' and object_type in ('TABLE','VIEW');

COUNT(*)
----------
513482

Elapsed: 00:00:05.68


Thus, we can see that a FullTableScan takes 5.7seconds to 19.5seconds.

23:20:50 SQL> select blocks, num_rows, sample_size from user_tables where table_name = 'TARGET_TABLE';

BLOCKS NUM_ROWS SAMPLE_SIZE
---------- ---------- -----------
102500 7353263 7353263

23:20:51 SQL> select num_rows, leaf_blocks from user_indexes where index_name = 'TARGET_TABLE_NDX_1';

NUM_ROWS LEAF_BLOCKS
---------- -----------
7353263 40906

23:20:51 SQL> select num_rows, leaf_blocks from user_indexes where index_name = 'TARGET_TABLE_NDX_2';

NUM_ROWS LEAF_BLOCKS
---------- -----------
7353263 45849

23:20:51 SQL> select column_position, column_name from user_ind_columns where index_name = 'TARGET_TABLE_NDX_1';

COLUMN_POSITION COLUMN_NAME
--------------- ------------------------------
1 OWNER
2 OBJECT_NAME

23:20:51 SQL> select column_position, column_name from user_ind_columns where index_name = 'TARGET_TABLE_NDX_2';

COLUMN_POSITION COLUMN_NAME
--------------- ------------------------------
1 OBJECT_NAME
2 OBJECT_TYPE


The table has 7.3million rows in 102,500 blocks and the two indexes on the table 86,750 blocks.

23:21:06 SQL> set timing on
23:21:06 SQL> update /*+ FULL (t) */ target_table t set owner='SYS_U', object_name = substr(object_name,1,15)||'_Updated'
23:21:06 2 where owner = 'SYS' and object_type in ('TABLE','VIEW') ;

513482 rows updated.

Elapsed: 00:04:23.99
23:25:30 SQL> set timing off
23:25:30 SQL>
23:25:30 SQL> @active_transactions
23:25:30 SQL> set echo off

SID SERIAL# SPID USERNAME PROGRAM XIDUSN USED_UBLK USED_UREC LAST_CALL_ET
---------- ---------- ------------ -------- --------------------------- ---------- ---------- ---------- ------------
147 7 5396 HEMANT sqlplus@linux64 (TNS V1-V3) 5 34597 2568456 0

23:25:30 SQL>


If I could do a FullTableScan in less than 20seconds, why did the UPDATE operation take 264seconds ?
Let's review what I see monitoring the update by querying V$SESSION_LONGOPS and V$TRANSACTION :

23:21:12 SQL> @current_longops

SID OPNAME
---------- ----------------------------------------------------------------
TARGET SOFAR TOTALWORK UNITS STARTTIM
---------------------------------------------------------------- ---------- ---------- -------------------------------- --------
TIME_REMAINING
--------------
MESSAGE
------------------------------------------------------------------------------------------------------------------------------------
USERNAME
--------
147 Table Scan
HEMANT.TARGET_TABLE 10 102500 Blocks 23:21:03
92241
Table Scan: HEMANT.TARGET_TABLE: 10 out of 102500 Blocks done
HEMANT


23:21:15 SQL>
23:21:24 SQL> @current_longops

SID OPNAME
---------- ----------------------------------------------------------------
TARGET SOFAR TOTALWORK UNITS STARTTIM
---------------------------------------------------------------- ---------- ---------- -------------------------------- --------
TIME_REMAINING
--------------
MESSAGE
------------------------------------------------------------------------------------------------------------------------------------
USERNAME
--------
147 Table Scan
HEMANT.TARGET_TABLE 1282 102500 Blocks 23:21:03
2132
Table Scan: HEMANT.TARGET_TABLE: 1282 out of 102500 Blocks done
HEMANT


23:21:30 SQL>

Notice how session 147 seemed to have been very slow in the FullTableScan of TARGET_TABLE. In the first 10seconds or so (23:21:03 to 23:21:14/15), it had read only 10 blocks ! At that time, Oracle estimated that the FullTableScan would take 92,241 more seconds ! A very far cry from the "less than 20seconds" for a simple query doing a FullTableScan !
10seconds later, Oracle had seemingly read 1,272 blocks from the table and revised its time estimate to being another 2,132seconds.

23:22:56 SQL> set echo off

SID OPNAME
---------- ----------------------------------------------------------------
TARGET SOFAR TOTALWORK UNITS STARTTIM
---------------------------------------------------------------- ---------- ---------- -------------------------------- --------
TIME_REMAINING
--------------
MESSAGE
------------------------------------------------------------------------------------------------------------------------------------
USERNAME
--------
147 Table Scan
HEMANT.TARGET_TABLE 24371 102500 Blocks 23:21:03
362
Table Scan: HEMANT.TARGET_TABLE: 24371 out of 102500 Blocks done
HEMANT


23:22:56 SQL>

About 1.5 minutes later (from 23:21:30 to 23:22:56) Oracle had read another 23,089 blocks (being 24,371 less 1,282). Now, the estimate was for yet another 362 seconds !

23:25:10 SQL> @current_longops

SID OPNAME
---------- ----------------------------------------------------------------
TARGET SOFAR TOTALWORK UNITS STARTTIM
---------------------------------------------------------------- ---------- ---------- -------------------------------- --------
TIME_REMAINING
--------------
MESSAGE
------------------------------------------------------------------------------------------------------------------------------------
USERNAME
--------
147 Table Scan
HEMANT.TARGET_TABLE 93775 102500 Blocks 23:21:03
23
Table Scan: HEMANT.TARGET_TABLE: 93775 out of 102500 Blocks done
HEMANT


23:25:13 SQL>

As at sometime between 23:25:10 and 23:25:13, the SQL operation of a FullTableScan that began at 23:21:03 was to still take another 23 seconds.


If you were a DBA merely querying V$SESSION_LONGOPS without checking what SQL operation the session was running and/or querying V$TRANSACTION, you might well think that there was something wrong with the hardware ! A 20second FullTableScan was now taking more than 4minutes !
Therefore, remember that it is always important to understand the context ! Session 147 was seemingly doing a FullTableScan, but it was actually using that in an UPDATE.
For every row that it updated (after doing a multiblock read from the table), it had to traverse the two indexes and update the index Leaf Blocks !

This shows what the UPDATE session was actually doing :

Statistic or Wait Val or Cnt Time MS
---------------------------------------------------------- ---------------- -------------
CPU : CPU used by this session 0 131,920.00
Recursive CPU : recursive cpu usage 0 260.00
Recursive CPU double counting: recursive cpu usage 0 -260.00
Statistic : cleanout - number of ktugct calls 3,060
Statistic : cleanouts and rollbacks - consistent read gets 134
Statistic : cleanouts only - consistent read gets 1
Statistic : consistent changes 497
Statistic : consistent gets 105,794
Statistic : consistent gets - examination 3,768
Statistic : consistent gets direct 0
Statistic : consistent gets from cache 105,794
Statistic : db block changes 5,198,292
Statistic : db block gets 8,855,340
Statistic : db block gets direct 0
Statistic : index fast full scans (direct read) 0
Statistic : physical reads 139,555
Statistic : physical reads direct 0
Statistic : physical reads direct (lob) 0
Statistic : physical reads direct temporary tablespace 0
Statistic : physical writes direct 0
Statistic : physical writes direct (lob) 0
Statistic : physical writes direct temporary tablespace 0
Statistic : recursive calls 2,133
Statistic : redo blocks written 0
Statistic : redo entries 2,594,328
Statistic : redo size 667,195,260
Statistic : session pga memory 609,208
Statistic : session pga memory max 2,199,128
Statistic : session uga memory 289,584
Statistic : session uga memory max 1,415,800
Statistic : table fetch by rowid 60
Statistic : table scan blocks gotten 101,188
Statistic : table scan rows gotten 7,354,970
Statistic : table scans (direct read) 0
Statistic : undo change vector size 275,026,980
Statistic : user calls 22
Statistic : user commits 0
Wait : SQL*Net message from client 14 336.46
Wait : SQL*Net message to client 15 .15
Wait : db file parallel read 1 11.13
Wait : db file scattered read 2,828 21,398.91
Wait : db file sequential read 29,675 73,651.06
Wait : events in waitclass Other 75 125.50
Wait : free buffer waits 2,212 31,485.88
Wait : log file switch (private strand flush incomplete) 5 2,212.00
Wait : log file switch completion 2 1,008.97
-------------
sum 262,150.07


Of the 262 seconds, 73seconds were waits on 'db file sequential read' !
The 'table scan' statistics do show 101,188 blocks and 7,354,970 rows read for a FullTableScan.
*BUT* there were 8.8million *blocks* in 'db block gets' and 5.2million *blocks* in 'db block changes'. The table + 2 indexes comprised less than 200thousand blocks and yet we obtained 8.8million blocks in 'current mode' and updated 5.2million of them ? That is because the Index blocks are much more densely packed. For each row that we updated, we visited the index blocks in 'current mode'. Furthermore, since an index Leaf Block contains very many RowIDs (7.3million RowIDs in 40,906 and 45,849 blocks in each of the two indexes), we visited the same Leaf Block multiple times !

What if this had been a large DELETE operation ? The impact of the presence of indexes would have been much worse !

To really verify that the 2 indexes caused us that much grief, let's run the UPDATE without the Indexes :

00:12:12 SQL> set timing on
00:12:12 SQL> drop index target_table_ndx_1;

Index dropped.

Elapsed: 00:00:02.72
00:12:14 SQL> drop index target_table_ndx_2;

Index dropped.

Elapsed: 00:00:00.19
00:12:15 SQL> select /*+ FULL (t) */ count(*) from target_table t;

COUNT(*)
----------
7353263

Elapsed: 00:00:18.05
00:12:33 SQL> select /*+ FULL (t) */ count(*) from target_table t where owner = 'SYS';

COUNT(*)
----------
5130305

Elapsed: 00:00:07.20
00:12:40 SQL> select /*+ FULL (t) */ count(*) from target_table t where owner = 'SYS' and object_type in ('TABLE','VIEW');

COUNT(*)
----------
513482

Elapsed: 00:00:05.33
00:12:45 SQL> set timing off
00:12:45 SQL> select blocks, num_rows, sample_size from user_tables where table_name = 'TARGET_TABLE';

BLOCKS NUM_ROWS SAMPLE_SIZE
---------- ---------- -----------
102500 7353263 7353263

00:12:45 SQL>
00:12:45 SQL> pause Press ENTER to proceed
Press ENTER to proceed

00:12:56 SQL>
00:12:56 SQL> connect hemant/hemant
Connected.
00:12:56 SQL>
00:12:56 SQL> @active_transactions
00:12:56 SQL> set echo off

no rows selected

00:12:56 SQL>
00:12:56 SQL>
00:12:56 SQL> set timing on
00:12:56 SQL> update /*+ FULL (t) */ target_table t set owner='SYS_U', object_name = substr(object_name,1,15)||'_Updated'
00:12:56 2 where owner = 'SYS' and object_type in ('TABLE','VIEW') ;

513482 rows updated.

Elapsed: 00:00:38.20
00:13:35 SQL> set timing off
00:13:35 SQL>
00:13:35 SQL> @active_transactions
00:13:35 SQL> set echo off

SID SERIAL# SPID USERNAME PROGRAM XIDUSN USED_UBLK USED_UREC LAST_CALL_ET
---------- ---------- ------------ -------- --------------------------- ---------- ---------- ---------- ------------
147 13 5600 HEMANT sqlplus@linux64 (TNS V1-V3) 5 7338 514528 0

00:13:35 SQL>


This time, the UPDATE took only 38.20seconds (down from 264 seconds earlier !)

Monitoring V$SESSION_LONGOPS from another session, I saw :

00:13:19 SQL> set echo off

SID OPNAME
---------- ----------------------------------------------------------------
TARGET SOFAR TOTALWORK UNITS STARTTIM
---------------------------------------------------------------- ---------- ---------- -------------------------------- --------
TIME_REMAINING
--------------
MESSAGE
------------------------------------------------------------------------------------------------------------------------------------
USERNAME
--------
147 Table Scan
HEMANT.TARGET_TABLE 65266 102500 Blocks 00:12:56
13
Table Scan: HEMANT.TARGET_TABLE: 65266 out of 102500 Blocks done
HEMANT


00:13:19 SQL>

The FullTableScan was seemingly taken 36seconds (23seconds from 00:12:56 to 00:13:19 and another estimated 13seconds at that time).
We can infer that the effort to update the Table Blocks is what increased the FullTableScan for the UPDATE from the 5-20seconds range to 38seconds. That, still isn't as bad as 264seconds.

And I had only 2 indexes, not 4 or 6 or 8 indexes. If I were running a DELETE, I would be "updating" all the indexes on the table !

7 comments:

nayyares said...

nice post!

I enjoyed the reading. keep it up.

cheers

Unknown said...

Excellent.

That is I'm looking for desperately.

Anonymous said...

Simply awesome

Anonymous said...

The explanation of not using V$SESSION_LONGOPS was really good, however can you please suggest, how to check progress of statistics gathering on a table?

Hemant K Chitale said...

Anonymous,
If it is a Partitioned Table, V$SESSION_LONGOPS can show you how many partitions are "pending" gather stats. However, for column histograms, Oracle has to read the table again for each column that it is creating a histogram on. So there will be multiple passes -- all visible in V$SESSION_LONGOPS if they are long enough -- on the table.

Hemant

Hemant K Chitale said...

Question from C P :
"How did you get the "Statistics or Wait" information for the UPDATE work. What ver of oracle was this"

Hemant K Chitale said...

C P ,

I used a query that does a UNION of results from v$SESSTAT (joined to V$STATNAME) and V$SESSION_EVENT to report Waits and Statistics together.
This test was in 10.2