[20191127]探究等待事件的本源4.txt
[20191127]探究等待事件的本源4.txt
--//昨天使用ash_wait_chains.sql指令碼把各個生產庫執行1遍,才發現我對一套系統效能理解錯誤.
--//我一直以為這套系統儲存有點問題,效能不是很好.
1.環境:
xxxxxx> @ ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.分析:
xxxxxx> @ tpt/ash/ash_wait_chains event2 1=1 trunc(sysdate)+8/24 sysdate
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- -------------------------------------------------------------
39% 2667 .5 -> ON CPU
18% 1274 .2 -> LNS wait on SENDREQ
18% 1249 .2 -> log file sync -> LGWR-LNS wait on channel
18% 1215 .2 -> LGWR-LNS wait on channel
1% 62 0 -> log file sync
1% 60 0 -> log file parallel write
1% 46 0 -> control file sequential read
1% 39 0 -> db file sequential read
1% 36 0 -> log file sync -> log file parallel write
0% 29 0 -> gc cr block 2-way
0% 24 0 -> gc current block 2-way
0% 23 0 -> null event
0% 21 0 -> direct path read
0% 20 0 -> log file sync -> ON CPU
0% 18 0 -> gcs log flush sync -> LGWR-LNS wait on channel
0% 18 0 -> gc cr block busy
0% 16 0 -> db file parallel write
0% 12 0 -> SQL*Net more data to client
0% 10 0 -> gc cr multi block request
0% 9 0 -> gc current grant busy
0% 7 0 -> Disk file operations I/O
0% 6 0 -> ASM file metadata operation
0% 5 0 -> log file sequential read
0% 4 0 -> LGWR wait on LNS
0% 4 0 -> log file switch completion -> LGWR-LNS wait on channel
0% 4 0 -> IPC send completion sync
0% 4 0 -> control file parallel write
0% 3 0 -> reliable message
0% 3 0 -> log file sync -> LGWR wait on LNS
0% 2 0 -> CGS wait for IPC msg
30 rows selected.
xxxxxx> select sysdate from dual ;
SYSDATE
-------------------
2019-11-27 09:27:51
xxxxxx> @ tpt/ash/ash_wait_chains event2 "event='log file sync'" trunc(sysdate)+8/24 sysdate
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- ----------------------------------------------
91% 1249 .2 -> log file sync -> LGWR-LNS wait on channel
5% 62 0 -> log file sync
3% 36 0 -> log file sync -> log file parallel write
1% 20 0 -> log file sync -> ON CPU
0% 3 0 -> log file sync -> LGWR wait on LNS
--//實際上主要問題在於log_archive_dest_2引數設定不合理,採用sync引數.
xxxxxx> show parameter log_archive_dest_2
NAME TYPE VALUE
------------------ ------ ----------------------------------------------------------------------------------------------------
log_archive_dest_2 string service=xxxxxx lgwr sync reopen=15 max_failure=10 net_timeout=30 optional noaffirm db_unique_name=xxxxx
xxxxxx> show parameter log_archive_config
NAME TYPE VALUE
------------------ ------ -----------
log_archive_config string nodg_config
--//實際上我第一次看應該是去年的春節前後,剛上線,當時這個問題沒有嚴重,現在顯得越來越明顯.
--//"可怕"的是我不能修改這個引數,這個所謂的dg是一個第三方安裝的東西,根本不是什麼dg,我一修改引數,對方的軟體視乎就檢測我的改動,自動重置回來.
--//alter system set log_archive_dest_2="service=xxxxxx lgwr async reopen=15 max_failure=10 net_timeout=30 optional noaffirm db_unique_name=xxxxxx";
--//btw:好像這個引數可以修改,也許我記錯了,不能修改log_archive_config引數,等一段時間觀察看看.
--//看awr報表:
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Tota Wait % DB
Event Waits Time Avg(ms) time Wait Class
------------------------------ ------------ ---- ------- ------ ----------
DB CPU 1063 78.5
log file sync 46,848 311. 7 23.0 Commit
control file sequential read 68,350 21.1 0 1.6 System I/O
gc cr block 2-way 17,827 8.2 0 .6 Cluster
gc current block 2-way 17,190 7.4 0 .5 Cluster
gc cr block busy 218 6.8 31 .5 Cluster
SQL*Net more data to client 541,828 6.4 0 .5 Network
db file sequential read 936 6 6 .4 User I/O
direct path read 1,591 5.2 3 .4 User I/O
Disk file operations I/O 23,740 4.6 0 .3 User I/O
--//log file sync 平均等待7ms,到業務高峰可以到達13-14ms.我開始以為磁碟io不行,或者使用asm的原因.實際是就是上面的引數設定不合理.
--//如果不小心選擇最佳化磁碟IO,那就選擇錯誤的最佳化方向.實際上這套系統cpu充足,磁碟效能也不差,典型的大馬拉小車.
--//主要問題在於應用軟體垃圾(不僅僅指這個dg設定)!!也就是我以前提得良好的硬體掩蓋拙劣的應用設計.
--//再來看看control file sequential read等待事件:
IOStat by Filetype summary DB/Inst: zzzzz/zzzzz1 Snaps: 25477-25478
-> 'Data' columns suffixed with M,G,T,P are in multiples of 1024
other columns suffixed with K,M,G,T,P are in multiples of 1000
-> Small Read and Large Read are average service times, in milliseconds
-> Ordered by (Data Read + Write) desc
Reads: Reqs Data Writes: Reqs Data Small Large
Filetype Name Data per sec per sec Data per sec per sec Read Read
--------------- ------- ------- ------- ------- ------- ------- ------- -------
Control File 8.3G 27.2 2.382M 228M 3.6 .064M 0.1 0.8
Log File 206M 0.1 .058M 228M 20.4 .064M 1.5 6.0
Data File 64M 2.2 .018M 235M 4.6 .066M 2.3 N/A
Archive Log 1M 0.2 0M 205M 0.1 .057M 0.0 N/A
Temp File 23M 0.0 .006M 23M 0.0 .006M 0.0 1.7
TOTAL: 8.6G 29.7 2.464M 919M 28.6 .257M 0.3 0.9
------------------------------------------------------
--//實際上對方的軟體簡直是變態,關於這個問題的描述在連結如下,不再分析展開貼出:
--//http://blog.itpub.net/267265/viewspace-2222146/=>[20181129]大量的control file sequential read.txt.
3.修改引數後的觀察:
--//檢查alert發現,是Wed Nov 27 09:33:31 2019修改引數
Wed Nov 27 09:33:31 2019
ALTER SYSTEM SET log_archive_dest_2='service=xxxxx lgwr async reopen=15 max_failure=10 net_timeout=30 optional noaffirm db_unique_name=xxxxx' SCOPE=BOTH;
xxxxxx> select sysdate from dual ;
SYSDATE
-------------------
2019-11-27 10:08:20
xxxxxx> @ tpt/ash/ash_wait_chains event2 "event='log file sync'" trunc(sysdate)+9/24+33/1440 sysdate
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- -----------------------------------------------------------------------------------------------
57% 26 0 -> log file sync -> LGWR-LNS wait on channel
33% 15 0 -> log file sync
9% 4 0 -> log file sync -> log file parallel write
2% 1 0 -> log file sync -> ON CPU
xxxxxx> @ tpt/ash/ash_wait_chains event2 "event='log file sync'" trunc(sysdate)+9/24+34/1440 sysdate
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- -----------------------------------------------------------------------------------------------
74% 14 0 -> log file sync
21% 4 0 -> log file sync -> log file parallel write
5% 1 0 -> log file sync -> ON CPU
--//你可以對比看出取值範圍9:33換成9:34,多了1分鐘由LGWR-LNS wait on channel引起的log file sync佔26秒,而9:34後的查詢完全看不到這個情況.
xxxxxx> @ tpt/ash/ash_wait_chains program2||event2 1=1 trunc(sysdate)+9/24+34/1440 sysdate
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- -----------------------------------------------------------------------------------------------
36% 547 .2 -> (zzzzzz.EXE) ON CPU
13% 204 .1 -> (wnwp.exe) ON CPU
9% 145 .1 -> (zzzzzz.EXE) ON CPU
7% 107 0 -> (NSAn) ON CPU
5% 80 0 -> (CAPAA-PIPE) ON CPU
3% 40 0 -> (httpd.exe) ON CPU
2% 31 0 -> (sqlplus) ON CPU
2% 31 0 -> (DIAn) ON CPU
2% 24 0 -> (oracle) ON CPU
1% 22 0 -> (LGWR) ON CPU
1% 22 0 -> (PSPn) ON CPU
1% 21 0 -> (LGWR) log file parallel write
1% 16 0 -> (NSAn) LNS wait on SENDREQ
1% 15 0 -> (sqlplus) control file sequential read
1% 15 0 -> (LMSn) ON CPU
1% 13 0 -> (zzzzzz.EXE) db file sequential read
1% 12 0 -> (zzzzzz.EXE) gc cr block 2-way
1% 12 0 -> (routine.exe) ON CPU
1% 12 0 -> (PlSqlDev.exe) ON CPU
1% 10 0 -> (Toad.exe) ON CPU
1% 10 0 -> (DBWn) db file parallel write
0% 7 0 -> (DBWn) ON CPU
0% 7 0 -> (wnwp.exe) log file sync
0% 6 0 -> (zzzzzz.EXE) gc current block 2-way
0% 6 0 -> (zzzzzz.EXE) log file sync
0% 6 0 -> (zzzzzz.EXE) direct path read
0% 5 0 -> (zzzzzz.EXE) log file sync
0% 5 0 -> (LMON) ON CPU
0% 4 0 -> (wnwp.exe) log file sync -> (LGWR) log file parallel write
0% 4 0 -> (MMON) ON CPU
30 rows selected.
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2665813/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20191125]探究等待事件的本源.txt事件
- [20191126]探究等待事件的本源2.txt事件
- [20180922]等待事件SQLNet more data from client 4.txt事件SQLclient
- [20210315]理解db file parallel read等待事件4.txtParallel事件
- [20210914]探究mutex的值 4.txtMutex
- [20211031]18c row cache mutext等待事件探究.txtMutex事件
- Solidity事件，等待事件Solid事件
- [20210126]探究oracle記憶體分配4.txtOracle記憶體
- [20200217]使用snapper探究DBMS_SHARED_POOL.MARKHOT標識熱物件的等待事件.txtAPP物件事件
- 【TUNE_ORACLE】等待事件之等待事件類別Oracle事件
- [20180129]簡單探究cluster table(補充)4.txt
- Selenium等待事件Waits事件AI
- read by other session等待事件Session事件
- log file sync等待事件事件
- ORACLE 常見等待事件Oracle事件
- latch等待事件彙總事件
- Latch free等待事件(轉)事件
- gc cr request等待事件GC事件
- 【等待事件】library cache pin事件
- 【等待事件】log file sync事件
- 【TUNE_ORACLE】等待事件之日誌等待“log file sync”Oracle事件
- 【TUNE_ORACLE】等待事件之IO等待“read by other session”Oracle事件Session
- 【TUNE_ORACLE】等待事件之IO等待“direct path read”Oracle事件
- 【TUNE_ORACLE】等待事件之IO等待“direct path write”Oracle事件
- Latch free等待事件四(轉)事件
- Latch free等待事件三(轉)事件
- db file scattered read等待事件事件
- db file sequential read等待事件事件
- latch:library cache lock等待事件事件
- Oracle常見UNDO等待事件Oracle事件
- Latch free等待事件二(轉)事件
- LightDB/PostgreSQL等待事件 Lock transactionidSQL事件
- openGauss/MOGDB與PG等待事件事件
- Cell smart table scan等待事件事件
- read by other session 等待事件分析Session事件
- 【等待事件】db file sequential read事件
- 【等待事件】db file scattered read事件
- 【等待事件】virtual circuit next request事件UI