//2019/7/31 18:41:14掐指一算應該resore完了呀,是不是天熱想罷工?不過已經差不多30個小時了無意間一查 tail -500f /var/log/messages 發現有些“more than 120 seconds|hung_task_timeout_secs”,還有寫ker ...
//2019/7/31 18:41:14
掐指一算應該resore完了呀,是不是天熱想罷工?不過已經差不多30個小時了
無意間一查 tail -500f /var/log/messages 發現有些“more than 120 seconds|hung_task_timeout_secs”,還有寫kernel亂七八糟的,有點蒙圈。。。先分析再幹活
咋一看2個帖子分析的非常有道理,那就乾吧,粗體是要執行查看的
問題原因:
預設情況下,Linux會最多使用40%的可用記憶體作為文件系統緩存。當超過這個閾值後,文件系統會把將緩存中的記憶體全部寫入磁碟,導致後續的IO請求都是同步的。
將緩存寫入磁碟時,有一個預設120秒的超時時間。出現上面的問題的原因是IO子系統的處理速度不夠快,不能在120秒將緩存中的數據全部寫入磁碟。
IO系統響應緩慢,導致越來越多的請求堆積,最終系統記憶體全部被占用,導致系統失去響應。
系統預設
[root@dinpaydg_cc ~]# sysctl -a | grep 'vm.dirty'
vm.dirty_background_ratio = 10
vm.dirty_background_bytes = 0
vm.dirty_ratio = 20
vm.dirty_bytes = 0
vm.dirty_writeback_centisecs = 500
vm.dirty_expire_centisecs = 3000
[root@dinpaydg_cc ~]#
解決方法:
根據應用程式情況,對vm.dirty_ratio,vm.dirty_background_ratio兩個參數進行調優設置
root執行下看看
sysctl -w vm.dirty_ratio=10
sysctl -w vm.dirty_background_ratio=5
sysctl -p
[root@dinpaydg_cc ~]# sysctl -a | grep 'vm.dirty'
vm.dirty_background_ratio = 5 #調小一倍
vm.dirty_background_bytes = 0
vm.dirty_ratio = 10 #調小一倍
vm.dirty_bytes = 0
vm.dirty_writeback_centisecs = 500
vm.dirty_expire_centisecs = 3000
[root@dinpaydg_cc ~]#
當然我只用了上免得方法,生產暫時沒法重啟。
如果系統永久生效,修改/etc/sysctl.conf文件。加入如下兩行:
#vi /etc/sysctl.conf
vm.dirty_background_ratio = 5
vm.dirty_ratio = 10
重啟系統生效。
系統日誌分析
grep 'Jul 31' messages | grep -E 'more than 120 seconds|hung_task_timeout_secs'
--發現機器restore了30個小時
[root@dinpaydg_cc log]# grep 'Jul 31' messages | grep -E 'more than 120 seconds|hung_task_timeout_secs'
Jul 31 15:11:57 dinpaydg_cc kernel: INFO: task oracle:4146 blocked for more than 120 seconds.
Jul 31 15:11:57 dinpaydg_cc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 31 16:17:57 dinpaydg_cc kernel: INFO: task oracle:4147 blocked for more than 120 seconds.
Jul 31 16:17:57 dinpaydg_cc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 31 16:23:57 dinpaydg_cc kernel: INFO: task oracle:4144 blocked for more than 120 seconds.
Jul 31 16:23:57 dinpaydg_cc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 31 16:23:57 dinpaydg_cc kernel: INFO: task oracle:4146 blocked for more than 120 seconds.
Jul 31 16:23:57 dinpaydg_cc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 31 16:25:57 dinpaydg_cc kernel: INFO: task oracle:4144 blocked for more than 120 seconds.
Jul 31 16:25:57 dinpaydg_cc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 31 17:15:57 dinpaydg_cc kernel: INFO: task oracle:4147 blocked for more than 120 seconds.
Jul 31 17:15:57 dinpaydg_cc kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[root@dinpaydg_cc log]#
資源使用分析
sar -r 查看發現這一段時間的記憶體使用情況,已使用記憶體的百分數(%memused)非常高,已使用交換空間的百分數(%swapused)比例也在個位數到40%直接,伺服器在10:31重啟,10:00 到10:30之間的數據沒有,不清楚什麼原因導致。從這些數據也可以看出記憶體資源非常緊張。
另外也用sar -u查看了CPU,CPU使用率不高。基本正常,當時忘記查看I/O和傳送速率的統計信息(現在去查看,已經看不到昨天的數據了),另外在message日誌裡面看到有"ata2.00: status: { DRDY ERR }", "ata2.00: qc timeout(cmd 0xa0)"; 之類的錯誤信息
【記憶體有瓶頸】一直99%以上
[root@dinpaydg_cc log]# sar -r
Linux 2.6.32-573.12.1.el6.x86_64 (dinpaydg_cc) 07/31/2019 _x86_64_ (16 CPU)
10:50:02 AM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit
11:00:01 AM 355288 65617760 99.46 150040 63419688 2689968 3.27
11:10:01 AM 354528 65618520 99.46 150088 63423884 2690020 3.27
11:20:01 AM 367640 65605408 99.44 150136 63412012 2689880 3.27
11:30:01 AM 362712 65610336 99.45 150088 63419560 2689976 3.27
11:40:01 AM 368524 65604524 99.44 150084 63411952 2690108 3.27
11:50:01 AM 347320 65625728 99.47 149712 63434068 2689940 3.27
12:00:01 PM 351676 65621372 99.47 149792 63426180 2689956 3.27
12:10:01 PM 356232 65616816 99.46 149924 63415948 2689944 3.27
12:20:01 PM 355240 65617808 99.46 150068 63416388 2689804 3.27
12:30:01 PM 368880 65604168 99.44 150048 63401996 2690048 3.27
12:40:01 PM 359596 65613452 99.45 150104 63413688 2690104 3.27
12:50:01 PM 350048 65623000 99.47 150172 63427012 2689940 3.27
01:00:01 PM 349784 65623264 99.47 150080 63417960 2690072 3.27
01:10:01 PM 362572 65610476 99.45 149996 63401240 2690092 3.27
01:20:01 PM 351272 65621776 99.47 150068 63414564 2689928 3.27
01:30:01 PM 350668 65622380 99.47 150272 63422528 2690012 3.27
01:40:01 PM 352900 65620148 99.47 150252 63412152 2690120 3.27
01:50:01 PM 366284 65606764 99.44 150116 63384588 2690016 3.27
02:00:01 PM 363068 65609980 99.45 150276 63397584 2690048 3.27
02:10:01 PM 368648 65604400 99.44 149992 63376084 2690120 3.27
02:20:01 PM 369268 65603780 99.44 149928 63373840 2690008 3.27
02:30:01 PM 362060 65610988 99.45 149820 63376720 2690012 3.27
02:40:01 PM 367160 65605888 99.44 149712 63383124 2690120 3.27
02:50:01 PM 360448 65612600 99.45 149276 63370696 2689952 3.27
03:00:01 PM 358000 65615048 99.46 149408 63372396 2690012 3.27
03:10:01 PM 359588 65613460 99.45 147528 63255224 2689944 3.27
03:20:01 PM 351660 65621388 99.47 147348 63241720 2690072 3.27
03:30:01 PM 355504 65617544 99.46 146716 63225352 2689952 3.27
03:40:01 PM 369560 65603488 99.44 147140 63211492 2682996 3.26
03:50:02 PM 365856 65607192 99.45 147276 63221384 2682936 3.26
04:00:01 PM 350200 65622848 99.47 147108 63235804 2685272 3.26
04:10:02 PM 359236 65613812 99.46 147284 63215036 2682936 3.26
04:20:01 PM 348992 65624056 99.47 147220 63184804 2683064 3.26
04:30:01 PM 348712 65624336 99.47 147492 63182200 2682868 3.26
04:40:01 PM 363872 65609176 99.45 147200 63189104 2683104 3.26
04:50:01 PM 355796 65617252 99.46 147840 63249792 2682868 3.26
05:00:01 PM 351828 65621220 99.47 147484 63243968 2682996 3.26
05:10:01 PM 368956 65604092 99.44 147996 63236072 2682984 3.26
05:20:01 PM 364492 65608556 99.45 147844 63237672 2683060 3.26
05:30:01 PM 350464 65622584 99.47 147632 63239828 2682912 3.26
05:40:01 PM 360896 65612152 99.45 148100 63253944 2683084 3.26
05:50:01 PM 366972 65606076 99.44 149312 63276300 2683028 3.26
06:00:01 PM 361516 65611532 99.45 150500 63310344 2682912 3.26
06:10:01 PM 355424 65617624 99.46 150628 63336856 2682980 3.26
06:20:01 PM 348836 65624212 99.47 150708 63356368 2682984 3.26
06:30:01 PM 351704 65621344 99.47 150700 63358596 2682912 3.26
06:40:01 PM 357428 65615620 99.46 151420 63355612 2687860 3.26
06:50:01 PM 350732 65622316 99.47 151608 63366176 2687856 3.26
Average: 358674 65614374 99.46 143847 63371864 2688699 3.26
[root@dinpaydg_cc log]#
參考帖子,感謝
Linux伺服器宕機案例第二則
https://www.cnblogs.com/kerrycode/p/5653586.html
故障報錯之/proc/sys/kernel/hung_task_timeout_secs
https://blog.csdn.net/weixin_43279032/article/details/87718804