Search My Oracle Blog

Custom Search

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:

Sadik 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 :)

Aggregated by orafaq.com

Aggregated by orafaq.com
This blog is being aggregated by orafaq.com

Top 50 Oracle SQL Blogs 2016

Top 50 Oracle SQL Blogs 2016
Top 50 Oracle SQL Blogs 2016