|
|
环境： AIX 5300-11 30408704M memory
oracle10.2.0.4 single instance
最近我在监控性能发现DB time的时间远大于Wait_time+DB CPU, 查阅了很多文章都没结果，贴出来麻烦大家帮我分析一下。
1. 摘录一部分AWR报告
WORKLOAD REPOSITORY report for
DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
PROD 741258667 prod 1 10.2.0.4.0 NO db1
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 33350 11-May-11 21:00:37 54 12.7
End Snap: 33351 11-May-11 22:00:02 52 13.0
Elapsed: 59.40 (mins
DB Time: 491.09 (mins)
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 1,312M 1,824M Std Block Size: 8K
Shared Pool Size: 2,048M 1,536M Log Buffer: 14,340K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 300,289.48 32,217.57
Logical reads: 76,388.09 8,195.55
Block changes: 2,117.34 227.17
Physical reads: 299.05 32.08
Physical writes: 59.13 6.34
User calls: 2,673.46 286.83
Parses: 69.52 7.46
Hard parses: 3.56 0.38
Sorts: 67.15 7.20
Logons: 0.27 0.03
Executes: 182.25 19.55
Transactions: 9.32
% Blocks changed per Read: 2.77 Recursive Call %: 25.42
Rollback per transaction %: 0.53 Rows per Sort: 8.80
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.61 In-memory Sort %: 100.00
Library Hit %: 97.83 Soft Parse %: 94.87
Execute to Parse %: 61.85 Latch Hit %: 99.99
Parse CPU to Parse Elapsd %: 19.84 % Non-Parse CPU: 97.76
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 44.96 24.17
% SQL with executions>1: 82.40 92.53
% Memory for SQL w/exec>1: 89.61 84.47
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 3,201 10.9
db file scattered read 187,905 1,903 10 6.5 User I/O
latch: shared pool 2,071 264 128 0.9 Concurrenc
latch: library cache 2,363 249 106 0.8 Concurrenc
db file sequential read 12,000 220 18 0.7 User I/O
-------------------------------------------------------------
Time Model Statistics DB/Inst: PROD/prod Snaps: 33350-33351
-> Total time in database user-calls (DB Time): 29465.3s
-> 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 29,915.6 101.5
Java execution elapsed time 15,483.6 52.5
PL/SQL execution elapsed time 9,162.4 31.1
DB CPU 3,200.7 10.9
parse time elapsed 686.4 2.3
hard parse elapsed time 502.1 1.7
PL/SQL compilation elapsed time 108.5 .4
sequence load elapsed time 16.7 .1
repeated bind elapsed time 0.9 .0
hard parse (sharing criteria) elapsed time 0.6 .0
connection management call elapsed time 0.3 .0
failed parse elapsed time 0.0 .0
hard parse (bind mismatch) elapsed time 0.0 .0
DB time 29,465.3 N/A
background elapsed time 658.2 N/A
background cpu time 18.9 N/A
-------------------------------------------------------------
Wait Class DB/Inst:PROD/prod Snaps: 33350-33351
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc
Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
User I/O 208,244 .0 2,133 10 6.3
Concurrency 7,698 31.2 551 72 0.2
System I/O 43,643 .0 344 8 1.3
Network 10,165,606 .0 11 0 306.0
Application 399 .0 9 23 0.0
Commit 1,066 .0 7 7 0.0
Other 1,419 2.3 6 4 0.0
Configuration 41 .0 3 82 0.0
-------------------------------------------------------------
Wait Events DB/Inst: PROD/prod Snaps: 33350-33351
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)
Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file scattered read 187,905 .0 1,903 10 5.7
latch: shared pool 2,071 .0 264 128 0.1
latch: library cache 2,363 .0 249 106 0.1
db file sequential read 12,000 .0 220 18 0.4
log file parallel write 36,240 .0 178 5 1.1
db file parallel write 3,410 .0 159 47 0.1
cursor: pin S wait on X 2,402 100.0 24 10 0.1
enq: UL - contention 122 .0 8 63 0.0
log file sync 1,066 .0 7 7 0.0
os thread startup 148 .0 7 46 0.0
SQL*Net message to client 9,515,904 .0 6 0 286.5
control file parallel write 1,237 .0 5 4 0.0
SQL*Net more data to client 648,854 .0 5 0 19.5
read by other session 84 .0 4 48 0.0
direct path write 2,756 .0 4 1 0.1
enq: SQ - contention 22 .0 3 134 0.0
library cache load lock 20 .0 3 142 0.0
direct path read 5,494 .0 2 0 0.2
latch: redo allocation 72 .0 2 24 0.0
enq: JS - queue lock 46 .0 2 36 0.0
SQL*Net break/reset to clien 246 .0 1 6 0.0
latch: row cache objects 41 .0 1 33 0.0
control file sequential read 2,740 .0 1 0 0.1
latch: cache buffers chains 133 .0 1 6 0.0
latch free 34 .0 1 23 0.0
enq: TX - contention 9 .0 1 76 0.0
latch: object queue header o 19 .0 0 23 0.0
LGWR wait for redo copy 933 2.8 0 0 0.0
enq: TX - index contention 4 .0 0 94 0.0
log file switch completion 8 .0 0 41 0.0
buffer busy waits 467 .0 0 1 0.0
kksfbc child completion 2 100.0 0 49 0.0
latch: redo writing 2 .0 0 48 0.0
latch: cache buffers lru cha 9 .0 0 8 0.0
rdbms ipc reply 284 .0 0 0 0.0
log file single write 8 .0 0 3 0.0
latch: In memory undo latch 45 .0 0 0 0.0
latch: session allocation 2 .0 0 9 0.0
latch: enqueue hash chains 4 .0 0 5 0.0
latch: library cache lock 1 .0 0 12 0.0
enq: TX - row lock contentio 31 .0 0 0 0.0
enq: HW - contention 9 .0 0 1 0.0
log file sequential read 8 .0 0 1 0.0
SQL*Net more data from clien 805 .0 0 0 0.0
direct path write temp 5 .0 0 0 0.0
SQL*Net more data from dblin 6 .0 0 0 0.0
SQL*Net message to dblink 36 .0 0 0 0.0
enq: FB - contention 1 .0 0 0 0.0
SQL*Net more data to dblink 1 .0 0 0 0.0
buffer deadlock 4 100.0 0 0 0.0
cursor: mutex S 3 .0 0 0 0.0
SQL*Net message from client 9,515,902 .0 48,075 5 286.5
Streams AQ: waiting for time 369 70.7 26,143 70849 0.0
jobq slave wait 5,562 85.2 15,209 2734 0.2
Streams AQ: qmn coordinator 1,341 39.6 3,481 2596 0.0
EMON idle wait 713 100.0 3,478 4879 0.0
wait for unread message on b 3,655 97.2 3,478 952 0.1
Streams AQ: waiting for mess 712 100.0 3,470 4874 0.0
virtual circuit status 119 100.0 3,458 29057 0.0
Streams AQ: qmn slave idle w 714 .0 3,454 4838 0.0
Wait Events DB/Inst: PROD/prod Snaps: 33350-33351
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)
Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
SGA: MMAN sleep for componen 40 82.5 0 9 0.0
single-task message 1 .0 0 301 0.0
SQL*Net message from dblink 36 .0 0 1 0.0
class slave wait 3 .0 0 0 0.0
-------------------------------------------------------------
Background Wait Events DB/Inst: PROD/prod Snaps: 33350-33351
-> ordered by wait time desc, waits desc (idle events last)
Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file parallel write 36,247 .0 178 5 1.1
db file parallel write 3,410 .0 159 47 0.1
latch: shared pool 181 .0 35 195 0.0
latch: library cache 175 .0 32 184 0.0
db file sequential read 2,390 .0 15 6 0.1
os thread startup 148 .0 7 46 0.0
control file parallel write 1,238 .0 5 4 0.0
events in waitclass Other 1,350 1.9 2 2 0.0
latch: row cache objects 7 .0 1 90 0.0
control file sequential read 1,443 .0 1 0 0.0
db file scattered read 25 .0 1 23 0.0
latch: cache buffers chains 81 .0 1 7 0.0
direct path write 70 .0 0 3 0.0
latch: redo writing 2 .0 0 48 0.0
direct path read 70 .0 0 1 0.0
log file single write 8 .0 0 3 0.0
log file sequential read 8 .0 0 1 0.0
buffer busy waits 2 .0 0 0 0.0
rdbms ipc message 45,069 26.0 30,741 682 1.4
Streams AQ: waiting for time 369 70.7 26,143 70849 0.0
pmon timer 1,241 100.0 3,483 2807 0.0
Streams AQ: qmn coordinator 1,341 39.6 3,481 2596 0.0
EMON idle wait 713 100.0 3,478 4879 0.0
smon timer 198 .0 3,458 17463 0.0
Streams AQ: qmn slave idle w 714 .0 3,454 4838 0.0
SGA: MMAN sleep for componen 40 82.5 0 9 0.0
-------------------------------------------------------------
Operating System Statistics DB/Inst: PROD/prod Snaps: 33350-33351
Statistic Total
-------------------------------- --------------------
NUM_LCPUS 0
NUM_VCPUS 0
AVG_BUSY_TIME 80,897
AVG_IDLE_TIME 275,913
AVG_IOWAIT_TIME 66,666
AVG_SYS_TIME 22,040
AVG_USER_TIME 58,739
BUSY_TIME 485,943
IDLE_TIME 1,656,091
IOWAIT_TIME 400,567
SYS_TIME 132,880
USER_TIME 353,063
LOAD 0
OS_CPU_WAIT_TIME 578,200
RSRC_MGR_CPU_WAIT_TIME 0
PHYSICAL_MEMORY_BYTES 31,138,447,360
NUM_CPUS 6
NUM_CPU_CORES 3
2. 所有的事件百分比加起来还不到20%，加上其他的也不会超过30%。应该说DB很闲，但是为什么DB Time是491.09mis呢？
3. DB time = 491.09min = 29465.4s
DB cpu = 3,200.7s
Wait_time 通过以下SQL来计算出来是: 3063s， DB time是不算Idle等待和background的
DB cpu(3200.7)+ wait_time(3063) = 6263.7s, 此数字远远小于DB time(29465.4s), 那剩下的时间干什么去了呢？？
很不明白，难道Oracle有Bug，去support看了一下，只是说等待direct path....相关的等待会有问题，但我这儿没有这样的事件。
我又看到一篇文件说：Wait_time + DB CPU << DB time 可能cpu非常繁忙，有cpu queue情况，但是我这里CPU应该是很闲的，而且有6个CPU。
select snap_id,begin_interval_time,end_interval_time,
round(sum(time_waited)/1000000) time_waited
from (
select a.dbid
, a.instance_number
, a.snap_id
, a.event_name
, a.wait_class
, s.startup_time
, s.begin_interval_time
, s.end_interval_time
, (case when s.begin_interval_time = s.startup_time then a.time_waited_micro
else a.time_waited_micro - lag( a.time_waited_micro, 1 )
over (partition by a.event_id, a.dbid, a.instance_number, s.startup_time
order by a.snap_id) end ) time_waited
from dba_hist_system_event a,
dba_hist_snapshot s
where a.dbid=s.dbid
and a.instance_number=s.instance_number
and a.snap_id=s.snap_id
and wait_class<>'Idle'
and a.snap_id in (33350,33351)
)
where time_waited is not null
group by snap_id,begin_interval_time,end_interval_time
[ 本帖最后由 Osric 于 2011-5-12 13:30 编辑 ] |
|
IP卡
狗仔卡
发表于 2011-5-12 12:36
收藏
提升卡
置顶卡
变色卡
显身卡
楼主
发表于 2011-5-13 17:18