09 July, 2011

Reading an AWR - 1

Given this extract from an AWR :
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.93 In-memory Sort %: 100.00
Library Hit %: 94.76 Soft Parse %: 96.21
Execute to Parse %: 30.63 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 79.13 % Non-Parse CPU: 93.52

Should I be worried about the Parse ratios ?

I then look at the "SQL ordered by Parse calls" section :
-> Total Parse Calls:          24,049
-> Captured SQL account for 71.1% of Total

% Total
Parse Calls Executions Parses SQL Id
------------ ------------ --------- -------------
5,208 5,208 21.66 bsa0wjtftg3uw
select file# from file$ where ts#=:1

3,868 3,868 16.08 cm5vu20fhtnq1
select /*+ connect_by_filtering */ privilege#,level from sysauth$ connect by gra
ntee#=prior privilege# and privilege#>0 start with grantee#=:1 and privilege#>0

861 861 3.58 86708bvah4akq
select name from undo$ where file#=:1 and block#=:2 and ts#=:3 and status$
!= 1

660 660 2.74 0kkhhb2w93cx0
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=:9,e
xtpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),groups=decod
e(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=DECODE(:17,0,NULL,:
17),scanhint=:18, bitmapranges=:19 where ts#=:1 and file#=:2 and block#=:3

625 440 2.60 0v3dvmc22qnam
insert into sys.col_usage$ (obj#, intcol#, equality_preds, equijoin_preds, noneq
uijoin_preds, range_preds, like_preds, null_preds, timestamp) values ( :objn,
:coln, decode(bitand(:flag,1),0,0,1), decode(bitand(:flag,2),0,0,1), decod
e(bitand(:flag,4),0,0,1), decode(bitand(:flag,8),0,0,1), decode(bitand(:flag

Should I be worried about the parse calls on SYSAUTH$ ? What about the lookups on FILE$ that are parsed so many times ?



What do you guys say ?


I'll see what responses I get.
.
.
.
UPDATE : 16-Jul-11 :

There were 3 responses.
The first was that the "Top 5 timed events" must be checked. The third response was that the elapsed time and database time must be checked.

Here they are, with Load Profile included as well :

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 1230 08-Jul-11 21:53:22 26 1.3
End Snap: 1234 08-Jul-11 23:00:45 32 1.1
Elapsed: 67.38 (mins)
DB Time: 3.45 (mins)


Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU 132 63.7
log buffer space 9 3 349 1.5 Configurat
enq: CR - block range reuse ck 44 3 69 1.5 Other
log file switch (checkpoint in 2 2 1201 1.2 Configurat
log file switch completion 21 1 47 .5 Configurat

Host CPU (CPUs: 1 Cores: 1 Sockets: 1)
~~~~~~~~ Load Average
Begin End %User %System %WIO %Idle
--------- --------- --------- --------- --------- ---------
0.33 1.32 1.3 17.7 1.5 78.4

Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~ --------------- --------------- ---------- ----------
DB Time(s): 0.1 0.4 0.01 0.06
DB CPU(s): 0.0 0.2 0.00 0.04
Redo size: 341,639.6 2,539,120.1
Logical reads: 1,435.2 10,666.3
Block changes: 1,612.4 11,983.4
Physical reads: 0.9 7.0
Physical writes: 25.6 190.3
User calls: 0.9 6.5
Parses: 6.0 44.2
Hard parses: 0.2 1.7
W/A MB processed: 0.0 0.3
Logons: 0.1 0.5
Executes: 8.6 63.7
Rollbacks: 0.0 0.0
Transactions: 0.1


You can see that the there was very little activity in the database. Less than 4 minutes of database time in 67minutes of elapsed time. There was less than 1 user call per second and 6 parses per second.
So, there was *some* activity occurring (6 parses per second on machine with only 1 CPU/Core). But it didn't consume significant resources. 6 parses per second over 67minutes does account for the more than 24thousand parses.

Why the high activity on FILE$ ? There was a job that was periodically dropping a table, creating a new table, populating it with 400,000 rows, deleting them, doing a rollback and then a count. The job would, in a loop, after a noticeable "sleep" period, run another pass of drop-create-populate-delete-rollback-count.


In this case, the data dictionary queries/updates (FILE$, SYSAUTH$, UNDO$, SEG$, COL_USAGE$) were all because of the pattern of operations. (FILE$ to identify the file for the extent allocation, SEG$ to update the table segment information with each new extent added, SYSAUTH$ for the privileges, UNDO$ for the undo segment and COL_USAGE$ to update column usage on queries.


With respect to the second response about the data dictionary stats and object stats, these were not an issue here.
.
.
.

5 comments:

Anonymous said...

Check "top 5 timed events" out, leave the parsing stuff be if no relevant un-healthy events spotted.

pvh said...

The recursive SQL's may not be a problem but will show a problem. I may be wrong but you need to check:

1. Whether the dictionary stats is collected as this may affect the read on dictionary tables.
2. The object statistics are gathered properly.
3. We can check whether the cursor related parameter are given proper value as insufficient cursor may cause more parsing.

This is just a try, there may be other reasons too.

Franck Pachot said...

Hi,

I usually think that all the AWR statistics have no meaning without checking elapsed time and db time first. Maybe there is no user activity here.

Then I always go first to the Timed sections (Top timed events and time model).
Here there is no time at all, so the number of executions or parse are a bit meaningless.

Regards,
Franck.

Hemant K Chitale said...

Anonymous, pvh, Franck,

Thank you. I will be returning to this thread in a few days and will post my responses.

Hemant

Hemant K Chitale said...

See my updates to this post on 16-Jul-11