使用hungtask 检测异常进程/内核死锁/超时阻塞问题
2018-03-01 23:02
1906 查看
1、内核hung task检测机制由来
我们知道进程等待IO时,经常处于D状态,即TASK_UNINTERRUPTIBLE状态,处于这种状态的进程不处理信号,所以kill不掉,如果进程长期处于D状态,那么肯定不正常,原因可能有二:
1)IO路径上的硬件出问题了,比如硬盘坏了(只有少数情况会导致长期D,通常会返回错误);
2)内核自己出问题了。
这种问题不好定位,而且一旦出现就通常不可恢复,kill不掉,通常只能重启恢复了。
内核针对这种开发了一种hung task的检测机制,基本原理是:定时检测系统中处于D状态的进程,如果其处于D状态的时间超过了指定时间(默认120s,可以配置),则打印相关堆栈信息,也可以通过proc参数配置使其直接panic。
2、hung task相关配置
1)设置timeout时间:
echo xx > /proc/sys/kernel/hung_task_timeout_secs
xx单位为s。
2)设置hung task后是否触发panic
echo 1 > /proc/sys/kernel/hung_task_panic
2、分析示例
今天遇到个hung task的问题,简单记录下分析过程
1)问题现象
控制台上有如下异常打印:
Aug 6 21:17:22 localhost kernel: Appxxx[13608] general protection ip:32be275204 sp:7ff6ad465750 error:0 in libc-2.12.so[32be200000+197000]
...
Aug 6 21:20:47 localhost kernel: INFO: task Appxxx:13189 blocked for more than 120 seconds.
Aug 6 21:20:47 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 6 21:20:47 localhost kernel: ZMSSStreaming D 000000000000000d 0 13189 1 0x00000080
Aug 6 21:20:47 localhost kernel: ffff88089c77fc98 0000000000000086 0000000000000001 0000000000000282
Aug 6 21:20:47 localhost kernel: ffff88089c77fc68 ffffffff810a4210 0000000000000000 ffff8807cc4cecd8
Aug 6 21:20:47 localhost kernel: ffff880bfe0d30b8 ffff88089c77ffd8 000000000000f4e8 ffff880bfe0d30b8
Aug 6 21:20:47 localhost kernel: Call Trace:
Aug 6 21:20:47 localhost kernel: [] ? exit_robust_list+0x90/0x160
Aug 6 21:20:47 localhost kernel: [] exit_mm+0x95/0x180
Aug 6 21:20:47 localhost kernel: [] do_exit+0x15f/0x870
Aug 6 21:20:47 localhost kernel: [] ? dequeue_entity+0x105/0x2e0
Aug 6 21:20:47 localhost kernel: [] ? __dequeue_entity+0x30/0x50
Aug 6 21:20:47 localhost kernel: [] do_group_exit+0x58/0xe0
Aug 6 21:20:47 localhost kernel: [] get_signal_to_deliver+0x1f6/0x460
Aug 6 21:20:47 localhost kernel: [] do_signal+0x75/0x800
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_cancel+0x22/0x30
Aug 6 21:20:47 localhost kernel: [] ? do_nanosleep+0x93/0xc0
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_nanosleep+0xc4/0x180
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_wakeup+0x0/0x30
Aug 6 21:20:47 localhost kernel: [] do_notify_resume+0x90/0xc0
Aug 6 21:20:47 localhost kernel: [] int_signal+0x12/0x17
Aug 6 21:20:47 localhost kernel: INFO: task ZMSSStreamingSe:13239 blocked for more than 120 seconds.
Aug 6 21:20:47 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 6 21:20:47 localhost kernel: ZMSSStreaming D 0000000000000000 0 13239 1 0x00000080
Aug 6 21:20:47 localhost kernel: ffff8808ca951c98 0000000000000086 ffff8801193b80c0 0000000000000005
Aug 6 21:20:47 localhost kernel: ffff8808ca951c68 ffffffff810a4210 000000101d1b9400 ffff8801193b80f8
Aug 6 21:20:47 localhost kernel: ffff880c0422c678 ffff8808ca951fd8 000000000000f4e8 ffff880c0422c678
Aug 6 21:20:47 localhost kernel: Call Trace:
Aug 6 21:20:47 localhost kernel: [] ? exit_robust_list+0x90/0x160
Aug 6 21:20:47 localhost kernel: [] exit_mm+0x95/0x180
Aug 6 21:20:47 localhost kernel: [] do_exit+0x15f/0x870
Aug 6 21:20:47 localhost kernel: [] ? dequeue_entity+0x105/0x2e0
Aug 6 21:20:47 localhost kernel: [] do_group_exit+0x58/0xe0
Aug 6 21:20:47 localhost kernel: [] get_signal_to_deliver+0x1f6/0x460
Aug 6 21:20:47 localhost kernel: [] do_signal+0x75/0x800
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_nanosleep+0xe7/0x180
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_wakeup+0x0/0x30
Aug 6 21:20:47 localhost kernel: [] do_notify_resume+0x90/0xc0
Aug 6 21:20:47 localhost kernel: [] int_signal+0x12/0x17
2)分析
从阻塞进程的堆栈看,应该是在信号处理过程中,进程退出时阻塞了,最终阻塞的地方在:
Aug 6 21:20:47 localhost kernel: [] exit_mm+0x95/0x180
反汇编再结合源代码确认在
wait_for_completion(&mm->core_done)
而wait_for_completion,默认就是进入D状态等待:
点击(此处)折叠或打开
void __sched wait_for_completion(struct completion *x)
{
wait_for_common(x, MAX_SCHEDULE_TIMEOUT, TASK_UNINTERRUPTIBLE);
}
mm->core_done其实就是在等待进程的coredump收集完成,说明此时该进程可能正在收集coredump
结合hung task之前的日志,发现该业务进程发生了段错误:
Aug 6 21:17:22 localhost kernel: Appxxx[13608] general protection ip:32be275204 sp:7ff6ad465750 error:0 in libc-2.12.so[32be200000+197000]
那就对上了,用户态进程发生段错误后,内核默认会向该进程发送信号,使其退出,正符合上述的堆栈逻辑。
那么总结起来,这个问题即因为:业务进程Appxxx出现了段错误,从而需要进行coredump的搜集,同时需要向业务进程发送信号使其终止运行,业务进程在处理信号,退出过程中,需要等coredump搜集完成,从而一直处于D状态,而因为业务进程占用的内存比较大导致收集时间比较长,超过了2分钟,所以出现了阻塞,触发hung task检测,但后来coredump收集完成后就自动恢复了。
我们知道进程等待IO时,经常处于D状态,即TASK_UNINTERRUPTIBLE状态,处于这种状态的进程不处理信号,所以kill不掉,如果进程长期处于D状态,那么肯定不正常,原因可能有二:
1)IO路径上的硬件出问题了,比如硬盘坏了(只有少数情况会导致长期D,通常会返回错误);
2)内核自己出问题了。
这种问题不好定位,而且一旦出现就通常不可恢复,kill不掉,通常只能重启恢复了。
内核针对这种开发了一种hung task的检测机制,基本原理是:定时检测系统中处于D状态的进程,如果其处于D状态的时间超过了指定时间(默认120s,可以配置),则打印相关堆栈信息,也可以通过proc参数配置使其直接panic。
2、hung task相关配置
1)设置timeout时间:
echo xx > /proc/sys/kernel/hung_task_timeout_secs
xx单位为s。
2)设置hung task后是否触发panic
echo 1 > /proc/sys/kernel/hung_task_panic
2、分析示例
今天遇到个hung task的问题,简单记录下分析过程
1)问题现象
控制台上有如下异常打印:
Aug 6 21:17:22 localhost kernel: Appxxx[13608] general protection ip:32be275204 sp:7ff6ad465750 error:0 in libc-2.12.so[32be200000+197000]
...
Aug 6 21:20:47 localhost kernel: INFO: task Appxxx:13189 blocked for more than 120 seconds.
Aug 6 21:20:47 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 6 21:20:47 localhost kernel: ZMSSStreaming D 000000000000000d 0 13189 1 0x00000080
Aug 6 21:20:47 localhost kernel: ffff88089c77fc98 0000000000000086 0000000000000001 0000000000000282
Aug 6 21:20:47 localhost kernel: ffff88089c77fc68 ffffffff810a4210 0000000000000000 ffff8807cc4cecd8
Aug 6 21:20:47 localhost kernel: ffff880bfe0d30b8 ffff88089c77ffd8 000000000000f4e8 ffff880bfe0d30b8
Aug 6 21:20:47 localhost kernel: Call Trace:
Aug 6 21:20:47 localhost kernel: [] ? exit_robust_list+0x90/0x160
Aug 6 21:20:47 localhost kernel: [] exit_mm+0x95/0x180
Aug 6 21:20:47 localhost kernel: [] do_exit+0x15f/0x870
Aug 6 21:20:47 localhost kernel: [] ? dequeue_entity+0x105/0x2e0
Aug 6 21:20:47 localhost kernel: [] ? __dequeue_entity+0x30/0x50
Aug 6 21:20:47 localhost kernel: [] do_group_exit+0x58/0xe0
Aug 6 21:20:47 localhost kernel: [] get_signal_to_deliver+0x1f6/0x460
Aug 6 21:20:47 localhost kernel: [] do_signal+0x75/0x800
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_cancel+0x22/0x30
Aug 6 21:20:47 localhost kernel: [] ? do_nanosleep+0x93/0xc0
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_nanosleep+0xc4/0x180
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_wakeup+0x0/0x30
Aug 6 21:20:47 localhost kernel: [] do_notify_resume+0x90/0xc0
Aug 6 21:20:47 localhost kernel: [] int_signal+0x12/0x17
Aug 6 21:20:47 localhost kernel: INFO: task ZMSSStreamingSe:13239 blocked for more than 120 seconds.
Aug 6 21:20:47 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 6 21:20:47 localhost kernel: ZMSSStreaming D 0000000000000000 0 13239 1 0x00000080
Aug 6 21:20:47 localhost kernel: ffff8808ca951c98 0000000000000086 ffff8801193b80c0 0000000000000005
Aug 6 21:20:47 localhost kernel: ffff8808ca951c68 ffffffff810a4210 000000101d1b9400 ffff8801193b80f8
Aug 6 21:20:47 localhost kernel: ffff880c0422c678 ffff8808ca951fd8 000000000000f4e8 ffff880c0422c678
Aug 6 21:20:47 localhost kernel: Call Trace:
Aug 6 21:20:47 localhost kernel: [] ? exit_robust_list+0x90/0x160
Aug 6 21:20:47 localhost kernel: [] exit_mm+0x95/0x180
Aug 6 21:20:47 localhost kernel: [] do_exit+0x15f/0x870
Aug 6 21:20:47 localhost kernel: [] ? dequeue_entity+0x105/0x2e0
Aug 6 21:20:47 localhost kernel: [] do_group_exit+0x58/0xe0
Aug 6 21:20:47 localhost kernel: [] get_signal_to_deliver+0x1f6/0x460
Aug 6 21:20:47 localhost kernel: [] do_signal+0x75/0x800
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_nanosleep+0xe7/0x180
Aug 6 21:20:47 localhost kernel: [] ? hrtimer_wakeup+0x0/0x30
Aug 6 21:20:47 localhost kernel: [] do_notify_resume+0x90/0xc0
Aug 6 21:20:47 localhost kernel: [] int_signal+0x12/0x17
2)分析
从阻塞进程的堆栈看,应该是在信号处理过程中,进程退出时阻塞了,最终阻塞的地方在:
Aug 6 21:20:47 localhost kernel: [] exit_mm+0x95/0x180
反汇编再结合源代码确认在
wait_for_completion(&mm->core_done)
而wait_for_completion,默认就是进入D状态等待:
点击(此处)折叠或打开
void __sched wait_for_completion(struct completion *x)
{
wait_for_common(x, MAX_SCHEDULE_TIMEOUT, TASK_UNINTERRUPTIBLE);
}
mm->core_done其实就是在等待进程的coredump收集完成,说明此时该进程可能正在收集coredump
结合hung task之前的日志,发现该业务进程发生了段错误:
Aug 6 21:17:22 localhost kernel: Appxxx[13608] general protection ip:32be275204 sp:7ff6ad465750 error:0 in libc-2.12.so[32be200000+197000]
那就对上了,用户态进程发生段错误后,内核默认会向该进程发送信号,使其退出,正符合上述的堆栈逻辑。
那么总结起来,这个问题即因为:业务进程Appxxx出现了段错误,从而需要进行coredump的搜集,同时需要向业务进程发送信号使其终止运行,业务进程在处理信号,退出过程中,需要等coredump搜集完成,从而一直处于D状态,而因为业务进程占用的内存比较大导致收集时间比较长,超过了2分钟,所以出现了阻塞,触发hung task检测,但后来coredump收集完成后就自动恢复了。
相关文章推荐
- 使用51内核单片机检测开关状态中断函数的问题
- 如何使用MDB调试分析Solaris内核死锁的问题
- XP CPU经常莫名其妙60%-70%,HDTune检测无坏块,System Interrupts进程异常问题解决
- libcurl使用easy模式阻塞卡死等问题的完美解决---超时设置
- H2 数据库,进程死锁导致访问异常的问题
- Linux系统/sys/hypervisor/uuid阻塞,导致数据库进程异常停止的问题
- kazoo在多进程下使用全局连接死锁问题
- Linux内核调试技术——进程D状态死锁检测
- 探讨由于死锁或进程阻塞造成的ASP突然不能访问的问题
- 解决进程间共享内存,由于某个进程异常退出导致死锁问题
- nginx使用zookeeper造成进程死锁和崩溃问题和解决方案
- libcurl使用easy模式阻塞卡死等问题的完美解决---超时设置
- 使用双向链表和Hashtable来加速处理“心跳”超时检测
- 使用exec启动其他进程时可能出现的问题
- linux 内核进程与用户进程的通信 方法一 使用sockopt与内核交换数据
- 进程死锁的检测:资源分配图的化简判断是否有死锁发生
- 拒绝访问。 (异常来自 HRESULT:0x80070005 (E_ACCESSDENIED)) 使用Enterprise Library 3.0的磁盘缓存Isolated Storage 的问题
- weblogic下使用hibernate3的异常问题及解决
- VB使用API实现串口通讯的异常问题
- 在从池中获取连接之前超时时间已过,所有池连接都已被使用并已达到最大池大小的问题解决方法