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.

1 comment:

Anonymous said...

Hi hemant

Nice Blog, I found you searching google for oracle related blogs. I also run an Oracle Forum, requesting you to check out and give me some feedback.

Btw I am an Oracle Apps Manufacturing consultant, not much of a DBA though :)