一次内核hung task分析

2015年4月18日 发表评论 阅读评论

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

3、分析示例

今天遇到个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: [<ffffffff810a4210>] ? exit_robust_list+0x90/0x160
Aug  6 21:20:47 localhost kernel: [<ffffffff8106eee5>] exit_mm+0x95/0x180
Aug  6 21:20:47 localhost kernel: [<ffffffff8106f32f>] do_exit+0x15f/0x870
Aug  6 21:20:47 localhost kernel: [<ffffffff81064d35>] ? dequeue_entity+0x105/0x2e0
Aug  6 21:20:47 localhost kernel: [<ffffffff81052fe0>] ? __dequeue_entity+0x30/0x50
Aug  6 21:20:47 localhost kernel: [<ffffffff8106fa98>] do_group_exit+0x58/0xe0
Aug  6 21:20:47 localhost kernel: [<ffffffff81084fe6>] get_signal_to_deliver+0x1f6/0x460
Aug  6 21:20:47 localhost kernel: [<ffffffff8100a2d5>] do_signal+0x75/0x800
Aug  6 21:20:47 localhost kernel: [<ffffffff81097032>] ? hrtimer_cancel+0x22/0x30
Aug  6 21:20:47 localhost kernel: [<ffffffff814fa6d3>] ? do_nanosleep+0x93/0xc0
Aug  6 21:20:47 localhost kernel: [<ffffffff81097104>] ? hrtimer_nanosleep+0xc4/0x180
Aug  6 21:20:47 localhost kernel: [<ffffffff81095eb0>] ? hrtimer_wakeup+0x0/0x30
Aug  6 21:20:47 localhost kernel: [<ffffffff8100aaf0>] do_notify_resume+0x90/0xc0
Aug  6 21:20:47 localhost kernel: [<ffffffff8100b3c1>] 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: [<ffffffff810a4210>] ? exit_robust_list+0x90/0x160
Aug  6 21:20:47 localhost kernel: [<ffffffff8106eee5>] exit_mm+0x95/0x180
Aug  6 21:20:47 localhost kernel: [<ffffffff8106f32f>] do_exit+0x15f/0x870
Aug  6 21:20:47 localhost kernel: [<ffffffff81064d35>] ? dequeue_entity+0x105/0x2e0
Aug  6 21:20:47 localhost kernel: [<ffffffff8106fa98>] do_group_exit+0x58/0xe0
Aug  6 21:20:47 localhost kernel: [<ffffffff81084fe6>] get_signal_to_deliver+0x1f6/0x460
Aug  6 21:20:47 localhost kernel: [<ffffffff8100a2d5>] do_signal+0x75/0x800
Aug  6 21:20:47 localhost kernel: [<ffffffff81097127>] ? hrtimer_nanosleep+0xe7/0x180
Aug  6 21:20:47 localhost kernel: [<ffffffff81095eb0>] ? hrtimer_wakeup+0x0/0x30
Aug  6 21:20:47 localhost kernel: [<ffffffff8100aaf0>] do_notify_resume+0x90/0xc0
Aug  6 21:20:47 localhost kernel: [<ffffffff8100b3c1>] int_signal+0x12/0x17

2)分析

从阻塞进程的堆栈看,应该是在信号处理过程中,进程退出时阻塞了,最终阻塞的地方在:
Aug  6 21:20:47 localhost kernel: [<ffffffff8106eee5>] 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收集完成后就自动恢复了。

注:本篇内容非原创,只不过在非析某问题时从网上查看到,刚好现网部分主机经常也没有kdump生成,而在message里有超过120秒的情况下产生堆栈信息和发生call trace的情况。这里提供了分析的一个思路。这里摘录下来。




本站的发展离不开您的资助,金额随意,欢迎来赏!

You can donate through PayPal.
My paypal id: itybku@139.com
Paypal page: https://www.paypal.me/361way

  1. 本文目前尚无任何评论.
  1. 本文目前尚无任何 trackbacks 和 pingbacks.