INFO: task ftest07:1247 blocked for more than 120 seconds 深入探索

这段时间需要对操作系统做一次ltp测试，主要是跑一下压力测试探探究竟；测试过程中出现了如下信息:

INFO: task ftest07:1247 blocked for more than 120 seconds."echo  0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.INFO: task ftest07:1248 blocked for more than 120 seconds."echo  0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.INFO: task ftest07:1249 blocked for more than 120 seconds."echo  0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.INFO: task ftest07:1250 blocked for more than 120 seconds."echo  0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

在网上找了一下相关资料，究其原因:
1.首先来看一下kernel 的hung_task（任务挂起）检测机制，我们知道进程一般情况下（实际还有几种另外三种）有三大状
态（R/S/D）分别为运行-TASK_RUNNING（run）、睡眠--可中断TASK_INTERRUPTIBLE（sleep）、睡眠--但是不可中断TASK_UNINTERRUPTIBLE（Deny）.
（1）运行：当一个进程在处理机上运行时，则称该进程处于运行状态。处于此状态的进程的数目小于等于处理器的数目，对于单处理机系统，处于
运行状态的进程只有一个。在没有其他进程可以执行时（如所有进程都在阻塞状态），通常会自动执行系统的空闲进程。
（2）就绪：当一个进程获得了除处理机以外的一切所需资源，一旦得到处理机即可运行，则称此进程处于就绪状态。就绪进程可以按多个优先级来划分队列。
例如，当一个进程由于时间片用完而进入就绪状态时，排入低优先级队列；当进程由I／O操作完成而进入就绪状态时，排入高优先级队列。
（3）阻塞：也称为等待或睡眠状态，一个进程正在等待某一事件发生（例如请求I/O而等待I/O完成等）而暂时停止运行，这时即使把处理机分
配给进程也无法运行，故称该进程处于阻塞状态。
所以按照上面的理论描述，我们分析一下：
我们知道进程等待IO时，经常处于D状态，即TASK_UNINTERRUPTIBLE状态，处于这种状态的进程不
处理信号，所以kill不掉，如果进程长期处于D状态，那么肯定不正常，原因可能有二：
1）IO路径上的硬件出问题了，比如硬盘坏了(只有少数情况会导致长期D，通常会返回错误)；
2）内核自己出问题了。
这种问题不好定位，而且一旦出现就通常不可恢复，kill不掉，通常只能重启恢复了。
内核针对这种开发了一种hung_task的检测机制，基本原理是：定时检测系统中处于D状态的
进程，如果其处于D状态的时间超过了指定时间(默认120s，可以配置)，则打印相关堆栈信
息，也可以通过proc参数配置使其直接panic。
2、hung task相关配置

1）设置timeout时间：echo num > /proc/sys/kernel/hung_task_timeout_secsxx单位为s。2）设置hung task后是否触发panic，设置为1会触发panicecho 1 > /proc/sys/kernel/hung_task_panic 

网络上有几个出现此问题的解释，我也来学习一下：


简短描述:本指南显示如何修复hung_task_timeout_secs和阻塞问题在Linux中超过120秒。
panic的发生可能由于硬件故障或软件bug。多数情况下操作系统可以在出现某个错误时继续运行。
然而，该系统可能是处在一个不稳定的状态下,冒着安全问题和数据损坏、操作系统停止,以防止进
一步损害和错误的诊断,在通常情况下会重新启动。从源代码重新编译一个内核二进制镜像后,内核
在启动期间发生的内核panic是一个常见的问题，如果没有正确配置、编译和安装的话。硬件或RAM
故障也可能是致命的内核错误来源,由于设备驱动程序与操作系统不兼容或丢失。如果无法找
根文件系统内核也可能进入panic()。在内核空间初始化的最后阶段,发生panic通常由于初始化失败
造成,这样也会导致系统将无法使用。


背景：
服务器响应突然变得非常迟钝。
收集日志信息来看了一下cpu 和内存的使用率不高 
硬重启之后突然发现不能通过VNC 和 SSH访问了。
VNC链接显示一个错误信息：

------------------------------------------------------------------------------------INFO: task jbd2/vda3-8:250 blocked for more than 120 seconds. Not tainted 2.6.32-431.11.2.el6.x86_64 #1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. ------------------------------------------------------------------------------------

 
 一步步来看：
 使用sar来看看cpu 和 内存的使用率：
 
  1）查看内存使用率： sar -r
 

 someuser@servercore [/var/log]# sar -r15:00:01 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit15:20:01 476604 1396772 74.56 110140 707116 1201652 30.6415:30:02 526240 1347136 71.91 110412 710536 1165148 29.7115:55:53 LINUX RESTART16:00:01 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit16:10:01 517168 1356208 72.39 136040 588964 1196724 30.5216:20:01 510580 1362796 72.75 137488 596560 1191664 30.39

以上信息显示，我们还有充足的内存可以；

  2）查看cpu使用率： sar -u

someuser@servercore [/var/log]# sar -u15:00:01 CPU %user %nice %system %iowait %steal %idle15:20:01 all 6.01 0.04 1.74 1.59 0.14 90.4815:30:02 all 4.97 0.04 1.54 7.87 0.15 85.44Average: all 7.20 0.06 2.19 2.69 0.26 87.6015:55:53 LINUX RESTART16:00:01 CPU %user %nice %system %iowait %steal %idle16:10:01 all 9.13 0.04 2.78 6.98 0.31 80.7616:20:01 all 4.21 0.04 1.39 3.49 0.15 90.73

又一次被打败了，发现cpu的使用率没有到100%啊，还有很多资源可用。有点百思不得其解的样子。
再次查看log信息 vim /var/log/messages ，看看有哪些error 日志和内核panic相关。


靠，检查一番之后返现....

-------------------------------------------------------------------------------------------------------------------------------someuser@servercore [/var/log]# grep 'Aug 22 15' messages | grep -v Firewall | grep -v blackmore | grep -v operational | grep -v ec2Aug 22 15:38:05 servercore kernel: INFO: task jbd2/vda3-8:250 blocked for more than 120 seconds.Aug 22 15:38:05 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:05 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:05 servercore kernel: jbd2/vda3-8 D 0000000000000000 0 250 2 0x00000000Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: INFO: task rs:main Q:Reg:1035 blocked for more than 120 seconds.Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: rs:main Q:Reg D 0000000000000000 0 1035 1 0x00000080Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: INFO: task queueprocd - qu:1793 blocked for more than 120 seconds.Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: queueprocd - D 0000000000000000 0 1793 1 0x00000080Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: INFO: task httpd:30439 blocked for more than 120 seconds.Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:07 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:07 servercore kernel: httpd D 0000000000000000 0 30439 2223 0x00000080Aug 22 15:38:07 servercore kernel: Call Trace:Aug 22 15:38:11 servercore kernel: INFO: task httpd:30482 blocked for more than 120 seconds.Aug 22 15:38:11 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:11 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:11 servercore kernel: httpd D 0000000000000000 0 30482 2223 0x00000080Aug 22 15:38:11 servercore kernel: Call Trace:Aug 22 15:39:54 servercore kernel: INFO: task jbd2/vda3-8:250 blocked for more than 120 seconds.Aug 22 15:39:54 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:39:54 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:39:54 servercore kernel: jbd2/vda3-8 D 0000000000000000 0 250 2 0x00000000Aug 22 15:39:54 servercore kernel: Call Trace:Aug 22 15:39:54 servercore kernel: INFO: task flush-253:0:263 blocked for more than 120 seconds.Aug 22 15:39:54 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:39:54 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:39:54 servercore kernel: flush-253:0 D 0000000000000000 0 263 2 0x00000000Aug 22 15:39:54 servercore kernel: Call Trace:Aug 22 15:39:56 servercore kernel: INFO: task rs:main Q:Reg:1035 blocked for more than 120 seconds.Aug 22 15:39:56 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:39:56 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:39:56 servercore kernel: rs:main Q:Reg D 0000000000000000 0 1035 1 0x00000080Aug 22 15:39:56 servercore kernel: Call Trace:Aug 22 15:42:11 servercore kernel: Clocksource tsc unstable (delta = -8589964877 ns)15:55:53 LINUX RESTART-------------------------------------------------------------------------------------------------------------------------------

上面日志显示 ”echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.“

以及“blocked for more than 120 seconds”




分析原因：
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. 
As IO subsystem responds slowly and more requests are served, System Memory gets 
filled up resulting in the above error, thus serving HTTP requests.
解释一下，linux会设置40%的可用内存用来做系统cache，当flush数据时这40%内存中的数据由于
和IO同步问题导致超时（120s），所将40%减小到10%，避免超时。


解决方案：
我们看看默认情况下这两个参数的值：

[zhong@localhost ~]$ ll /proc/sys/vm/dirty_ratio -rw-r--r--. 1 root root 0 7月   4 12:56 /proc/sys/vm/dirty_ratio[zhong@localhost ~]$ cat /proc/sys/vm/dirty_ratio   40[zhongtian@localhost ~]$ cat /proc/sys/vm/dirty_background_ratio 10

接下来我们修改相关参数：
1. 修改参数 vm.dirty_ratio 和 vm.dirty_backgroud_ratio 可以避免这个问题
# sysctl -w vm.dirty_ratio=10
# sysctl -w vm.dirty_background_ratio=5
立即生效：
# sysctl -p
永久修改（需要reboot生效）：
# vi /etc/sysctl.conf  //在此文件的最后添加两行
vm.dirty_background_ratio = 5
vm.dirty_ratio = 10
# reboot


2.找到耗资源的进程，然后对其优化


如果想看看kernel的代码中这部分是怎么回事儿，克隆一份代码在 kernel/hung_task.c 和 kernel/sysctl.c这两个源文件中
有更详细的逻辑。内核源码书中Documentation/sysctl/vm.txt 中有更详细的描述可以参考，因为这部分牵涉到内核关于
虚拟内存子系统的描述，更详细的内容还需要一探究竟！！！


希望可以帮到你！！！


参考资料：
《 一次内核hung task分析》
《Linux进程状态解析之R、S、D、T、Z、X》
《Linux Kernel panic issue: How to fix hung_task_timeout_secs and blocked for more than 120 seconds problem》


以上文档的初衷是在一次ltp压力测试过程中发现一个小问题之后一路追到这里的，虽然还有更进一步的内容需要去探索，这里就不在

继续了，发现问题是要有追下去的勇气，这个过程会让我们进步良多！！！感谢网络上许多前辈们的分享。

欢迎转载！！