資訊專欄INFORMATION COLUMN
小伙伴們，大家好。
這次分享一個(gè)因?yàn)閼?yīng)用連接數(shù)暴漲進(jìn)而導(dǎo)致數(shù)據(jù)庫(kù)hang的故障分析處理經(jīng)驗(yàn)。
2020年01月13日，收到某運(yùn)營(yíng)商一核心數(shù)據(jù)庫(kù)告警，提示數(shù)據(jù)庫(kù)連接數(shù)超過預(yù)警閾值，短時(shí)間內(nèi)連接數(shù)暴漲，同事也收到業(yè)務(wù)人員反饋?，F(xiàn)將整個(gè)事件過程介紹如下:
01-1310:40 收到短信告警，某業(yè)務(wù)數(shù)據(jù)庫(kù)b節(jié)點(diǎn)連接數(shù)超過預(yù)警閾值。 01-1310:43 某業(yè)務(wù)庫(kù)連接數(shù)突增到16000導(dǎo)致實(shí)例hang住。 01-1310:45 為快速恢復(fù)故障決定重啟b節(jié)點(diǎn)實(shí)例及CRS服務(wù)，發(fā)現(xiàn)crs長(zhǎng)時(shí)間無法關(guān)閉。 01-1310:47 決定直接重啟b節(jié)點(diǎn)主機(jī)。 01-1311:00 b節(jié)點(diǎn)主機(jī)重啟完成，CRS服務(wù)啟動(dòng)正常，但b節(jié)點(diǎn)與a節(jié)點(diǎn)通信異常導(dǎo)致b節(jié)點(diǎn)實(shí)例無法啟動(dòng)。 01-1311:10 與業(yè)務(wù)人員溝通業(yè)務(wù)可以停止，于是，重啟a節(jié)點(diǎn)實(shí)例及CRS服務(wù)，業(yè)務(wù)a節(jié)點(diǎn)關(guān)閉完成后，業(yè)務(wù)b節(jié)點(diǎn)實(shí)例正常啟動(dòng)，狀態(tài)正常。 01-1311:15 啟動(dòng)a節(jié)點(diǎn)實(shí)例，均恢復(fù)正常。 |
根據(jù)問題發(fā)生時(shí)段數(shù)據(jù)庫(kù)預(yù)警文件、Trc、OSW、dbwait日志、ash視圖數(shù)據(jù)，查詢相關(guān)MOS資料。
問題時(shí)間點(diǎn)的主要是librarycache lock
通過
發(fā)現(xiàn)都是被9599阻塞了
查詢發(fā)現(xiàn)9599也是被阻塞的進(jìn)程
查詢6674
阻塞者是LGWR的這個(gè)進(jìn)程，它的狀態(tài)是ONCPU。
回到AWR里看看LGWR的工作情況。
首先在AWR里看到top1的等待就是logfile sync ，而且它的平均等待時(shí)間非?？鋸垼好看蝐ommit，需要等516.49ms，也就是每次提交都要等半秒多。
檢查下I/O是否有問題：
dbfile sequential read 5,300,861 3031 571.79us 8.7 User I/O
logfile parallel write 77,000 0 132 1.72ms 3.22 1.02
這幾個(gè)指標(biāo)顯示，平均讀和平均寫的速度還是非?？斓?。排除掉IO性能引發(fā)的問題。
匹配MOS中相關(guān)資料，根據(jù)文檔：
Troubleshooting:Log file sync Waits ( Doc ID 1376916.1)的介紹，再來排查應(yīng)用設(shè)計(jì)的問題。特別是ExcessiveApplication Commits 這部分。
AWR報(bào)告里的usercall 和commit/rollback的比例：211
這里也遠(yuǎn)遠(yuǎn)高于期望值，說明應(yīng)用的涉及和提交的頻率也都是合理的。
這里，基本上可以排除掉了：
A、IO問題
B、應(yīng)用提交過于頻繁的問題。
基于以上情況，我們?cè)俳Y(jié)合ASH的報(bào)告看一下：
TopSQL with Top Events TopSQL statements by DB Time along with the top events by DB Time forthose SQLs. %Activity is the percentage of DB Time due to the SQL. %Event is the percentage of DB Time due to the event that the SQL iswaiting on. %Row Source is the percentage of DB Time due to the row source for theSQL waiting on the event. Executionsis the number of executions of the SQL that were sampled in ASH. SQLID Plan Hash Executions % Activity Event % Event Top Row Source % RowSource SQL Text Container Name 6n7g6c077brjn803 20.85 CPU + Wait for CPU 9.44 ** Row Source Not Available ** 9.44insert into EVENT_FLOW_DETAIL_... PDBTPH1 6n7g6c077brjn803 20.85 db file sequential read 6.69 ** Row Source Not Available **6.69 insert into EVENT_FLOW_DETAIL_... PDBTPH1 6n7g6c077brjn803 20.85 log buffer space 2.04 ** Row Source Not Available ** 2.04insert into EVENT_FLOW_DETAIL_... PDBTPH1 f8sc80c9z96d6459533022 61 5.38 buffer busy waits 3.99 INDEX - UNIQUE SCAN 3.99select count(*) from READWRITE... PDBTPH1 0npaa07q0pttb74 3.74 log buffer space 2.31 ** Row Source Not Available ** 2.31insert into READWRITE_LOG(data... PDBTPH1 88kr8yruv2gnj39 2.75 buffer busy waits 1.36 ** Row Source Not Available ** 1.36insert into READWRITE_LOG(data... PDBTPH1 gdk0gfjud55cd3141682953 36 1.41 log buffer space 0.68 UPDATE 0.68 updatest_cdr_eventerr set tot... PDBTPH1 |
這個(gè)報(bào)告里，直接看到的20.85的Activity%都是CPU+WaitOn CPU上，而我們知道數(shù)據(jù)庫(kù)的等待的事件logbuffer space也是它造成的，那么也就是20.85+20.85+3.74+1.41的百分比的事件采樣都在CPU上等待。
看OSwatcher里CPU的情況：
vmstat里看起來CPU不是特別忙：
zzz***Fri Jan 15 14:22:13 BEIST 2021 Systemconfiguration: lcpu=72 mem=184320MB ent=18.00 kthrmemory page faults cpu ------------------- ------------------------ ----------------------------------- rb p avm fre fi fo pi po fr sr in sy cs us sy id wa pc ec 110 0 18182240 26782687 0 64 0 0 0 0 3077 95404 18331 14 13 74 0 7.3240.6 170 2 18227945 26736960 0 0 0 0 0 0 1708 67546 16123 12 10 77 0 6.1434.1 110 0 18259599 26705274 0 0 0 0 0 0 1668 104636 20241 12 10 79 0 5.9132.8 zzz***Fri Jan 15 14:22:43 BEIST 2021 Systemconfiguration: lcpu=72 mem=184320MB ent=18.00 |
由于vmstat計(jì)算的是平均值，我們看看具體的信息：
Systemconfiguration: lcpu=72 ent=18.0 mode=Capped cpumin maj mpc int cs ics rq mig lpa sysc us sy wa id pc %ec lcs 011582 0 0 696 1105 116 1 404 94 5318 46 53 0 1 0.37 2.1 466 10 0 0 17 0 0 0 0 - 0 0 0 0 100 0.07 0.4 17 20 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 30 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 418024 0 0 425 876 116 0 331 93 66250 69 30 0 1 0.27 1.5 422 50 0 0 19 0 0 0 0 - 0 0 1 0 99 0.05 0.3 19 60 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 19 70 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 19 812948 0 0 459 1117 125 0 414 96 6172 65 34 0 1 0.28 1.5 414 90 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 100 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 19 110 0 0 17 0 0 0 0 - 0 0 0 0 100 0.05 0.3 17 129500 0 0 537 1278 115 2 391 96 5561 55 43 0 2 0.25 1.4 516 130 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 140 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 150 0 0 19 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 1615891 0 0 306 724 80 1 297 93 8875 54 45 0 1 0.32 1.8 297 170 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 20 180 0 0 18 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 190 0 0 17 0 0 0 0 - 0 0 0 0 100 0.06 0.3 18 2011809 0 0 487 1160 109 0 425 96 6827 50 48 0 2 0.23 1.3 484 210 0 0 19 0 0 0 0 - 0 0 1 0 99 0.05 0.3 19 220 0 0 18 0 0 0 0 - 0 0 0 0 100 0.05 0.3 20 230 0 0 19 0 0 0 0 - 0 0 1 0 99 0.05 0.3 20 2416369 0 0 700 1172 175 1 398 96 9610 54 44 0 1 0.31 1.7 533 250 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 260 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 270 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 19 2810775 0 0 248 308 23 0 109 97 4042 68 32 0 0 0.44 2.4 184 290 0 0 18 0 0 0 0 - 0 0 0 0 100 0.08 0.4 18 300 0 0 18 0 0 0 0 - 0 0 0 0 100 0.08 0.4 18 310 0 0 17 0 0 0 0 - 0 0 0 0 100 0.08 0.4 17 3217188 0 0 390 795 92 0 348 95 5781 66 32 0 1 0.22 1.2 347 330 0 0 18 0 0 0 0 - 0 0 0 0 100 0.04 0.2 18 340 0 0 17 0 0 0 0 - 0 0 0 0 100 0.04 0.2 17 350 0 0 17 0 0 0 0 - 0 0 0 0 100 0.04 0.2 17 3617666 0 0 432 870 73 0 348 95 5447 67 31 0 2 0.20 1.1 383 370 0 0 19 0 0 0 0 - 0 0 1 0 99 0.04 0.2 20 380 0 0 18 0 0 0 0 - 0 0 0 0 100 0.04 0.2 18 390 0 0 18 0 0 0 0 - 0 0 1 0 99 0.04 0.2 18 4025199 0 0 357 990 160 1 361 75 5932 59 37 0 4 0.29 1.6 582 415707 0 0 188 437 19 0 90 100 511 25 25 0 51 0.10 0.6 262 4284 0 0 18 1 0 0 0 100 54 1 2 0 98 0.06 0.3 21 430 0 0 17 9 0 0 1 100 5 0 1 0 99 0.06 0.3 21 4416521 0 0 289 498 48 0 229 95 7464 63 36 0 1 0.32 1.8 271 450 0 0 18 0 0 0 0 - 0 0 1 0 99 0.06 0.3 19 460 0 0 19 0 0 0 0 - 0 0 0 0 100 0.06 0.3 18 470 0 0 18 0 0 0 0 - 0 0 0 0 100 0.06 0.3 18 4810136 0 1 340 697 71 0 303 95 10628 45 54 0 1 0.22 1.2 325 490 0 0 19 0 0 0 0 - 0 0 1 0 99 0.04 0.2 19 500 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 510 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 527850 0 0 542 1253 109 0 512 95 3575 55 43 0 2 0.22 1.2 487 530 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 540 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 550 0 0 19 0 0 0 0 - 0 0 0 0 100 0.04 0.2 19 566305 0 0 200 464 81 0 132 79 2582 38 23 0 39 0.21 1.2 299 57241 0 0 105 58 58 1 0 100 6 100 0 0 0 0.60 3.3 3 580 0 0 20 2 0 0 1 100 2 0 0 0 100 0.09 0.5 21 590 0 0 18 0 0 0 0 - 0 0 0 0 100 0.09 0.5 18 608082 0 0 132 411 68 1 131 73 48108 48 43 0 10 0.28 1.5 369 613843 0 0 106 72 21 0 3 100 4137 70 12 0 19 0.22 1.2 136 620 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 630 0 0 18 0 0 0 0 - 0 0 0 0 100 0.07 0.4 18 6412474 0 0 379 915 89 0 354 95 29274 47 52 0 1 0.24 1.3 398 650 0 0 18 0 0 0 0 - 0 0 1 0 99 0.04 0.2 18 660 0 0 18 0 0 0 0 - 0 0 1 0 99 0.04 0.2 18 670 0 0 18 0 0 0 0 - 0 0 0 0 100 0.04 0.2 18 686916 0 0 537 1157 134 0 219 84 5124 48 46 0 6 0.22 1.2 787 691401 0 0 114 261 14 0 49 100 2158 50 15 0 35 0.11 0.6 243 7019 0 0 25 11 0 0 0 100 41 1 2 0 97 0.05 0.3 29 710 0 0 18 0 0 0 0 - 0 0 0 0 100 0.05 0.3 18 U- - - - - - - - - - - - 0 71 10.04 55.8 - ALL246530 0 1 8893 16641 1896 8 5850 0 243484 18 11 0 71 8.61 47.9 9155 |
這里我們看到CPU的情況就不樂觀了，問題應(yīng)該就是來自于LGWR沒有被CPU及時(shí)調(diào)度了。而我們能看到有一些CPU的idle是100%，而有一批的CPU的idle是0%，而且有些idle為0的CPU的工作狀態(tài)，還有大部分是分配給了sys的。
比如：
45421 0 0 752 1446 174 1 747 95 4130 68 31 0 1 0.40 2.2 346 640 0 0 119 0 0 0 0 - 0 0 48 0 52 0.00 0.0 119 6412474 0 0 379 915 89 0 354 95 29274 47 52 0 1 0.24 1.3 398 |
無論如何，CPU有空閑但是看起來LGWR的進(jìn)程，并沒有被CPU及時(shí)的進(jìn)行調(diào)度，所以才產(chǎn)生了當(dāng)前500ms的logfile sync的等待。
根據(jù)現(xiàn)象看，就是LGWR不能及時(shí)被CPU調(diào)度
解決方案為:
確認(rèn)Aix的補(bǔ)丁打到了最高的版本，打了最新的Aix補(bǔ)丁，避免是Aix的bug引發(fā)的類似問題，已確認(rèn)為最新補(bǔ)丁。
聯(lián)系主機(jī)側(cè)確認(rèn)CPU工作狀態(tài)情況為什么是這樣的（只有個(gè)別CPU非常忙，其它都不工作），確認(rèn)關(guān)掉了IBM主機(jī)的CPU 折疊的功能
可以通過HMC/ASMI設(shè)置，關(guān)閉操作系統(tǒng)的CPU折疊的功能，關(guān)閉CPUfolding
把LGWR的進(jìn)程直接放在RR的調(diào)度方式里：
SQL>altersystem set "_high_priority_processes"=LMS*|LGWR sid=*scope=spfile;
為了避免Oracle讓LGWR進(jìn)入idle的狀態(tài)，關(guān)掉adaptive log file sync的工作模式，看是否有改進(jìn)
ALTERSYSTEM SET "_use_adaptive_log_file_sync"=
在ASH里還看到了和log buffer相關(guān)的等待，雖然次數(shù)不多，但是足以說明我們調(diào)整log buffer的大小會(huì)優(yōu)化系統(tǒng)，特別是應(yīng)用的提交頻率不高，這會(huì)對(duì)log buffer 的大小有更大的要求，可以調(diào)整log buffer的大小到32M或者更大。
文章版權(quán)歸作者所有，未經(jīng)允許請(qǐng)勿轉(zhuǎn)載,若此文章存在違規(guī)行為，您可以聯(lián)系管理員刪除。
轉(zhuǎn)載請(qǐng)注明本文地址：http://systransis.cn/yun/130004.html
摘要：于是檢查時(shí)發(fā)現(xiàn)，拼寫錯(cuò)誤，應(yīng)為。第個(gè)問題，是真真切切錯(cuò)誤卸載重要軟件包，導(dǎo)致系統(tǒng)崩潰，修復(fù)系統(tǒng)的方法自然也就是利用原鏡像在下把該裝的都裝回去，前提是日志存在，萬幸沒有執(zhí)行過。 首先問題產(chǎn)生的緣由很簡(jiǎn)單，是我一同事在安裝oracle一套軟件時(shí)，按照要求需要binutils軟件包的32位版本，然而在Oracle Linux已經(jīng)裝有64位，按理說是可以安裝i686的，我猜應(yīng)該是32位的版本低...
摘要：?jiǎn)栴}描述近期項(xiàng)目需要從虛擬機(jī)環(huán)境遷移到容器環(huán)境，其中有一個(gè)項(xiàng)目在遷移到容器環(huán)境之后的兩天之內(nèi)出現(xiàn)了次死鎖的問題，部分關(guān)鍵日志如下日志還是挺明顯的，線程獲得了鎖，等待獲取而正好相反，從而導(dǎo)致死鎖問題分析以上的錯(cuò)誤 問題描述 近期項(xiàng)目需要從虛擬機(jī)環(huán)境遷移到容器環(huán)境，其中有一個(gè)項(xiàng)目在遷移到容器環(huán)境之后的兩天之內(nèi)出現(xiàn)了2次死鎖(deadlock)的問題，部分關(guān)鍵日志如下： Found one ...
摘要：首先先解讀下這個(gè)報(bào)警內(nèi)容，原因活躍線程數(shù)過多，是監(jiān)聽的端口號(hào)用來獲取虛擬機(jī)各項(xiàng)信息，代表著此時(shí)的線程數(shù)，是設(shè)置的報(bào)警閾值。 前言 前天，一位21世紀(jì)的好好青年正在工位上默念社會(huì)主義大法好的時(shí)候，釘釘上又報(bào)警了（公司項(xiàng)目接入了open-faclon監(jiān)控，指標(biāo)不正常會(huì)報(bào)警給釘釘?shù)臋C(jī)器人），無奈默默流淚揮手告別社會(huì)主義大法開始定位線上問題。 報(bào)警內(nèi)容 首先我們先來看下報(bào)警信息，為防止泄露公...
閱讀 1356·2023-01-11 13:20
閱讀 1707·2023-01-11 13:20
閱讀 1215·2023-01-11 13:20
閱讀 1906·2023-01-11 13:20
閱讀 4165·2023-01-11 13:20
閱讀 2757·2023-01-11 13:20
閱讀 1402·2023-01-11 13:20
閱讀 3671·2023-01-11 13:20
