Randolf Geist has written a test case to show what happens when a performance tuning exercise isn't continued because the Developer / DBA / Consultant only looks at the first set of rows returned by a query.
A front-end tool may present only the first N set of rows but if the query is part of an application code (eg copying/transforming a large set of rows), the application would actually be waiting for ALL the rows to be processed.
I am an Oracle Database Specialist in Singapore.
Please note that this site uses cookies.
28 January, 2009
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.
Thus, we can see that a FullTableScan takes 5.7seconds to 19.5seconds.
The table has 7.3million rows in 102,500 blocks and the two indexes on the table 86,750 blocks.
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 :
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.
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 !
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 :
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 :
This time, the UPDATE took only 38.20seconds (down from 264 seconds earlier !)
Monitoring V$SESSION_LONGOPS from another session, I saw :
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 !
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 !
Subscribe to:
Posts (Atom)