資訊專欄INFORMATION COLUMN
小伙伴們，大家好。
這次分享一個因為應用連接數暴漲進而導致數據庫hang的故障分析處理經驗。
2020年01月13日，收到某運營商一核心數據庫告警，提示數據庫連接數超過預警閾值，短時間內連接數暴漲，同事也收到業務人員反饋?，F將整個事件過程介紹如下:
01-1310:40 收到短信告警，某業務數據庫b節點連接數超過預警閾值。 01-1310:43 某業務庫連接數突增到16000導致實例hang住。 01-1310:45 為快速恢復故障決定重啟b節點實例及CRS服務，發現crs長時間無法關閉。 01-1310:47 決定直接重啟b節點主機。 01-1311:00 b節點主機重啟完成，CRS服務啟動正常，但b節點與a節點通信異常導致b節點實例無法啟動。 01-1311:10 與業務人員溝通業務可以停止，于是，重啟a節點實例及CRS服務，業務a節點關閉完成后，業務b節點實例正常啟動，狀態正常。 01-1311:15 啟動a節點實例，均恢復正常。 |
根據問題發生時段數據庫預警文件、Trc、OSW、dbwait日志、ash視圖數據，查詢相關MOS資料。
問題時間點的主要是librarycache lock
通過
發現都是被9599阻塞了
查詢發現9599也是被阻塞的進程
查詢6674
阻塞者是LGWR的這個進程，它的狀態是ONCPU。
回到AWR里看看LGWR的工作情況。
首先在AWR里看到top1的等待就是logfile sync ，而且它的平均等待時間非常夸張：每次commit，需要等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
這幾個指標顯示，平均讀和平均寫的速度還是非?？斓?。排除掉IO性能引發的問題。
匹配MOS中相關資料，根據文檔：
Troubleshooting:Log file sync Waits ( Doc ID 1376916.1)的介紹，再來排查應用設計的問題。特別是ExcessiveApplication Commits 這部分。
AWR報告里的usercall 和commit/rollback的比例：211
這里也遠遠高于期望值，說明應用的涉及和提交的頻率也都是合理的。
這里，基本上可以排除掉了：
A、IO問題
B、應用提交過于頻繁的問題。
基于以上情況，我們再結合ASH的報告看一下：
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 |
這個報告里，直接看到的20.85的Activity%都是CPU+WaitOn CPU上，而我們知道數據庫的等待的事件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計算的是平均值，我們看看具體的信息：
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的情況就不樂觀了，問題應該就是來自于LGWR沒有被CPU及時調度了。而我們能看到有一些CPU的idle是100%，而有一批的CPU的idle是0%，而且有些idle為0的CPU的工作狀態，還有大部分是分配給了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的進程，并沒有被CPU及時的進行調度，所以才產生了當前500ms的logfile sync的等待。
根據現象看，就是LGWR不能及時被CPU調度
解決方案為:
確認Aix的補丁打到了最高的版本，打了最新的Aix補丁，避免是Aix的bug引發的類似問題，已確認為最新補丁。
聯系主機側確認CPU工作狀態情況為什么是這樣的（只有個別CPU非常忙，其它都不工作），確認關掉了IBM主機的CPU 折疊的功能
可以通過HMC/ASMI設置，關閉操作系統的CPU折疊的功能，關閉CPUfolding
把LGWR的進程直接放在RR的調度方式里：
SQL>altersystem set "_high_priority_processes"=LMS*|LGWR sid=*scope=spfile;
為了避免Oracle讓LGWR進入idle的狀態，關掉adaptive log file sync的工作模式，看是否有改進
ALTERSYSTEM SET "_use_adaptive_log_file_sync"=
在ASH里還看到了和log buffer相關的等待，雖然次數不多，但是足以說明我們調整log buffer的大小會優化系統，特別是應用的提交頻率不高，這會對log buffer 的大小有更大的要求，可以調整log buffer的大小到32M或者更大。
文章版權歸作者所有，未經允許請勿轉載,若此文章存在違規行為，您可以聯系管理員刪除。
轉載請注明本文地址：http://specialneedsforspecialkids.com/yun/130004.html
摘要：于是檢查時發現，拼寫錯誤，應為。第個問題，是真真切切錯誤卸載重要軟件包，導致系統崩潰，修復系統的方法自然也就是利用原鏡像在下把該裝的都裝回去，前提是日志存在，萬幸沒有執行過。 首先問題產生的緣由很簡單，是我一同事在安裝oracle一套軟件時，按照要求需要binutils軟件包的32位版本，然而在Oracle Linux已經裝有64位，按理說是可以安裝i686的，我猜應該是32位的版本低...
摘要：問題描述近期項目需要從虛擬機環境遷移到容器環境，其中有一個項目在遷移到容器環境之后的兩天之內出現了次死鎖的問題，部分關鍵日志如下日志還是挺明顯的，線程獲得了鎖，等待獲取而正好相反，從而導致死鎖問題分析以上的錯誤 問題描述 近期項目需要從虛擬機環境遷移到容器環境，其中有一個項目在遷移到容器環境之后的兩天之內出現了2次死鎖(deadlock)的問題，部分關鍵日志如下： Found one ...
摘要：首先先解讀下這個報警內容，原因活躍線程數過多，是監聽的端口號用來獲取虛擬機各項信息，代表著此時的線程數，是設置的報警閾值。 前言 前天，一位21世紀的好好青年正在工位上默念社會主義大法好的時候，釘釘上又報警了（公司項目接入了open-faclon監控，指標不正常會報警給釘釘的機器人），無奈默默流淚揮手告別社會主義大法開始定位線上問題。 報警內容 首先我們先來看下報警信息，為防止泄露公...
閱讀 1346·2023-01-11 13:20
閱讀 1684·2023-01-11 13:20
閱讀 1132·2023-01-11 13:20
閱讀 1858·2023-01-11 13:20
閱讀 4100·2023-01-11 13:20
閱讀 2704·2023-01-11 13:20
閱讀 1385·2023-01-11 13:20
閱讀 3597·2023-01-11 13:20
