28S基础软件入所测试问题

现象描述

28s总体部基础软件入所测试过程中出现大面积机器死机现象。

鼠标键盘无响应，卡死在登陆界面或界面完全不亮，切换字符界面无响应，网络服务不可用，机器完全卡死。

环境描述

系统版本: Kylin-4.0.2-server-sp4-20092117.J1-x86_64

内核版本: Linux Kylin 4.4.131-20200901.kylin.x86-generic

硬件型号及BIOS版本: TSINGHUA TONGFANG COMPUTER Q170-4S/Q170-4S, BIOS E011AP1 02/27/2017

CPU信息: Intel(R) Core(TM) i7-7700 CPU @ 3.60GHz

硬盘信息:1TB SATA HDD

问题分析

首次出现后分析syslog，发现有如下kernel错误日志。

ata 1.00:failed command:WAITE FPDMA QUEUED

ata 1.00 cmd 61/08:28:a0:77:a0/00:00:3a:00:00/40 tags ncp 4096 out

res 40/00:00:00:00/00:00:00:00:00/000 Emask 0x4(timeout)

ata 1.00:failed command:FlUSH CACHE EXIT

ata 1.00:NCQ disable due to excessive errors

??? 初步认为是磁盘开启了NCQ性能优化功能，grub加入参数libata.force=noncq关闭该功能后当天下午机器运行正常，认为找到解决方式，随后将所有机器grub加入该参数进行不断电测试。当天晚上记录工作日志时意识到禁用ncq功能仅对SSD有效，如果该机器为HDD，则ncq不是机器卡死的原因。次日现场发现仍然有大面积机器死机情况，使用lsblk命令确认磁盘可旋转，为HDD。继续排查日志发现出现死机机器syslog中均有类似如下日志。

INFO: rcu_sched detected stalls on CPUs/tasks:

?? 0-...: (1 GPs behind) idle=a2d/1/0 softirq=214590/214590 fqs=59893

?? (detected by 7, t=60007 jiffies, g=178539, c=178538, q=43631)

Task dump for CPU 0:

swapper/0?????? R? running task??????? 0???? 0????? 0 0x00000008

?ffffffff82e03e70 0000000000000018 00ff88045dc15560 000018894b07378d

?ffffffff82e04000 ffffffff82f3e600 ffff88045dc1dd00 ffffffff82eb44c0

?ffffffff82e00000 ffffffff82e03eb8 ffffffff8171a8b7 ffffffff82e03ed0

Call Trace:

?[<ffffffff8171a8b7>] ? cpuidle_enter+0x17/0x20

?[<ffffffff810c9352>] ? call_cpuidle+0x32/0x60

?[<ffffffff8171a899>] ? cpuidle_select+0x19/0x20

?[<ffffffff810c95ac>] ? cpu_startup_entry+0x20c/0x280

?[<ffffffff818508fc>] ? rest_init+0x7c/0x80

?[<ffffffff82f64023>] ? start_kernel+0x48a/0x4ab

?[<ffffffff82f63120>] ? early_idt_handler_array+0x120/0x120

?[<ffffffff82f63339>] ? x86_64_start_reservations+0x2a/0x2c

?[<ffffffff82f63485>] ? x86_64_start_kernel+0x14a/0x16d

INFO: task sd-resolve:607 blocked for more than 120 seconds.

????? Not tainted 4.4.131-20200901.kylin.x86-generic #kylin

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

sd-resolve????? D ffff880442c57a68???? 0?? 607????? 1 0x00000002

?ffff880442c57a68 0000000044106ac0 ffff88044b6feac0 ffff880444106ac0

?ffff880442c58000 ffff880442c57c08 ffff880442c57c00 ffff880444106ac0

?ffff880442c57c00 ffff880442c57a80 ffffffff81858e15 7fffffffffffffff

Call Trace:

?[<ffffffff81858e15>] schedule+0x35/0x80

?[<ffffffff8185c436>] schedule_timeout+0x1b6/0x270

?[<ffffffff811f647b>] ? __slab_free+0xcb/0x2c0

?[<ffffffff81859873>] wait_for_completion+0xb3/0x140

?[<ffffffff810b00e0>] ? wake_up_q+0x70/0x70

?[<ffffffff810e9dfa>] __wait_rcu_gp+0xca/0xf0

?[<ffffffff810ecbdd>] synchronize_sched+0x6d/0x80

?[<ffffffff810ee3c0>] ? call_rcu_bh+0x20/0x20

?[<ffffffff810e9d10>] ? trace_raw_output_rcu_utilization+0x60/0x60

?[<ffffffff81238918>] namespace_unlock+0x88/0xa0

?[<ffffffff8123b144>] drop_collected_mounts+0x54/0x60

?[<ffffffff8123cfd0>] put_mnt_ns+0x20/0x30

?[<ffffffff810a4a9b>] free_nsproxy+0x1b/0x90

?[<ffffffff810a4c1c>] switch_task_namespaces+0x5c/0x70

?[<ffffffff810a4c40>] exit_task_namespaces+0x10/0x20

?[<ffffffff8108620c>] do_exit+0x2dc/0xb00

?[<ffffffff8173ff90>] ? skb_recv_datagram+0x60/0x60

?[<ffffffff81086ab3>] do_group_exit+0x43/0xb0

[<ffffffff81093484>] get_signal+0x294/0x600

?[<ffffffff8123471b>] ? destroy_inode+0x3b/0x60

?[<ffffffff8102e567>] do_signal+0x37/0x6f0

?[<ffffffff81730947>] ? SYSC_recvfrom+0x147/0x160

?[<ffffffff81732030>] ? __sys_sendmsg+0x80/0x90

?[<ffffffff8100320c>] exit_to_usermode_loop+0x8c/0xd0

?[<ffffffff81003cde>] syscall_return_slowpath+0x4e/0x60

?[<ffffffff8185ddb0>] int_ret_from_sys_call+0x25/0x9f

INFO: task systemd:1 blocked for more than 120 seconds.

????? Not tainted 4.4.131-20200901.kylin.x86-generic #kylin

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

systemd???????? D ffff88044b6b3b58???? 0???? 1????? 0 0x00000000

?ffff88044b6b3b58 0000000000000001 ffff8804495e8000 ffff88044b6a8000

?ffff88044b6b4000 ffff88044b6b3cf8 ffff88044b6b3cf0 ffff88044b6a8000

?ffff88044b6b3cf0 ffff88044b6b3b70 ffffffff81858e15 7fffffffffffffff

??? 通过分析发现，是由于文件系统脏缓存往磁盘写时超过120s导致磁盘夯死，经验判断磁盘夯死符合问题描述中的情况，随机sysctl –a|grep dirty查看脏缓存参数。其中vm.dirty_ratio为40，vm.dirty_background_ratio为10，同事确认系统内存为16GB，随即将该系统vm.dirty_ratio参数调整为10，vm.dirty_background_ratio调整为5，同时将hung_task_timeout_secs参数调整为0，即不设置120s时间限制。然后进行测试，运行一天后仍然有少量机器死机，继续查看日志发现有nouveau相关的call trace，但个人认为nouveau不会导致系统夯死，不过为保险起见，仍在部分机器上安装了nvidia闭源显卡驱动作为对照组。后续查看死机机器的last reboot，发现是有第三方厂家的人手动重启过机器导致之前设置的内核参数回到之前的值(sysctl –w设置，重启失效)，为防止第三方厂家需要手动重启机器，于是将内核参数写入sysctl.conf文件，后续继续观察机器是否死机。

修改参数后的机器稳定运行，并未出现死机情况，从而得出结论，是文件系统脏缓存设置过大导致系统夯死，个人认为是机器磁盘性能太差。

Windows机器也会频繁出现蓝屏现象，同时所里在电科云上部署10套虚拟机未出现过死机，也佐证了这一结论。

问题总结

vm.dirty_background_ratio:这个参数指定了当文件系统缓存脏页数量达到系统内存百分之多少时（如5%）就会触发pdflush/flush/kdmflush等后台回写进程运行，将一定缓存的脏页异步地刷入外存；

vm.dirty_ratio:而这个参数则指定了当文件系统缓存脏页数量达到系统内存百分之多少时（如10%），系统不得不开始处理缓存脏页（因为此时脏页数量已经比较多，为了避免数据丢失需要将一定脏页刷入外存）；在此过程中很多应用进程可能会因为系统转而处理文件IO而阻塞。

当系统内存较大，磁盘性能较差，同时vm.dirty_background_ratio和vm.dirty_ratio均设置较大时，会发生hung死现象，注意修改时vm.dirty_background_ratio要小于等于vm.dirty_ratio的值。