dmesg报INFO: task blocked for more than 120 seconds

问题

业务反馈k8s node状态为not ready

排查

查看kubelet日志,定位是和docker交互超时

重启docker后恢复(ps:重启了两遍,重启第一次时卡住很久)

#tail -100f /var/log/kubernetes/kubelet.dc08-prod-maybach-bj01host-96130.root.log.WARNING.20240819-100423.168494
Log file created at: 2024/08/19 10:04:23
Running on machine: dc08-prod-maybach-bj01host-96130
Binary: Built with gc go1.11.4 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
W0819 10:04:23.018723  168494 manager.go:253] Timeout trying to communicate with docker during initialization, will retry
W0819 10:04:43.019185  168494 manager.go:253] Timeout trying to communicate with docker during initialization, will retry
W0819 10:05:23.019388  168494 manager.go:253] Timeout trying to communicate with docker during initialization, will retry
W0819 10:06:03.019575  168494 manager.go:253] Timeout trying to communicate with docker during initialization, will retry

继续排查系统层面问题

dmesg查看系统日志,根据堆栈日志可以发现dockerd IO交互超时

#dmesg -T
[Sun Aug 18 12:52:55 2024] INFO: task dockerd:2157 blocked for more than 120 seconds.
[Sun Aug 18 12:52:55 2024] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sun Aug 18 12:52:55 2024] dockerd         D ffff8f7cec2eb0c0     0  2157      1 0x00000080
[Sun Aug 18 12:52:55 2024] Call Trace:
[Sun Aug 18 12:52:55 2024]  [<ffffffffc06a2a49>] ? __split_and_process_bio+0x2e9/0x520 [dm_mod]
[Sun Aug 18 12:52:55 2024]  [<ffffffffbd167c49>] schedule+0x29/0x70
[Sun Aug 18 12:52:55 2024]  [<ffffffffbd165721>] schedule_timeout+0x221/0x2d0
[Sun Aug 18 12:52:55 2024]  [<ffffffffc06a2fa8>] ? dm_make_request+0x128/0x1a0 [dm_mod]
[Sun Aug 18 12:52:55 2024]  [<ffffffffbcb01052>] ? ktime_get_ts64+0x52/0xf0
[Sun Aug 18 12:52:55 2024]  [<ffffffffbd1672ed>] io_schedule_timeout+0xad/0x130
[Sun Aug 18 12:52:55 2024]  [<ffffffffbd16827d>] wait_for_completion_io+0xfd/0x140
[Sun Aug 18 12:52:55 2024]  [<ffffffffbcad67b0>] ? wake_up_state+0x20/0x20
[Sun Aug 18 12:52:55 2024]  [<ffffffffbcd4d84c>] blkdev_issue_discard+0x2ac/0x2d0
[Sun Aug 18 12:52:55 2024]  [<ffffffffbcd56d35>] blk_ioctl_discard+0xe5/0x130
[Sun Aug 18 12:52:55 2024]  [<ffffffffbcd57882>] blkdev_ioctl+0x632/0xa20

监控发现该机器在开机时即memory cache很高,且有大量IO

反馈业务排查相关业务服务

问题原因

默认情况下， Linux会最多使用40%的可用内存作为文件系统缓存。当超过这个阈值后，文件系统会把将缓存中的内存全部写入磁盘， 导致后续的IO请求都是同步的。将缓存写入磁盘时，有一个默认120秒的超时时间。 出现上面的问题的原因是IO子系统的处理速度不够快，不能在120秒将缓存中的数据全部写入磁盘。IO系统响应缓慢，导致越来越多的请求堆积，最终系统内存全部被占用，导致系统失去响应。

这通常发生在内存很大的系统上。系统内存大，则缓冲区大，同步数据所需要的时间就越长，超时的概率就越大。

解决办法

i.调整脏数据回写磁盘参数

1.vm.dirty_background_ratio

内存可以填充脏数据的百分比。这些脏数据稍后会写入磁盘，pdflush/flush/kdmflush这些后台进程会稍后清理脏数据
 

2.vm.dirty_ratio

脏数据填充的绝对最大系统内存量，当系统到达此点时，必须将所有脏数据提交到磁盘，同时所有新的I/O块都会被阻塞，直到脏数据被写入磁盘。这通常是长I/O卡顿的原因，但这也是保证内存中不会存在过量脏数据的保护机制。
 

3.vm.dirty_background_bytes 和 vm.dirty_bytes

另一种指定这些参数的方法。如果设置 xxx_bytes版本，则 xxx_ratio版本将变为0，反之亦然

4.vm.dirty_expire_centisecs

指定脏数据能存活的时间。在这里它的值是30秒。当 pdflush/flush/kdmflush 在运行的时候，他们会检查是否有数据超过这个时限，如果有则会把它异步地写到磁盘中

5.vm.dirty_writeback_centisecs 

指定多长时间 pdflush/flush/kdmflush 这些进程会唤醒一次，然后检查是否有缓存需要清理

ii.如何度量设置的是否合理

观察nr_writeback变化,通常接近0,如果长期维持高点,则证明设置的太小

#grep -A 1 dirty /proc/vmstat
nr_dirty 64620 #当前在内存中等待写入到磁盘的脏页数量
nr_writeback 0 #系统全局的正在回写的脏页数目

iii.调优思路

1.关键数据调小参数,更积极的回写磁盘

2.数据不重要调大参数,更充分利用缓存

3.vm.dirty_background_ratio调较小,vm.dirty_ratio调比较大:系统后台进程在脏数据达到5%时就开始异步清理，但在80%之前系统不会强制同步写磁盘

参考 

Linux磁盘I/O（二）：使用vm.dirty_ratio和vm.dirty_background_ratio优化磁盘性能-CSDN博客

Kernel Tuning - NICPB HEP Group