看懂AWR

原始出處AWR分析

http://www.os2ora.com/how-to-analyze-awr-report-1/

http://www.os2ora.com/how-to-analyze-awr-report-2/

http://www.os2ora.com/how-to-analyze-awr-report-3/

http://www.os2ora.com/how-to-analyze-awr-report-4/

http://www.os2ora.com/how-to-analyze-awr-report-5/

Host CPU (CPUs: 4 Cores: 2 Sockets: 1)

Load Average Begin	Load Average End	%User	%System	%WIO	%Idle
		4.9	4.0		91.2

• 在OS來說CPU的使用率=Busy + Idle→所以在這裡Busy%=1-91.2=8.8%
• 搭著Operating System Statistics看
• %User = USER_TIME/(BUSY_TIME+IDLE_TIME)*100 
• 18457/(33590+345995)*100=4.86 
• %Sys  = SYS_TIME/(BUSY_TIME+IDLE_TIME)*100
• 15133/379585=3.98
• %Idle = IDLE_TIME/(BUSY_TIME+IDLE_TIME)*100
• 345995/379585=91.15

Operating System Statistics

• *TIME statistic values are diffed. All others display actual values. End Value is displayed if different
• ordered by statistic type (CPU Use, Virtual Memory, Hardware Config), Name

Statistic	Value	End Value
AVG_BUSY_TIME	8,372
AVG_IDLE_TIME	86,474
AVG_SYS_TIME	3,761
AVG_USER_TIME	4,590
BUSY_TIME	33,590
IDLE_TIME	345,995
SYS_TIME	15,133
USER_TIME	18,457
RSRC_MGR_CPU_WAIT_TIME	0
VM_IN_BYTES	66,340,137,790,754,816
VM_OUT_BYTES	-144,554,992,965,316,608
PHYSICAL_MEMORY_BYTES	8,470,183,936
NUM_CPUS	4
NUM_CPU_CORES	2
NUM_CPU_SOCKETS	1

• BUSY_TIME + IDLE_TIME = ELAPSED_TIME * CPU_COUNT
• 至于DB对CPU的利用情况，这就涉及到10g新引入的一个关于时间统计的视图了， v$sys_time_model，简单而言，Oracle采用了一个统一的时间模型对一些重要的时间指标进行了记录，具体而言，这些指标包括:

1) background elapsed time
    2) background cpu time
          3) RMAN cpu time (backup/restore)
1) DB time
    2) DB CPU
    2) connection management call elapsed time
    2) sequence load elapsed time
    2) sql execute elapsed time
    2) parse time elapsed
          3) hard parse elapsed time
                4) hard parse (sharing criteria) elapsed time
                    5) hard parse (bind mismatch) elapsed time
          3) failed parse elapsed time
                4) failed parse (out of shared memory) elapsed time
    2) PL/SQL execution elapsed time
    2) inbound PL/SQL rpc elapsed time
    2) PL/SQL compilation elapsed time
    2) Java execution elapsed time
    2) repeated bind elapsed time

紅色的兩個CPU時間才需要注意，並且在Time Model Statistics也可以看到。

Time Model Statistics

Total time in database user-calls (DB Time): 38.8s
Statistics including the word "background" measure background process time, and so do not contribute to the DB time statistic
Ordered by % or DB time desc, Statistic name


Statistic Name
Time (s)
% of DB Time
sql execute elapsed time
30.97
79.75
DB CPU
3.56
9.18
connection management call elapsed time
2.27
5.85
PL/SQL execution elapsed time
0.99
2.55
parse time elapsed
0.29
0.76
hard parse elapsed time
0.18
0.45
hard parse (sharing criteria) elapsed time
0.17
0.44
PL/SQL compilation elapsed time
0.00
0.01
repeated bind elapsed time
0.00
0.00
sequence load elapsed time
0.00
0.00
DB time
38.83

background elapsed time
32.43

background cpu time
1.33

Total DB CPU = DB CPU + background cpu time = 3.56+ 1.33 = 4.89 seconds


再除以 BUSY_TIME + IDLE_TIME=3795.85


% Total CPU = 4.89/3795.85 = 0.13%，可以跟Instance CPU對應。


Instance CPU


%Total CPU
%Busy CPU
%DB time waiting for CPU (Resource Manager)
0.1
1.5
0.0



在Load Profile部分，我們也可以看出DB對系统CPU的资源利用情况。


%Total CPU = DB CPU per Second/CPU Count =0/4 = 0 %(前台耗用)


比0.1%(前台加後台耗用)稍小，中間的差距即是後台所使用的CPU%




Load Profile


Per Second
Per Transaction
Per Exec
Per Call
DB Time(s):
0.0
0.2
0.00
0.01
DB CPU(s):
0.0
0.0
0.00
0.00



每秒最大DB CUP 的值即為其CPU數目=N s(N=CPU數)


Load Profile


Per Second
Per Transaction
Per Exec
Per Call
Redo size:
2,270.0
9,749.1

Logical reads:
45.3
194.7

Block changes:
9.7
41.8

Physical reads:
0.0
0.1

Physical writes:
0.8
3.3





5個IO都來自v$systat

Redo Size: ‘redo size’


Logical reads = ‘session logical reads’ or (‘db block gets’ + ‘consistent gets’)


Blocks Changes = ‘db block changes’


Physical reads = ‘physical reads’


Physical writes = ‘physical writes’

Mbps= (Physical reads + Physical writes) * Block_Size(KB)

(196,271.4+2.0)*8*1024/1024/1024 = 1533 MB/s


更精準的可以看Instance Activity Stats
physical IO disk bytes = physical read total bytes + physical write total bytes



Instance Activity Stats

Ordered by statistic name


Statistic
Total
per Second
per Trans
Batched IO (full) vector count
0
0.00
0.00
Batched IO block miss count
0
0.00
0.00
Batched IO double miss count
0
0.00
0.00
Batched IO same unit count
0
0.00
0.00
Batched IO single block count
0
0.00
0.00
Batched IO vector block count
0
0.00
0.00
Batched IO vector read count
0
0.00
0.00
Block Cleanout Optim referenced
5
0.01
0.02
CCursor + sql area evicted
1
0.00
0.00
CPU used by this session
331
0.35
1.48
CPU used when call started
219
0.23
0.98
CR blocks created
63
0.07
0.28
Cached Commit SCN referenced
0
0.00
0.00
Commit SCN cached
0
0.00
0.00
DB time
309,539
323.21
1,388.07
DBWR checkpoint buffers written
722
0.75
3.24
DBWR checkpoints
0
0.00
0.00
DBWR object drop buffers written
0
0.00
0.00
DBWR revisited being-written buffer
0
0.00
0.00
DBWR thread checkpoint buffers written
0
0.00
0.00
DBWR transaction table writes
25
0.03
0.11
DBWR undo block writes
133
0.14
0.60
HSC Compressed Segment Block Changes
0
0.00
0.00
HSC Heap Segment Block Changes
1,216
1.27
5.45
HSC IDL Compressed Blocks
0
0.00
0.00
HSC OLTP Compressed Blocks
0
0.00
0.00
HSC OLTP Non Compressible Blocks
0
0.00
0.00
HSC OLTP Space Saving
0
0.00
0.00
HSC OLTP positive compression
0
0.00
0.00
HSC OLTP recursive compression
0
0.00
0.00
Heap Segment Array Inserts
95
0.10
0.43
Heap Segment Array Updates
93
0.10
0.42
IMU CR rollbacks
44
0.05
0.20
IMU Flushes
324
0.34
1.45
IMU Redo allocation size
396,408
413.91
1,777.61
IMU commits
193
0.20
0.87
IMU contention
2
0.00
0.01
IMU ktichg flush
3
0.00
0.01
IMU pool not allocated
0
0.00
0.00
IMU recursive-transaction flush
2
0.00
0.01
IMU undo allocation size
1,143,136
1,193.61
5,126.17
IMU- failed to get a private strand
0
0.00
0.00
LOB table id lookup cache misses
0
0.00
0.00
Misses for writing mapping
0
0.00
0.00
Number of read IOs issued
0
0.00
0.00
RowCR - row contention
0
0.00
0.00
RowCR attempts
204
0.21
0.91
RowCR hits
208
0.22
0.93
SMON posted for undo segment shrink
0
0.00
0.00
SQL*Net roundtrips to/from client
2,222
2.32
9.96
TBS Extension: bytes extended
0
0.00
0.00
TBS Extension: files extended
0
0.00
0.00
TBS Extension: tasks created
0
0.00
0.00
TBS Extension: tasks executed
0
0.00
0.00
active txn count during cleanout
60
0.06
0.27
application wait time
2
0.00
0.01
auto extends on undo tablespace
0
0.00
0.00
background checkpoints completed
0
0.00
0.00
background checkpoints started
0
0.00
0.00
background timeouts
4,003
4.18
17.95
branch node splits
0
0.00
0.00
buffer is not pinned count
18,666
19.49
83.70
buffer is pinned count
13,714
14.32
61.50
bytes received via SQL*Net from client
621,974
649.43
2,789.12
bytes sent via SQL*Net to client
370,780
387.15
1,662.69
calls to get snapshot scn: kcmgss
10,815
11.29
48.50
calls to kcmgas
635
0.66
2.85
calls to kcmgcs
3,676
3.84
16.48
cell physical IO interconnect bytes
46,218,752
48,259.35
207,258.98
change write time
3
0.00
0.01
cleanout - number of ktugct calls
61
0.06
0.27
cleanouts and rollbacks - consistent read gets
0
0.00
0.00
cleanouts only - consistent read gets
2
0.00
0.01
cluster key scan block gets
2,668
2.79
11.96
cluster key scans
2,244
2.34
10.06
commit batch performed
0
0.00
0.00
commit batch requested
0
0.00
0.00
commit batch/immediate performed
0
0.00
0.00
commit batch/immediate requested
0
0.00
0.00
commit cleanout failures: block lost
3
0.00
0.01
commit cleanout failures: callback failure
8
0.01
0.04
commit cleanout failures: cannot pin
0
0.00
0.00
commit cleanouts
1,221
1.27
5.48
commit cleanouts successfully completed
1,210
1.26
5.43
commit immediate performed
0
0.00
0.00
commit immediate requested
0
0.00
0.00
commit txn count during cleanout
28
0.03
0.13
concurrency wait time
52
0.05
0.23
consistent changes
113
0.12
0.51
consistent gets
34,982
36.53
156.87
consistent gets - examination
11,921
12.45
53.46
consistent gets direct
0
0.00
0.00
consistent gets from cache
34,982
36.53
156.87
consistent gets from cache (fastpath)
18,453
19.27
82.75
cursor authentications
108
0.11
0.48
data blocks consistent reads - undo records applied
69
0.07
0.31
db block changes
9,315
9.73
41.77
db block gets
8,434
8.81
37.82
db block gets direct
10
0.01
0.04
db block gets from cache
8,424
8.80
37.78
db block gets from cache (fastpath)
2,783
2.91
12.48
deferred (CURRENT) block cleanout applications
712
0.74
3.19
enqueue conversions
196
0.20
0.88
enqueue releases
11,487
11.99
51.51
enqueue requests
11,484
11.99
51.50
enqueue timeouts
0
0.00
0.00
enqueue waits
1
0.00
0.00
execute count
9,297
9.71
41.69
file io service time
0
0.00
0.00
file io wait time
5,072,015
5,295.95
22,744.46
free buffer requested
314
0.33
1.41
heap block compress
8
0.01
0.04
immediate (CR) block cleanout applications
2
0.00
0.01
immediate (CURRENT) block cleanout applications
326
0.34
1.46
index crx upgrade (positioned)
1,583
1.65
7.10
index fast full scans (full)
424
0.44
1.90
index fetch by key
9,569
9.99
42.91
index scans kdiixs1
6,819
7.12
30.58
leaf node 90-10 splits
13
0.01
0.06
leaf node splits
28
0.03
0.13
lob reads
12
0.01
0.05
lob writes
21
0.02
0.09
lob writes unaligned
21
0.02
0.09
logons cumulative
98
0.10
0.44
max cf enq hold time
452
0.47
2.03
messages received
765
0.80
3.43
messages sent
765
0.80
3.43
min active SCN optimization applied on CR
14
0.01
0.06
no work - consistent read gets
15,377
16.06
68.96
non-idle wait count
5,812
6.07
26.06
non-idle wait time
7,463
7.79
33.47
opened cursors cumulative
8,528
8.90
38.24
parse count (describe)
2
0.00
0.01
parse count (failures)
12
0.01
0.05
parse count (hard)
72
0.08
0.32
parse count (total)
4,138
4.32
18.56
parse time cpu
21
0.02
0.09
parse time elapsed
23
0.02
0.10
physical read IO requests
23
0.02
0.10
physical read bytes
188,416
196.73
844.91
physical read total IO requests
1,658
1.73
7.43
physical read total bytes
27,009,024
28,201.50
121,116.70
physical read total multi block requests
0
0.00
0.00
physical reads
23
0.02
0.10
physical reads cache
23
0.02
0.10
physical reads cache prefetch
0
0.00
0.00
physical reads direct
0
0.00
0.00
physical reads direct (lob)
0
0.00
0.00
physical reads direct temporary tablespace
0
0.00
0.00
physical reads prefetch warmup
0
0.00
0.00
physical write IO requests
482
0.50
2.16
physical write bytes
5,996,544
6,261.30
26,890.33
physical write total IO requests
1,404
1.47
6.30
physical write total bytes
19,209,728
20,057.85
86,142.28
physical write total multi block requests
8
0.01
0.04
physical writes
732
0.76
3.28
physical writes direct
10
0.01
0.04
physical writes direct (lob)
7
0.01
0.03
physical writes direct temporary tablespace
3
0.00
0.01
physical writes from cache
722
0.75
3.24
physical writes non checkpoint
100
0.10
0.45
process last non-idle time
69,059
72.11
309.68
recursive calls
41,045
42.86
184.06
recursive cpu usage
243
0.25
1.09
redo blocks checksummed by FG (exclusive)
2,379
2.48
10.67
redo blocks written
4,447
4.64
19.94
redo buffer allocation retries
0
0.00
0.00
redo entries
3,668
3.83
16.45
redo log space requests
0
0.00
0.00
redo log space wait time
0
0.00
0.00
redo ordering marks
120
0.13
0.54
redo size
2,174,056
2,270.04
9,749.13
redo size for direct writes
364
0.38
1.63
redo subscn max counts
280
0.29
1.26
redo synch time
1,250
1.31
5.61
redo synch writes
160
0.17
0.72
redo wastage
65,976
68.89
295.86
redo write time
980
1.02
4.39
redo writes
255
0.27
1.14
rollback changes - undo records applied
5
0.01
0.02
rollbacks only - consistent read gets
63
0.07
0.28
root node splits
0
0.00
0.00
rows fetched via callback
2,480
2.59
11.12
scheduler wait time
0
0.00
0.00
session connect time
0
0.00
0.00
session cursor cache hits
6,488
6.77
29.09
session logical reads
43,416
45.33
194.69
shared hash latch upgrades - no wait
4,069
4.25
18.25
shared hash latch upgrades - wait
0
0.00
0.00
sorts (memory)
3,356
3.50
15.05
sorts (rows)
16,025
16.73
71.86
sql area evicted
1
0.00
0.00
sql area purged
13
0.01
0.06
switch current to new buffer
74
0.08
0.33
table fetch by rowid
8,726
9.11
39.13
table fetch continued row
12
0.01
0.05
table scan blocks gotten
3,507
3.66
15.73
table scan rows gotten
153,585
160.37
688.72
table scans (short tables)
1,079
1.13
4.84
temp space allocated (bytes)
0
0.00
0.00
total cf enq hold time
875
0.91
3.92
total number of cf enq holders
25
0.03
0.11
total number of times SMON posted
0
0.00
0.00
transaction rollbacks
0
0.00
0.00
undo change vector size
769,500
803.47
3,450.67
user I/O wait time
549
0.57
2.46
user calls
2,911
3.04
13.05
user commits
222
0.23
1.00
user rollbacks
1
0.00
0.00
workarea executions - onepass
0
0.00
0.00
workarea executions - optimal
2,196
2.29
9.85
write clones created in background
0
0.00
0.00
write clones created in foreground
0
0.00
0.00 




physical IO disk bytes = physical read total bytes + physical write total bytes

physical write total bytes大致是physical write bytes的两倍。因為Oracle做了ASM，normal redundancy，一份數據寫了兩遍。





Load Profile



Per Second
Per Transaction
Per Exec
Per Call
User calls:
3.0
13.1

Parses:
4.3
18.6

Hard parses:
0.1
0.3

W/A MB processed:
0.1
0.2

Logons:
0.1
0.4

Executes:
9.7
41.7

Rollbacks:
0.0
0.0

Transactions:
0.2






除了W/A MB processed来自v$pgastat（單位是Byte，不是MB），其它數據都是來自v$sysstat。


Blocks Changes: ‘db block changes’



User calls:  ‘user calls’



Parses: ‘parse count (total)’



Hard parses: ‘parse count (hard)’



Logons: ‘logons cumulative’



Executes:  ‘execute count’



Rollbacks: ‘user rollbacks’



Tranasactions: ‘user rollbacks’ + ‘user commits’



W/A MB processed: ‘bytes processed’

一般而言，Hard parses < Parses < Executes < User Calls。









Foreground Wait Class

s - second, ms - millisecond - 1000th of a second
ordered by wait time desc, waits desc
%Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Captured Time accounts for 102.1% of Total DB time 38.83 (s)
Total FG Wait Time: 36.10 (s) DB CPU time: 3.56 (s)


Wait Class
Waits
%Time -outs
Total Wait Time (s)
Avg wait (ms)
%DB time
System I/O
568
0
21
36
52.90
Commit
150
0
12
78
30.06
DB CPU
4
9.18
User I/O
120
0
4
29
9.08
Other
147
95
0
2
0.87
Application
62
0
0
0
0.04
Network
2,243
0
0
0
0.01
Concurrency
2
0
0
0
0.00


如果DB CPU + FG Wait Time < DB Time 表示CPU很忙(DB Time包含DB等待CPU時間 )
如果DB CPU + FG Wait Time > DB Time 表示CPU不忙



Top 5 Timed Foreground Events





Event
Waits
Time(s)
Avg wait (ms)
% DB time
Wait Class
control file sequential read
568
21
36
52.90
System I/O
log file sync
150
12
78
30.06
Commit
DB CPU
4
9.18

db file sequential read
13
2
151
5.07
User I/O
Disk file operations I/O
104
1
9
2.47
User I/O