19 October, 2008

Using STATISTICS_LEVEL='ALL' and 10046, level 8

Although I have, on occassion, used event 10046, level 8 to trace database operations in production, I am taken aback when a vendor wants to use both STATISTICS_LEVEL='ALL' and 10046, level 8 together for a long-running job ostensibly to collect more detailed information.

I can understand STATISTICS_LEVEL='ALL' providing better information in V$ views. But does it provide "better" information when the reviewing only AWR reports and tkprof outputs of the trace files (gathered with event 10046, level 8) ? I am not convinced of the need for this in production.

I have decided to run a simple test with an UPDATE statement on a 10million row table.
One run will be with STATISTICS_LEVEL='TYPICAL' and tracing with event 10046 set at level 1.
The second run will be with STATISTICS_LEVEL='ALL' and tracing with event 10046 set at level 8.

FIRST RUN, with STATISTICS_LEVEL='TYPICAL' and Level 1 Tracing :

update my_transactions mt
set mt.converted_amount =
(select st.transaction_amount*sf.conv_rate
from my_transactions st, my_fx_rates sf
where
st.transaction_c_c=sf.currency_code
and
trunc(st.transaction_date)=sf.conv_rate_date
and
st.transaction_id=mt.transaction_id),
mt.updated_at=sysdate

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.03 0.03 0 0 0 0
Execute 1 1074.94 1184.89 753724 62611107 10743805 10000000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1074.98 1184.93 753724 62611107 10743805 10000000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE MY_TRANSACTIONS (cr=60928473 pr=742011 pw=0 time=1157314862 us)
20338218 TABLE ACCESS FULL MY_TRANSACTIONS (cr=10979090 pr=732914 pw=0 time=183093956 us)
10278974 NESTED LOOPS (cr=51631852 pr=20663 pw=0 time=715168290 us)
10338218 TABLE ACCESS BY INDEX ROWID MY_TRANSACTIONS (cr=31014657 pr=20469 pw=0 time=305940011 us)
10338218 INDEX UNIQUE SCAN MY_TRANSACTIONS_PK (cr=20676439 pr=20469 pw=0 time=163468271 us)(object id 58495)
10278974 TABLE ACCESS BY INDEX ROWID MY_FX_RATES (cr=20617195 pr=194 pw=0 time=256486318 us)
10278974 INDEX UNIQUE SCAN MY_FX_RATES_PK (cr=10338221 pr=119 pw=0 time=124931227 us)(object id 58464)

********************************************************************************


SECOND RUN, with STATISTICS_LEVEL='ALL' and Level 8 Tracing :


update my_transactions mt
set mt.converted_amount =
(select st.transaction_amount*sf.conv_rate
from my_transactions st, my_fx_rates sf
where
st.transaction_c_c=sf.currency_code
and
trunc(st.transaction_date)=sf.conv_rate_date
and
st.transaction_id=mt.transaction_id),
mt.updated_at=sysdate

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.03 0 0 0 0
Execute 1 1165.17 1261.06 753135 62114208 10724083 10000000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1165.20 1261.10 753135 62114208 10724083 10000000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE MY_TRANSACTIONS (cr=60933001 pr=744851 pw=0 time=1240297420 us)
20239080 TABLE ACCESS FULL MY_TRANSACTIONS (cr=10975891 pr=732493 pw=0 time=222679174 us)
10179836 NESTED LOOPS (cr=51136162 pr=20449 pw=0 time=716122504 us)
10239080 TABLE ACCESS BY INDEX ROWID MY_TRANSACTIONS (cr=30717243 pr=20259 pw=0 time=308789524 us)
10239080 INDEX UNIQUE SCAN MY_TRANSACTIONS_PK (cr=20478163 pr=20259 pw=0 time=167672057 us)(object id 58495)
10179836 TABLE ACCESS BY INDEX ROWID MY_FX_RATES (cr=20418919 pr=190 pw=0 time=255736454 us)
10179836 INDEX UNIQUE SCAN MY_FX_RATES_PK (cr=10239083 pr=115 pw=0 time=125362994 us)(object id 58464)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 107600 0.07 56.46
db file scattered read 40467 0.26 65.70
log file switch completion 171 0.17 3.42
log buffer space 3 0.04 0.12
log file switch (checkpoint incomplete) 5 0.97 1.06
latch: cache buffers lru chain 152 0.00 0.01
rdbms ipc reply 221 0.03 0.11
latch: object queue header operation 11 0.10 0.10
latch: checkpoint queue latch 1 0.00 0.00
buffer busy waits 2 0.00 0.01
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.03 0.03
********************************************************************************


The execution time was only slightly higher at 1,261seconds versus 1,185seconds. However, I also note that, other than the listing of Wait Events and durations of each event, I do not notice information in the tkprof output of the trace file when I review it post-facto.
STATISTICS_LEVEL='ALL' does provide additional information in V$ views but that is unlikely to be visible in a tkprof of an SQL Trace file (whether level 1 or 8) that is generated and reviewed later.

12 October, 2008

Delayed Block Cleanout -- through Instance Restart

Continuing my previous post on Delayed Block Cleanout, in this post, I show how a database shutdown doesn't guarantee that all the modified blocks in a table are "cleaned out" before the shutdown.

I run a large update and commit it. Next, I shutdown the database. The first query against the table after the subsequent restart still has to examine modified blocks, confirm if the updates to rows in the block have been committed and then execute a cleanout of these modified blocks. Thus, we see "consistent gets - examination" and "cleanout%" statistics being incremented for the first query after the restart :


SQL> select blocks,num_rows from user_tables where table_name = upper('test_d_b_c');

BLOCKS NUM_ROWS
---------- ----------
47069 3242752

SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 0
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 0
consistent changes 0
consistent gets 47,513
consistent gets - examination 207
db block changes 0
db block gets 0
redo entries 0
redo size 0
undo change vector size 0
SQL>
SQL> REM Run an update on 60% (not all) of the rows
SQL> UPDATE TEST_D_B_C SET COL_1 = 'HKC_'||SUBSTR(COL_1,4,11) WHERE MOD(COL_4,10) > 3 ;

1945344 rows updated.

SQL> COMMIT;

Commit complete.

SQL>
SQL> REM We will now shutdown and restart the database
SQL> connect / as sysdba
Connected.
SQL> shutdown immediate
Database closed.
Database dismounted.
ORACLE instance shut down.
SQL> startup
ORACLE instance started.

Total System Global Area 734003200 bytes
Fixed Size 2023688 bytes
Variable Size 264244984 bytes
Database Buffers 461373440 bytes
Redo Buffers 6361088 bytes
Database mounted.
Database opened.
SQL>
SQL> connect hemant/hemant
Connected.
SQL> REM Now let's query the table
SQL> REM Will the first execution suffer delayed block cleanout ?
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 46,969
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 46,969
consistent changes 0
consistent gets 94,910
consistent gets - examination 47,367
db block changes 46,973
db block gets 3
redo entries 46,971
redo size 3,383,012
undo change vector size 204
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 46,969
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 46,969
consistent changes 0
consistent gets 141,993
consistent gets - examination 47,367
db block changes 46,973
db block gets 3
redo entries 46,971
redo size 3,383,012
undo change vector size 204


It is the first full table scan query that shows "consistent gets - examination" and "cleanout%" statistics. It did 46,969 examinations and cleanouts and generated 3.383MB of redo (for the correspondng 46,971 redo entries).

04 October, 2008

Delayed Block Cleanout

A query that reads datablocks that have been updated by a large DML (INSERT/UPDATE/DELETE) may well incur "delayed block cleanout". The commit operation of the DML does not involve clearing the ITL entries in each modified datablock but only marking the transaction in the undo slot entry as "COMMITTED" (plus, possibly, a few blocks being updated). Therefore, the next query (whether from the same database session OR from another database session) to read the datablock has to verify the ITL entries against the transaction in the undo segment and then "clean out" the ITL entry and the row marker in each datablock. This process of updating the datablock also generates redo.
The presence of the "Penalty" of delayed block cleanout is visible in the "cleanout %" statistics and also in the "consistent gets - examination" count [which is a subset of the "consistent gets" count].

This has implications in that large batch jobs that update very many datablocks and are able to exeute a COMMIT quickly actually cause subsequent jobs or queries against the same table to suffer this overhead.

You may not see "delayed block cleanout" when only a small set of datablocks are updated by a transaction.


This set of SQL commands and outputs below show how the *first* query against the table undergoing DML suffers this Penalty and the "cleanout %" and "consistent gets - examination" and "redo size" statistics are incremented (ie incurred) for this query but not the next query on the same datablocks.

I use with a table with 3.24million rows and run UPDATE, DELETE and INSERT operations against the table and identify the changes to these statistics which indicate delayed block cleanout.





SQL> select blocks,num_rows from user_tables where table_name = upper('test_d_b_c');

BLOCKS NUM_ROWS
---------- ----------
47197 3242752

SQL> REM Get the number of consistent gets -- the query has been run once ahead to parse it
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 0
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 0
consistent changes 0
consistent gets 48,174
consistent gets - examination 498
db block changes 4
db block gets 3
redo entries 2
redo size 672
undo change vector size 204
SQL>
SQL> REM REM ########## Test for an UPDATE ################ REM REM ####################
SQL> REM Run an update on 60% (not all) of the rows
SQL> UPDATE TEST_D_B_C SET COL_1 = 'HKC_'||SUBSTR(COL_1,1,15) WHERE MOD(COL_4,10) > 3 ;

1945344 rows updated.

SQL> COMMIT;

Commit complete.

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 0
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 0
consistent changes 0
consistent gets 95,395
consistent gets - examination 503
db block changes 1,471,008
db block gets 732,521
redo entries 726,323
redo size 340,420,260
undo change vector size 141,809,380
SQL>
SQL>
SQL> REM Now let's query the table
SQL> REM The first execution will suffer delayed block cleanout
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 46,969
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 46,969
consistent changes 0
consistent gets 189,575
consistent gets - examination 47,472
db block changes 1,517,977
db block gets 732,521
redo entries 773,293
redo size 343,803,772
undo change vector size 141,809,380
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 46,969
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 46,969
consistent changes 0
consistent gets 236,786
consistent gets - examination 47,472
db block changes 1,517,977
db block gets 732,521
redo entries 773,293
redo size 343,803,772
undo change vector size 141,809,380
SQL>
SQL>
SQL> REM REM ########## Test for a DELETE ################ REM REM ####################
SQL> REM Test for a DELETE
SQL> DELETE TEST_D_B_C WHERE MOD(COL_4,5) > 3;

648640 rows deleted.

SQL> COMMIT;

Commit complete.

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 46,969
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 46,969
consistent changes 0
consistent gets 284,451
consistent gets - examination 47,486
db block changes 2,870,813
db block gets 1,465,003
redo entries 1,458,221
redo size 586,670,260
undo change vector size 292,754,836
SQL>
SQL> REM Now let's query the table
SQL> REM The first execution will suffer delayed block cleanout
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
2594112

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 56,180
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 56,180
consistent changes 0
consistent gets 340,873
consistent gets - examination 56,697
db block changes 2,880,024
db block gets 1,465,003
redo entries 1,467,432
redo size 587,334,024
undo change vector size 292,754,836
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
2594112

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 56,180
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 56,180
consistent changes 0
consistent gets 388,084
consistent gets - examination 56,697
db block changes 2,880,024
db block gets 1,465,003
redo entries 1,467,432
redo size 587,334,024
undo change vector size 292,754,836
SQL>
SQL>
SQL> REM REM ########## Test for a INSERT ################ REM REM ####################
SQL> REM Test for an INSERT
SQL> INSERT INTO TEST_D_B_C SELECT * FROM TEST_D_B_C_BAK WHERE MOD(COL_4,5) > 3;

648640 rows created.

SQL> COMMIT;

Commit complete.

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 65,255
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 56,180
consistent changes 0
consistent gets 453,419
consistent gets - examination 65,810
db block changes 2,936,433
db block gets 1,532,712
redo entries 1,506,633
redo size 659,399,228
undo change vector size 295,378,592
SQL>
SQL> REM Now let's query the table
SQL> REM The first execution will suffer delayed block cleanout
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 72,839
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 63,764
consistent changes 0
consistent gets 508,214
consistent gets - examination 73,394
db block changes 2,944,017
db block gets 1,532,712
redo entries 1,514,217
redo size 659,945,320
undo change vector size 295,378,592
SQL>
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

COUNT(*)
----------
3242752

SQL> @Report_select_Statistics
SQL> set echo off

Statistic Value
---------------------------------------------------------- ----------------
cleanout - number of ktugct calls 72,839
cleanouts and rollbacks - consistent read gets 0
cleanouts only - consistent read gets 63,764
consistent changes 0
consistent gets 555,425
consistent gets - examination 73,394
db block changes 2,944,017
db block gets 1,532,712
redo entries 1,514,217
redo size 659,945,320
undo change vector size 295,378,592
SQL>


As you can see "cleanout - number of ktugct calls" and "cleanouts only - consistent read gets" are incremented as with "consistent gets - examination". [Remember that "consistent gets - examination" count is *included* in "consistent gets" count]. Also, "redo entries" and "redo size" are incremented. These occur for the first query against the modified datablocks.
NOTE : This table [TEST_D_B_C] does NOT have any indexes so "consistent gets - examination" does NOT reflect reads on index blocks [root blocks or otherwise]. {google might show a few references indicating the "consistent gets - examination" occurs for index blocks but that isn't the only case for this statistic}.


The above test was on 10.2.0.1 I have had similar results on 10.2.0.2

However, on 10.2.0.4 I have had a very surprisingly large number of "consistent gets - examination" {exceeding 1.9million} for the UPDATE itself [testing with both ASSM and MSSM], which I cannot explain yet. The "consistent gets - examination" count for the "delayed block cleanout" effect on the first query is still consistent. However, I haven't published the 10.2.0.4 numbers because of the 1.9million "consistent gets - examination" in the UPDATE. That is something I have to investigate.