oracle9i statspack 報告 分析 direct path read 等待事件
阿新 • • 發佈：2017-06-03
sql pin physical 100% ica statistic ffi 10.9 count(0
DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
LIXORA 1409317108 LIXORA 1 9.2.0.1.0 NO lixora-DATA
Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 52 06-8月 -15 09:35:04 107 110.9
End Snap: 53 06-8月 -15 09:49:47 112 106.5
Elapsed: 14.72 (mins)
Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 600M Std Block Size: 8K
Shared Pool Size: 200M Log Buffer: 10,240K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 3,473.25 1,406.83
Logical reads: 6,959.90 2,819.08
Block changes: 15.52 6.28
Physical reads: 554.17 224.46
Physical writes: 391.05 158.39
User calls: 80.09 32.44
Parses: 13.35 5.41
Hard parses: 1.69 0.68
Sorts: 6.34 2.57
Logons: 0.03 0.01
Executes: 167.66 67.91
Transactions: 2.47
% Blocks changed per Read: 0.22 Recursive Call %: 70.00
Rollback per transaction %: 79.27 Rows per Sort: 2161.38
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.54 Redo NoWait %: 100.00
Buffer Hit %: 97.66 In-memory Sort %: 93.03
Library Hit %: 98.20 Soft Parse %: 87.35
Execute to Parse %: 92.04 Latch Hit %: 98.16
Parse CPU to Parse Elapsd %: 19.16 % Non-Parse CPU: 95.76
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 86.21 86.82
% SQL with executions>1: 52.42 54.94
% Memory for SQL w/exec>1: 49.55 51.72
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
direct path read 40,202 8,654 51.85
buffer busy waits 28,721 2,001 11.99
db file sequential read 26,887 1,997 11.97
enqueue 553 1,702 10.20
db file scattered read 22,423 1,661 9.95
-------------------------------------------------------------
Wait Events for DB: LIXORA Instance: LIXORA Snaps: 52 -53
-> 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
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
direct path read 40,202 0 8,654 215 18.4
buffer busy waits 28,721 16 2,001 70 13.2
db file sequential read 26,887 0 1,997 74 12.3
enqueue 553 553 1,702 3078 0.3
db file scattered read 22,423 0 1,661 74 10.3
log file sync 493 4 111 224 0.2
direct path write 1,588 0 100 63 0.7
control file parallel write 243 0 99 408 0.1
log file parallel write 508 439 86 169 0.2
db file parallel write 342 171 80 233 0.2
control file sequential read 318 0 16 51 0.1
library cache pin 118 0 8 67 0.1
library cache load lock 6 2 6 1060 0.0
latch free 679 625 0 1 0.3
row cache lock 5 0 0 17 0.0
SQL*Net more data to client 871 0 0 0 0.4
SQL*Net break/reset to clien 26 0 0 0 0.0
LGWR wait for redo copy 1 0 0 0 0.0
SQL*Net message from client 69,253 0 20,459 295 31.8
virtual circuit status 28 28 840 29999 0.0
SQL*Net message to client 69,269 0 0 0 31.8
SQL*Net more data from clien 21 0 0 0 0.0
-------------------------------------------------------------
Background Wait Events for DB: LIXORA Instance: LIXORA Snaps: 52 -53
-> ordered by wait time desc, waits desc (idle events last)
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
direct path read 1,467 0 278 190 0.7
db file scattered read 1,483 0 152 103 0.7
buffer busy waits 1,441 0 146 102 0.7
control file parallel write 244 0 100 408 0.1
log file parallel write 508 439 85 168 0.2
db file parallel write 344 172 80 233 0.2
db file sequential read 319 0 23 71 0.1
control file sequential read 100 0 6 59 0.0
direct path write 8 0 0 25 0.0
latch free 23 22 0 1 0.0
LGWR wait for redo copy 1 0 0 0 0.0
rdbms ipc message 2,435 1,959 5,846 2401 1.1
smon timer 3 3 922 ###### 0.0
SQL*Net message from client 32 0 0 1 0.0
SQL*Net message to client 32 0 0 0 0.0
每秒redo 生產僅僅有3.4kb,且系統cpu。 mem 都沒有大的開銷。
log file parallel write 平均等待168ms ；基本能夠表明是系統io負載過高
direct path read 等待過高 正是因為io 負載過高而表征出來;
‘wait time‘= 49982.8604 cs
‘Service Time‘ = 48414 cs
‘Response Time‘ = 98396.8604 cs
--‘Response Time‘ components:---
CPU time =49.2%
direct path read =26.7%
db file sequential read =7.3%
enqueue =6.9%
db file scattered read =3.9%
buffer busy waits =2.1%
對statspack 具體分析後發現，系統的服務時間占用了49.2%，而cpu的高開銷，
也從一個側面表明，應用存在大開銷cpu 的操作。這類操作一般可能是排序。或者大量硬解析。
可是top event裏並沒有看到shared pool 相關的等待事件。
繼續看下 SQL ordered by Gets
CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
333,146 7 47,592.3 2.6 43.73 ######### 3804332362
select count(0) from (select LIXORA_QX.*,(SELECT YQLB FROM LIXORA_QX
YQ WHERE LIXORA_HLJ.SEQ_NUMBER = LIXORA_QX.DQYQXH) AS YQLB from T_S
B_QX where (1=1) order by C_DATE) --果然存在一個排序操作
建議：
1》sql 語句調整，降低排序；能夠在c_date 字段上加索引；或者去掉order by
------------ ----------- ------------ -------- ----------- ------- ------------
LIXORA 1409317108 LIXORA 1 9.2.0.1.0 NO lixora-DATA
Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 52 06-8月 -15 09:35:04 107 110.9
End Snap: 53 06-8月 -15 09:49:47 112 106.5
Elapsed: 14.72 (mins)
Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 600M Std Block Size: 8K
Shared Pool Size: 200M Log Buffer: 10,240K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 3,473.25 1,406.83
Logical reads: 6,959.90 2,819.08
Block changes: 15.52 6.28
Physical reads: 554.17 224.46
Physical writes: 391.05 158.39
User calls: 80.09 32.44
Parses: 13.35 5.41
Hard parses: 1.69 0.68
Sorts: 6.34 2.57
Logons: 0.03 0.01
Executes: 167.66 67.91
Transactions: 2.47
% Blocks changed per Read: 0.22 Recursive Call %: 70.00
Rollback per transaction %: 79.27 Rows per Sort: 2161.38
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.54 Redo NoWait %: 100.00
Buffer Hit %: 97.66 In-memory Sort %: 93.03
Library Hit %: 98.20 Soft Parse %: 87.35
Execute to Parse %: 92.04 Latch Hit %: 98.16
Parse CPU to Parse Elapsd %: 19.16 % Non-Parse CPU: 95.76
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 86.21 86.82
% SQL with executions>1: 52.42 54.94
% Memory for SQL w/exec>1: 49.55 51.72
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
direct path read 40,202 8,654 51.85
buffer busy waits 28,721 2,001 11.99
db file sequential read 26,887 1,997 11.97
enqueue 553 1,702 10.20
db file scattered read 22,423 1,661 9.95
-------------------------------------------------------------
Wait Events for DB: LIXORA Instance: LIXORA Snaps: 52 -53
-> 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
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
direct path read 40,202 0 8,654 215 18.4
buffer busy waits 28,721 16 2,001 70 13.2
db file sequential read 26,887 0 1,997 74 12.3
enqueue 553 553 1,702 3078 0.3
db file scattered read 22,423 0 1,661 74 10.3
log file sync 493 4 111 224 0.2
direct path write 1,588 0 100 63 0.7
control file parallel write 243 0 99 408 0.1
log file parallel write 508 439 86 169 0.2
db file parallel write 342 171 80 233 0.2
control file sequential read 318 0 16 51 0.1
library cache pin 118 0 8 67 0.1
library cache load lock 6 2 6 1060 0.0
latch free 679 625 0 1 0.3
row cache lock 5 0 0 17 0.0
SQL*Net more data to client 871 0 0 0 0.4
SQL*Net break/reset to clien 26 0 0 0 0.0
LGWR wait for redo copy 1 0 0 0 0.0
SQL*Net message from client 69,253 0 20,459 295 31.8
virtual circuit status 28 28 840 29999 0.0
SQL*Net message to client 69,269 0 0 0 31.8
SQL*Net more data from clien 21 0 0 0 0.0
-------------------------------------------------------------
Background Wait Events for DB: LIXORA Instance: LIXORA Snaps: 52 -53
-> ordered by wait time desc, waits desc (idle events last)
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
direct path read 1,467 0 278 190 0.7
db file scattered read 1,483 0 152 103 0.7
buffer busy waits 1,441 0 146 102 0.7
control file parallel write 244 0 100 408 0.1
log file parallel write 508 439 85 168 0.2
db file parallel write 344 172 80 233 0.2
db file sequential read 319 0 23 71 0.1
control file sequential read 100 0 6 59 0.0
direct path write 8 0 0 25 0.0
latch free 23 22 0 1 0.0
LGWR wait for redo copy 1 0 0 0 0.0
rdbms ipc message 2,435 1,959 5,846 2401 1.1
smon timer 3 3 922 ###### 0.0
SQL*Net message from client 32 0 0 1 0.0
SQL*Net message to client 32 0 0 0 0.0
每秒redo 生產僅僅有3.4kb,且系統cpu。 mem 都沒有大的開銷。
log file parallel write 平均等待168ms ；基本能夠表明是系統io負載過高
direct path read 等待過高 正是因為io 負載過高而表征出來;
‘wait time‘= 49982.8604 cs
‘Service Time‘ = 48414 cs
‘Response Time‘ = 98396.8604 cs
--‘Response Time‘ components:---
CPU time =49.2%
direct path read =26.7%
db file sequential read =7.3%
enqueue =6.9%
db file scattered read =3.9%
buffer busy waits =2.1%
對statspack 具體分析後發現，系統的服務時間占用了49.2%，而cpu的高開銷，
也從一個側面表明，應用存在大開銷cpu 的操作。這類操作一般可能是排序。或者大量硬解析。
可是top event裏並沒有看到shared pool 相關的等待事件。
繼續看下 SQL ordered by Gets
CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
333,146 7 47,592.3 2.6 43.73 ######### 3804332362
select count(0) from (select LIXORA_QX.*,(SELECT YQLB FROM LIXORA_QX
YQ WHERE LIXORA_HLJ.SEQ_NUMBER = LIXORA_QX.DQYQXH) AS YQLB from T_S
B_QX where (1=1) order by C_DATE) --果然存在一個排序操作
建議：
1》sql 語句調整，降低排序；能夠在c_date 字段上加索引；或者去掉order by
2》更換更高性能的存儲
oracle9i statspack 報告 分析 direct path read 等待事件