2013年3月20日 星期三

看懂AWR


原始出處AWR分析


Host CPU (CPUs: 4 Cores: 2 Sockets: 1)
Load Average BeginLoad Average End%User%System%WIO%Idle
4.94.091.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
StatisticValueEnd Value
AVG_BUSY_TIME8,372
AVG_IDLE_TIME86,474
AVG_SYS_TIME3,761
AVG_USER_TIME4,590
BUSY_TIME33,590
IDLE_TIME345,995
SYS_TIME15,133
USER_TIME18,457
RSRC_MGR_CPU_WAIT_TIME0
VM_IN_BYTES66,340,137,790,754,816
VM_OUT_BYTES-144,554,992,965,316,608
PHYSICAL_MEMORY_BYTES8,470,183,936
NUM_CPUS4
NUM_CPU_CORES2
NUM_CPU_SOCKETS1
  • 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 NameTime (s)% of DB Time
sql execute elapsed time30.9779.75
DB CPU3.569.18
connection management call elapsed time2.275.85
PL/SQL execution elapsed time0.992.55
parse time elapsed0.290.76
hard parse elapsed time0.180.45
hard parse (sharing criteria) elapsed time0.170.44
PL/SQL compilation elapsed time0.000.01
repeated bind elapsed time0.000.00
sequence load elapsed time0.000.00
DB time38.83
background elapsed time32.43
background cpu time1.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.11.50.0
  • 在Load Profile部分,我們也可以看出DB對系统CPU的资源利用情况。
  • %Total CPU = DB CPU per Second/CPU Count =0/4 = 0 %(前台耗用)
  • 比0.1%(前台加後台耗用)稍小,中間的差距即是後台所使用的CPU%
Load Profile
Per SecondPer TransactionPer ExecPer Call
DB Time(s):0.00.20.000.01
DB CPU(s):0.00.00.000.00
  • 每秒最大DB CUP 的值即為其CPU數目=N s(N=CPU數)
Load Profile
Per SecondPer TransactionPer ExecPer Call
Redo size:2,270.09,749.1
Logical reads:45.3194.7
Block changes:9.741.8
Physical reads:0.00.1
Physical writes:0.83.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
StatisticTotalper Secondper Trans
Batched IO (full) vector count00.000.00
Batched IO block miss count00.000.00
Batched IO double miss count00.000.00
Batched IO same unit count00.000.00
Batched IO single block count00.000.00
Batched IO vector block count00.000.00
Batched IO vector read count00.000.00
Block Cleanout Optim referenced50.010.02
CCursor + sql area evicted10.000.00
CPU used by this session3310.351.48
CPU used when call started2190.230.98
CR blocks created630.070.28
Cached Commit SCN referenced00.000.00
Commit SCN cached00.000.00
DB time309,539323.211,388.07
DBWR checkpoint buffers written7220.753.24
DBWR checkpoints00.000.00
DBWR object drop buffers written00.000.00
DBWR revisited being-written buffer00.000.00
DBWR thread checkpoint buffers written00.000.00
DBWR transaction table writes250.030.11
DBWR undo block writes1330.140.60
HSC Compressed Segment Block Changes00.000.00
HSC Heap Segment Block Changes1,2161.275.45
HSC IDL Compressed Blocks00.000.00
HSC OLTP Compressed Blocks00.000.00
HSC OLTP Non Compressible Blocks00.000.00
HSC OLTP Space Saving00.000.00
HSC OLTP positive compression00.000.00
HSC OLTP recursive compression00.000.00
Heap Segment Array Inserts950.100.43
Heap Segment Array Updates930.100.42
IMU CR rollbacks440.050.20
IMU Flushes3240.341.45
IMU Redo allocation size396,408413.911,777.61
IMU commits1930.200.87
IMU contention20.000.01
IMU ktichg flush30.000.01
IMU pool not allocated00.000.00
IMU recursive-transaction flush20.000.01
IMU undo allocation size1,143,1361,193.615,126.17
IMU- failed to get a private strand00.000.00
LOB table id lookup cache misses00.000.00
Misses for writing mapping00.000.00
Number of read IOs issued00.000.00
RowCR - row contention00.000.00
RowCR attempts2040.210.91
RowCR hits2080.220.93
SMON posted for undo segment shrink00.000.00
SQL*Net roundtrips to/from client2,2222.329.96
TBS Extension: bytes extended00.000.00
TBS Extension: files extended00.000.00
TBS Extension: tasks created00.000.00
TBS Extension: tasks executed00.000.00
active txn count during cleanout600.060.27
application wait time20.000.01
auto extends on undo tablespace00.000.00
background checkpoints completed00.000.00
background checkpoints started00.000.00
background timeouts4,0034.1817.95
branch node splits00.000.00
buffer is not pinned count18,66619.4983.70
buffer is pinned count13,71414.3261.50
bytes received via SQL*Net from client621,974649.432,789.12
bytes sent via SQL*Net to client370,780387.151,662.69
calls to get snapshot scn: kcmgss10,81511.2948.50
calls to kcmgas6350.662.85
calls to kcmgcs3,6763.8416.48
cell physical IO interconnect bytes46,218,75248,259.35207,258.98
change write time30.000.01
cleanout - number of ktugct calls610.060.27
cleanouts and rollbacks - consistent read gets00.000.00
cleanouts only - consistent read gets20.000.01
cluster key scan block gets2,6682.7911.96
cluster key scans2,2442.3410.06
commit batch performed00.000.00
commit batch requested00.000.00
commit batch/immediate performed00.000.00
commit batch/immediate requested00.000.00
commit cleanout failures: block lost30.000.01
commit cleanout failures: callback failure80.010.04
commit cleanout failures: cannot pin00.000.00
commit cleanouts1,2211.275.48
commit cleanouts successfully completed1,2101.265.43
commit immediate performed00.000.00
commit immediate requested00.000.00
commit txn count during cleanout280.030.13
concurrency wait time520.050.23
consistent changes1130.120.51
consistent gets34,98236.53156.87
consistent gets - examination11,92112.4553.46
consistent gets direct00.000.00
consistent gets from cache34,98236.53156.87
consistent gets from cache (fastpath)18,45319.2782.75
cursor authentications1080.110.48
data blocks consistent reads - undo records applied690.070.31
db block changes9,3159.7341.77
db block gets8,4348.8137.82
db block gets direct100.010.04
db block gets from cache8,4248.8037.78
db block gets from cache (fastpath)2,7832.9112.48
deferred (CURRENT) block cleanout applications7120.743.19
enqueue conversions1960.200.88
enqueue releases11,48711.9951.51
enqueue requests11,48411.9951.50
enqueue timeouts00.000.00
enqueue waits10.000.00
execute count9,2979.7141.69
file io service time00.000.00
file io wait time5,072,0155,295.9522,744.46
free buffer requested3140.331.41
heap block compress80.010.04
immediate (CR) block cleanout applications20.000.01
immediate (CURRENT) block cleanout applications3260.341.46
index crx upgrade (positioned)1,5831.657.10
index fast full scans (full)4240.441.90
index fetch by key9,5699.9942.91
index scans kdiixs16,8197.1230.58
leaf node 90-10 splits130.010.06
leaf node splits280.030.13
lob reads120.010.05
lob writes210.020.09
lob writes unaligned210.020.09
logons cumulative980.100.44
max cf enq hold time4520.472.03
messages received7650.803.43
messages sent7650.803.43
min active SCN optimization applied on CR140.010.06
no work - consistent read gets15,37716.0668.96
non-idle wait count5,8126.0726.06
non-idle wait time7,4637.7933.47
opened cursors cumulative8,5288.9038.24
parse count (describe)20.000.01
parse count (failures)120.010.05
parse count (hard)720.080.32
parse count (total)4,1384.3218.56
parse time cpu210.020.09
parse time elapsed230.020.10
physical read IO requests230.020.10
physical read bytes188,416196.73844.91
physical read total IO requests1,6581.737.43
physical read total bytes27,009,02428,201.50121,116.70
physical read total multi block requests00.000.00
physical reads230.020.10
physical reads cache230.020.10
physical reads cache prefetch00.000.00
physical reads direct00.000.00
physical reads direct (lob)00.000.00
physical reads direct temporary tablespace00.000.00
physical reads prefetch warmup00.000.00
physical write IO requests4820.502.16
physical write bytes5,996,5446,261.3026,890.33
physical write total IO requests1,4041.476.30
physical write total bytes19,209,72820,057.8586,142.28
physical write total multi block requests80.010.04
physical writes7320.763.28
physical writes direct100.010.04
physical writes direct (lob)70.010.03
physical writes direct temporary tablespace30.000.01
physical writes from cache7220.753.24
physical writes non checkpoint1000.100.45
process last non-idle time69,05972.11309.68
recursive calls41,04542.86184.06
recursive cpu usage2430.251.09
redo blocks checksummed by FG (exclusive)2,3792.4810.67
redo blocks written4,4474.6419.94
redo buffer allocation retries00.000.00
redo entries3,6683.8316.45
redo log space requests00.000.00
redo log space wait time00.000.00
redo ordering marks1200.130.54
redo size2,174,0562,270.049,749.13
redo size for direct writes3640.381.63
redo subscn max counts2800.291.26
redo synch time1,2501.315.61
redo synch writes1600.170.72
redo wastage65,97668.89295.86
redo write time9801.024.39
redo writes2550.271.14
rollback changes - undo records applied50.010.02
rollbacks only - consistent read gets630.070.28
root node splits00.000.00
rows fetched via callback2,4802.5911.12
scheduler wait time00.000.00
session connect time00.000.00
session cursor cache hits6,4886.7729.09
session logical reads43,41645.33194.69
shared hash latch upgrades - no wait4,0694.2518.25
shared hash latch upgrades - wait00.000.00
sorts (memory)3,3563.5015.05
sorts (rows)16,02516.7371.86
sql area evicted10.000.00
sql area purged130.010.06
switch current to new buffer740.080.33
table fetch by rowid8,7269.1139.13
table fetch continued row120.010.05
table scan blocks gotten3,5073.6615.73
table scan rows gotten153,585160.37688.72
table scans (short tables)1,0791.134.84
temp space allocated (bytes)00.000.00
total cf enq hold time8750.913.92
total number of cf enq holders250.030.11
total number of times SMON posted00.000.00
transaction rollbacks00.000.00
undo change vector size769,500803.473,450.67
user I/O wait time5490.572.46
user calls2,9113.0413.05
user commits2220.231.00
user rollbacks10.000.00
workarea executions - onepass00.000.00
workarea executions - optimal2,1962.299.85
write clones created in background00.000.00
write clones created in foreground00.000.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 SecondPer TransactionPer ExecPer Call
User calls:3.013.1
Parses:4.318.6
Hard parses:0.10.3
W/A MB processed:0.10.2
Logons:0.10.4
Executes:9.741.7
Rollbacks:0.00.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 ClassWaits%Time -outsTotal Wait Time (s)Avg wait (ms)%DB time
System I/O5680213652.90
Commit1500127830.06
DB CPU49.18
User I/O12004299.08
Other14795020.87
Application620000.04
Network2,2430000.01
Concurrency20000.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
    EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
    control file sequential read568213652.90System I/O
    log file sync150127830.06Commit
    DB CPU49.18
    db file sequential read1321515.07User I/O
    Disk file operations I/O104192.47User I/O