菜单开关

周梦康 发表于 2017-10-17 1071 次浏览

免费领取阿里云优惠券 我的直播 - 《PHP 进阶之路》

昨天22:44 负载突然很高,服务器就部署了一个 java 程序,java 进程没怎么占用 cpu 和 内存,今天查看/var/log/messages 记录下:

Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel: INFO: task AliYunDun:1869 blocked for more than 120 seconds.
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel: AliYunDun     D ffff810001015120     0  1869      1          1870  1854 (NOTLB)
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  ffff810237ea9c98 0000000000000086 ffffffffffffffff ffffffff00000000
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  0000000100000000 000000000000000a ffff810238ae3820 ffff810107f1f080
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  0007cc9e11509465 000000000013428a ffff810238ae3a08 0000000238ae3820
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel: Call Trace:
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8012e9a3>] inode_has_perm+0x56/0x63
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8006467c>] __down_read+0x7a/0x92
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8004db17>] proc_exe_link+0x58/0xdd
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8010a2ad>] proc_pid_follow_link+0x33/0x43
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8000a465>] __link_path_walk+0xbbc/0xfd1
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8000eb88>] link_path_walk+0x45/0xb8
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8000ce9c>] do_path_lookup+0x294/0x310
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8001299a>] getname+0x15b/0x1c2
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff80023b45>] __user_walk_fd+0x37/0x4c
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff80028acf>] vfs_stat_fd+0x1b/0x4a
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff80023875>] sys_newstat+0x19/0x31
Oct 16 22:43:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8005d116>] system_call+0x7e/0x83
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel: INFO: task crond:14288 blocked for more than 120 seconds.
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel: crond         D ffff8102278c77a0     0 14288   1955         14289       (NOTLB)
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  ffff8101f0efbe58 0000000000000086 0c15a4ae3e296e0c 40a55b9499d22e8d
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  c5dd7ad60792f249 0000000000000006 ffff8102278c77a0 ffff810238cd0080
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  0007cc9df6f85ee5 0000000000168e8d ffff8102278c7988 00000002801abaee
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel: Call Trace:
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff80063161>] wait_for_completion+0x79/0xa2
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8008e857>] default_wake_function+0x0/0xe
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8012778a>] __key_instantiate_and_link+0x8f/0xc5
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff800a11c5>] synchronize_rcu+0x30/0x36
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff800a0d01>] wakeme_after_rcu+0x0/0x9
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8012a1aa>] install_session_keyring+0xc0/0xd3
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff80003838>] level3_kernel_pgt+0x838/0x1000
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8012a6d8>] join_session_keyring+0x25/0xcb
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff80129b95>] keyctl_join_session_keyring+0x2d/0x40
Oct 16 22:41:31 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8005d116>] system_call+0x7e/0x83
Oct 16 22:43:24 iZbp19sg81jq1ic4pf9lrsZ kernel: BUG: soft lockup - CPU#3 stuck for 60s! [telegraf:4248]
Oct 16 22:43:24 iZbp19sg81jq1ic4pf9lrsZ kernel: CPU 3:
Oct 16 22:43:24 iZbp19sg81jq1ic4pf9lrsZ kernel: Modules linked in: dm_mirror dm_multipath scsi_dh video backlight sbs power_meter hwmon i2c_ec dell_wmi wmi button battery asus_acpi acpi_memhotplug ac parport_pc lp parport floppy acpiphp virtio_cod(U) joydev i2c_piix4 virtio_net(U) ide_cd cdrom tpm_tis i2c_core tpm serio_raw pcspkr tpm_bios dm_raid45 dm_message dm_region_hash dm_log dm_mod dm_mem_cache ata_piix libata sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd virtio_console(U) hvc_console(U) virtio_pci(U) virtio_blk(U) virtio(U) virtio_ring(U) xen_platform_pci(U)
Oct 16 22:43:24 iZbp19sg81jq1ic4pf9lrsZ kernel: Pid: 4248, comm: telegraf Tainted: G     ---- 2.6.18-274.el5 #1
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: RIP: 0010:[<ffffffff800232c5>]  [<ffffffff800232c5>] flush_tlb_others+0x8d/0xbd
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: RSP: 0018:ffff810218a51e18  EFLAGS: 00000246
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: RAX: 0000000000000000 RBX: ffff81000101c580 RCX: 00000000000000ff
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: RDX: ffff810218a51e18 RSI: 0000000000000003 RDI: ffff81000101c580
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: RBP: 0000000000000246 R08: 0000000000000002 R09: 000000000000003e
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: R10: ffff810218a51db8 R11: 0000000000000246 R12: ffff81000101c580
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: R13: ffff810218a51de0 R14: ffffffff80563cd0 R15: ffffffff80563cd0
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: FS:  00002b2f9f0f6940(0000) GS:ffff810107f1e6c0(0000) knlGS:0000000000000000
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: CR2: 00002aef37ab75f0 CR3: 0000000219812000 CR4: 00000000000006a0
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel:
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel: Call Trace:
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff800232d2>] flush_tlb_others+0x9a/0xbd
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff80077aa8>] flush_tlb_mm+0xcc/0xd7
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff800cfd9e>] zap_page_range+0xcb/0xf5
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff800cf999>] sys_madvise+0x3a7/0x4c1
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff800a6667>] sys_futex+0x10a/0x12b
Oct 16 22:43:25 iZbp19sg81jq1ic4pf9lrsZ kernel:  [<ffffffff8005d116>] system_call+0x7e/0x83

Soft lockup名称解释:所谓,soft lockup就是说,这个bug没有让系统彻底死机,但是若干个进程(或者kernel thread)被锁死在了某个状态(一般在内核区域),很多情况下这个是由于内核锁的使用的问题。

参考一

http://blog.ronnyegner-consulting.de/2011/10/13/info-task-blocked-for-more-than-120-seconds/comment-page-1/

This is a know bug. By default Linux uses up to 40% of the available memory for file system caching. After this mark has been reached the file system flushes all outstanding data to disk causing all following IOs going synchronous. For flushing out this data to disk this there is a time limit of 120 seconds by default. In the case here the IO subsystem is not fast enough to flush the data withing 120 seconds. This especially happens on systems with a lof of memory.

The problem is solved in later kernels and there is not “fix” from Oracle. I fixed this by lowering the mark for flushing the cache from 40% to 10% by setting “vm.dirty_ratio=10” in /etc/sysctl.conf. This setting does not influence overall database performance since you hopefully use Direct IO and bypass the file system cache completely.

照这篇博主的意思,应该是这台机器内存大,却没跑什么服务。空闲内存越大,触发这个问题的可能性就更大。因为能缓存的数据更多,所以当这部分被分配用来缓存脏数据的内存满了的时候,则开始把数据从内存刷到硬盘,默认的 120s 无法完成导致出现了负载过高。

参考二

https://feichashao.com/dirty_ratio_and_dirty_background_ratio/

sysctl -a |grep dirty
vm.dirty_background_bytes = 0
vm.dirty_bytes = 0
vm.dirty_expire_centisecs = 2999
vm.dirty_writeback_centisecs = 499
vm.dirty_ratio = 40
vm.dirty_background_ratio = 10

vm.dirty_background_ratio 是内存可以填充“脏数据”的百分比。这些“脏数据”在稍后是会写入磁盘的,pdflush/flush/kdmflush这些后台进程会稍后清理脏数据。举一个例子,我有32G内存,那么有3.2G的内存可以待着内存里,超过3.2G的话就会有后来进程来清理它。

vm.dirty_ratio 是绝对的脏数据限制,内存里的脏数据百分比不能超过这个值。如果脏数据超过这个数量,新的IO请求将会被阻挡,直到脏数据被写进磁盘。这是造成IO卡顿的重要原因,但这也是保证内存中不会存在过量脏数据的保护机制。

修改参数

临时修改方式1 echo

# sysctl vim.dirty_ratio
40
# echo 10 > dirty_ratio
# sysctl vim.dirty_ratio
vm.dirty_ratio = 10

临时修改方式2 sysctl

sysctl vm.dirty_ratio=10

永久修改:在/etc/sysctl.conf文件里添加如下参数

echo 'dirty_ratio=10' >> /etc/sysctl.conf

嗨,老铁,欢迎来到我的博客!

如果觉得我的内容还不错的话,可以关注下我在 segmentfault.com 上的直播。我主要从事 PHP 和 Java 方面的开发,《深入 PHP 内核》作者之一。

[视频直播] PHP 进阶之路 - 亿级 pv 网站架构的技术细节与套路 直播中我将毫无保留的分享我这六年的全部工作经验和踩坑的故事,以及会穿插着一些面试中的 考点难点加分点

评论列表

回复 ideal 2017-10-17 12:01:38
感觉可以设置vm.dirty_ratio。http://blog.ronnyegner-consulting.de/2011/10/13/info-task-blocked-for-more-than-120-seconds/comment-page-1/
回复 梦康 2017-10-17 13:30:26
回复ideal: 既然你已经设置了,那我就不动啦,其他几台服务器却没出现这个问题,照这篇博主的意思,应该是这台机器内存大,却没跑什么服务。
空闲内存太多,触发这个问题的可能性更大,缓存的数据更多,所以从内存刷到硬盘120s 无法完成估计。