iT邦幫忙

0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message

有一台虛擬機器系統是
Red Hat Enterprise Linux Server release 6.5
2.6.32-431.el6.x86_64
上面有安裝tomcat,mysql,zabbix

最近每天都會當機,可以ssh過去但輸入密碼後就停住,從VMware vSphere Client打開主機會看到錯誤訊息如下
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message
INFO: task xxxx:xxxx blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message
INFO: task xxxx:xxxx blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message
INFO: task xxxx:xxxx blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message
INFO: task xxxx:xxxx blocked for more than 120 seconds.

google後大家的解法都是修改
vm.dirty_ratio=10
vm.dirty_background_ratio=5

但我修改後還是一樣,後來發現是固定每天半夜一點的時候會當機,
查看/var/log/cron 發現都是在一點後時間突然變成錯誤的未來時間?
Jul 17 00:40:01 localhost CROND[25556]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jul 17 00:50:01 localhost CROND[26726]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jul 17 01:00:01 localhost CROND[27940]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jul 17 01:01:01 localhost CROND[28064]: (root) CMD (run-parts /etc/cron.hourly)
Jul 17 01:01:01 localhost CROND[28065]: (root) CMD (run-parts /etc/cron.hourly)
Jul 17 16:46:12 localhost crond[2796]: (CRON) STARTUP (1.4.4)
Jul 17 16:46:12 localhost crond[2796]: (CRON) INFO (RANDOM_DELAY will be scaled with factor 94% if used.)
Jul 17 16:46:12 localhost crond[2796]: (CRON) INFO (running with inotify support)

/var/log/message 的log
Jul 17 16:46:03 localhost kernel: imklog 5.8.10, log source = /proc/kmsg started.
Jul 17 16:46:03 localhost rsyslogd: [origin software="rsyslogd" swVersion="5.8.10" x-pid="1491" x-info="http://www.rsyslog.com"] start
Jul 17 16:46:03 localhost kernel: Initializing cgroup subsys cpuset
Jul 17 16:46:03 localhost kernel: Initializing cgroup subsys cpu
Jul 17 16:46:03 localhost kernel: Linux version 2.6.32-431.el6.x86_64 (mockbuild@x86-023.build.eng.bos.redhat.com) (gcc version 4.4.7 20120313 (Red Hat 4.4.7-4) (GCC) ) #1 SMP Sun Nov 10 22:19:54 EST 2013
Jul 17 16:46:03 localhost kernel: Command line: ro root=/dev/mapper/vg_airtd01-lv_root rd_LVM_LV=vg_airtd01/lv_swap rd_LVM_LV=vg_airtd01/lv_root LANG=zh_TW.UTF-8 rd_NO_MD crashkernel=auto rd_NO_LUKS KEYBOARDTYPE=pc KEYTABLE=us rd_NO_DM rhgb quiet
Jul 17 16:46:03 localhost kernel: KERNEL supported cpus:
Jul 17 16:46:03 localhost kernel: Intel GenuineIntel
Jul 17 16:46:03 localhost kernel: AMD AuthenticAMD
Jul 17 16:46:03 localhost kernel: Centaur CentaurHauls
Jul 17 16:46:03 localhost kernel: Disabled fast string operations
Jul 17 16:46:03 localhost kernel: BIOS-provided physical RAM map:
Jul 17 16:46:03 localhost kernel: BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000000dc000 - 0000000000100000 (reserved)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 0000000000100000 - 00000000bfef0000 (usable)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000bfef0000 - 00000000bfeff000 (ACPI data)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000bfeff000 - 00000000bff00000 (ACPI NVS)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000bff00000 - 00000000c0000000 (usable)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000f0000000 - 00000000f8000000 (reserved)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000fec00000 - 00000000fec10000 (reserved)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 00000000fffe0000 - 0000000100000000 (reserved)
Jul 17 16:46:03 localhost kernel: BIOS-e820: 0000000100000000 - 0000000240000000 (usable)
Jul 17 16:46:03 localhost kernel: DMI present.
Jul 17 16:46:03 localhost kernel: SMBIOS version 2.4 @ 0xF6A70
Jul 17 16:46:03 localhost kernel: Phoenix BIOS detected: BIOS may corrupt low RAM, working around it.
Jul 17 16:46:03 localhost kernel: Hypervisor detected: VMware
Jul 17 16:46:03 localhost kernel: last_pfn = 0x240000 max_arch_pfn = 0x400000000
Jul 17 16:46:03 localhost kernel: x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
Jul 17 16:46:03 localhost kernel: total RAM covered: 8192M
Jul 17 16:46:03 localhost kernel: Found optimal setting for mtrr clean up
Jul 17 16:46:03 localhost kernel: gran_size: 64K chunk_size: 64K num_reg: 4 lose cover RAM: 0G
Jul 17 16:46:03 localhost kernel: last_pfn = 0xc0000 max_arch_pfn = 0x400000000
Jul 17 16:46:03 localhost kernel: init_memory_mapping: 0000000000000000-00000000c0000000
Jul 17 16:46:03 localhost kernel: init_memory_mapping: 0000000100000000-0000000240000000
Jul 17 16:46:03 localhost kernel: RAMDISK: 36f82000 - 37fef4e2
Jul 17 16:46:03 localhost kernel: ACPI: RSDP 00000000000f6ac0 00024 (v02 PTLTD )
Jul 17 16:46:03 localhost kernel: ACPI: XSDT 00000000bfef109b 0005C (v01 INTEL 440BX 06040000 VMW 01324272)
Jul 17 16:46:03 localhost kernel: ACPI: FACP 00000000bfefee73 000F4 (v04 INTEL 440BX 06040000 PTL 000F4240)
Jul 17 16:46:03 localhost kernel: ACPI: DSDT 00000000bfef1349 0DB2A (v01 PTLTD Custom 06040000 MSFT 03000001)
Jul 17 16:46:03 localhost kernel: ACPI: FACS 00000000bfefffc0 00040
Jul 17 16:46:03 localhost kernel: ACPI: BOOT 00000000bfef1321 00028 (v01 PTLTD $SBFTBL$ 06040000 LTP 00000001)
Jul 17 16:46:03 localhost kernel: ACPI: APIC 00000000bfef12c3 0005E (v01 PTLTD ? APIC 06040000 LTP 00000000)
Jul 17 16:46:03 localhost kernel: ACPI: MCFG 00000000bfef1287 0003C (v01 PTLTD $PCITBL$ 06040000 LTP 00000001)

zivtor iT邦新手 4 級 ‧ 2018-07-25 10:50:35 檢舉
Server時間不正確?
都是在半夜一點時候突然變成未來時間,後來有設定一個排程每小時校正一次還是一樣.
圖片
  直播研討會
圖片
{{ item.channelVendor }} {{ item.webinarstarted }} |
{{ formatDate(item.duration) }}
直播中

2 個回答

0
bizpro
iT邦大師 1 級 ‧ 2018-07-25 15:19:26

兩個不同的"錯誤"來自同一個原因: 系統負載過重.

  1. 訊息"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message 是建議你要將hung task的警告關閉, 起因是因為IO的問題, 例如硬碟存取太慢, 因此, 在改變dirty_ratio時, 如訊息建議, 也要關閉hung_task_timeout_secs, 眼不見為淨, 我的建議是:
    kernel.hung_task_panic = 0
    kernel.hung_task_timeout_secs = 0
    vm.dirty_ratio=60
    vm.dirty_background_ratio=5

但這是治標非治本. IO的問題還在, 系統負擔過重. 您設定10%的dirty_ratio, 會降低系統性能. 你有8GB的RAM, Kernel在到達每800MB的dirty pages時要停止所有應用程式的IO來將dirty pages寫入磁碟? 建議這個值要提高, 例如60, 聽聞在繁忙的系統和VMWARE中, 有人設定100%. 而vm.dirty_background_ratio可以
留在5%或10%. 讓kernel慢慢的將dirty pages寫入磁碟.
還有一些dirty pages的設定, 這篇文章可以參考:
https://lonesysadmin.net/2013/12/22/better-linux-disk-caching-performance-vm-dirty_ratio/
文章中vm.dirty_background_ratio的設定不適合zabbix.

  1. 第二個問題我似乎有見過, 好像是ntpd的問題? 或因系統負載過重? 機房過熱? VMWare過載? 或是在啟動rsyslog後出了問題?
    Jul 17 16:46:03 localhost rsyslogd: [origin software="rsyslogd" swVersion="5.8.10" x-pid="1491" x-info="http://www.rsyslog.com"] start

這兩個應該是獨立的報錯, 根源應該都是系統負載的問題, 只能就有限的訊息猜測.

感謝回答,

1.我再嘗試調整參數試試看,但這台其實附載沒有很重,而且之前有加大記憶體過,但狀況還是一樣,I/O出問題有可能是硬體方面嗎?(ex:硬碟快掛掉?)

2.在加上每小時同步時間後,我有把ntpd關掉,所以應該不是ntpd問題,在半夜一點時也沒有去啟動rsyslog,
在此機房還有其他台機器都沒這問題,可以排除是硬體方面的問題 嗎?

還是可以提供哪些log更能進一步分析呢?謝謝.

感謝大師,終於找到問題,在VM主機上看到
建立快照時發生錯誤: msg.snapshot.error-QUIESCINGERROR。
儲存快照時發生錯誤: msg.snapshot.error-QUIESCINGERROR。
是廠商設定的備份發生錯誤

1
Ray
iT邦大神 1 級 ‧ 2018-07-25 16:42:19

系統負載問題 +1...

但我遇到的狀況, 不是 VM 本身的負載, 而是外層 Host 的負載. 該 Host 因採用 Hyperconverge 架構, 在某些狀況下, 某個 Process 將 CPU Thread 全部搶走, 導致 VM 幾乎沒有 Thread 可以用, 此時 VM 也會出現上面的錯誤....

從 VM 去查修, log 內看不到高負載的跡象, 但若從 Host 去查, 就會發現同時段內, CPU 或 I/O 的負載高到異常....

感謝ray大回答,

但我這台host上其他主機沒有這狀況,所以可以排除此問題嗎?

Ray iT邦大神 1 級 ‧ 2018-07-26 09:40:03 檢舉

No, 其他 VM 沒有, 不代表 Host 正常.

我先前的狀況就是:
Host 雖然高負載, 但是所有 VM 都可以跑, 不過這台 host 上面的 10 個 VM, 就是其中一兩個會在固定的時間點, 發生以上的訊息, 其他的不會. 而且會出問題的就是那一兩個, 也不會跳來跳去...

當初也是陷入這個迷思, 以為這兩個 VM 有問題, 查了好幾個月, 後來才慢慢了解到, 問題是由 Host 造成的, 不是 VM 本身. 所以最後是去調整 Host, VM 就不會再出問題了.

所以不能用: 其他 VM 沒有, 來判定這是 個別 VM 的問題.

感謝Ray大,終於找到問題,在VM主機上看到
建立快照時發生錯誤: msg.snapshot.error-QUIESCINGERROR。
儲存快照時發生錯誤: msg.snapshot.error-QUIESCINGERROR。
是廠商設定的備份發生錯誤

我要發表回答

立即登入回答