softlockup: automatically detect hung TASK_UNINTERRUPTIBLE tasks
authorIngo Molnar <mingo@elte.hu>
Fri, 25 Jan 2008 20:08:02 +0000 (21:08 +0100)
committerIngo Molnar <mingo@elte.hu>
Fri, 25 Jan 2008 20:08:02 +0000 (21:08 +0100)
this patch extends the soft-lockup detector to automatically
detect hung TASK_UNINTERRUPTIBLE tasks. Such hung tasks are
printed the following way:

 ------------------>
 INFO: task prctl:3042 blocked for more than 120 seconds.
 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message
 prctl         D fd5e3793     0  3042   2997
        f6050f38 00000046 00000001 fd5e3793 00000009 c06d8264 c06dae80 00000286
        f6050f40 f6050f00 f7d34d90 f7d34fc8 c1e1be80 00000001 f6050000 00000000
        f7e92d00 00000286 f6050f18 c0489d1a f6050f40 00006605 00000000 c0133a5b
 Call Trace:
  [<c04883a5>] schedule_timeout+0x6d/0x8b
  [<c04883d8>] schedule_timeout_uninterruptible+0x15/0x17
  [<c0133a76>] msleep+0x10/0x16
  [<c0138974>] sys_prctl+0x30/0x1e2
  [<c0104c52>] sysenter_past_esp+0x5f/0xa5
  =======================
 2 locks held by prctl/3042:
 #0:  (&sb->s_type->i_mutex_key#5){--..}, at: [<c0197d11>] do_fsync+0x38/0x7a
 #1:  (jbd_handle){--..}, at: [<c01ca3d2>] journal_start+0xc7/0xe9
 <------------------

the current default timeout is 120 seconds. Such messages are printed
up to 10 times per bootup. If the system has crashed already then the
messages are not printed.

if lockdep is enabled then all held locks are printed as well.

this feature is a natural extension to the softlockup-detector (kernel
locked up without scheduling) and to the NMI watchdog (kernel locked up
with IRQs disabled).

[ Gautham R Shenoy <ego@in.ibm.com>: CPU hotplug fixes. ]
[ Andrew Morton <akpm@linux-foundation.org>: build warning fix. ]

Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
include/linux/debug_locks.h
include/linux/sched.h
kernel/fork.c
kernel/lockdep.c
kernel/sched.c
kernel/softlockup.c
kernel/sysctl.c

index 1678a5de7013a91f08f3f352a773ff90166240f1..f4a5871767f534ef6b8a2a950c70372ef7c27ca7 100644 (file)
@@ -47,6 +47,7 @@ struct task_struct;
 
 #ifdef CONFIG_LOCKDEP
 extern void debug_show_all_locks(void);
+extern void __debug_show_held_locks(struct task_struct *task);
 extern void debug_show_held_locks(struct task_struct *task);
 extern void debug_check_no_locks_freed(const void *from, unsigned long len);
 extern void debug_check_no_locks_held(struct task_struct *task);
@@ -55,6 +56,10 @@ static inline void debug_show_all_locks(void)
 {
 }
 
+static inline void __debug_show_held_locks(struct task_struct *task)
+{
+}
+
 static inline void debug_show_held_locks(struct task_struct *task)
 {
 }
index 288245f83bd4f89fd8937677f2cf59872961f81d..0846f1f9e196d35c1e9af6f841d77f6f5e13aa03 100644 (file)
@@ -258,12 +258,17 @@ extern void account_process_tick(struct task_struct *task, int user);
 extern void update_process_times(int user);
 extern void scheduler_tick(void);
 
+extern void sched_show_task(struct task_struct *p);
+
 #ifdef CONFIG_DETECT_SOFTLOCKUP
 extern void softlockup_tick(void);
 extern void spawn_softlockup_task(void);
 extern void touch_softlockup_watchdog(void);
 extern void touch_all_softlockup_watchdogs(void);
 extern int softlockup_thresh;
+extern unsigned long sysctl_hung_task_check_count;
+extern unsigned long sysctl_hung_task_timeout_secs;
+extern long sysctl_hung_task_warnings;
 #else
 static inline void softlockup_tick(void)
 {
@@ -1041,6 +1046,11 @@ struct task_struct {
 /* ipc stuff */
        struct sysv_sem sysvsem;
 #endif
+#ifdef CONFIG_DETECT_SOFTLOCKUP
+/* hung task detection */
+       unsigned long last_switch_timestamp;
+       unsigned long last_switch_count;
+#endif
 /* CPU-specific state of this task */
        struct thread_struct thread;
 /* filesystem information */
index 8dd8ff2810095d9bab2e511e60dbfe2500ef8b90..09c0b90a69ccd5a265958e01968f0bbf68af37b7 100644 (file)
@@ -1059,6 +1059,11 @@ static struct task_struct *copy_process(unsigned long clone_flags,
        p->prev_utime = cputime_zero;
        p->prev_stime = cputime_zero;
 
+#ifdef CONFIG_DETECT_SOFTLOCKUP
+       p->last_switch_count = 0;
+       p->last_switch_timestamp = 0;
+#endif
+
 #ifdef CONFIG_TASK_XACCT
        p->rchar = 0;           /* I/O counter: bytes read */
        p->wchar = 0;           /* I/O counter: bytes written */
index e2c07ece367d1f9793f68c21a03a80701a09509f..3574379f4d62d2d04c9431c0c2172dc044d0ca66 100644 (file)
@@ -3206,7 +3206,11 @@ retry:
 
 EXPORT_SYMBOL_GPL(debug_show_all_locks);
 
-void debug_show_held_locks(struct task_struct *task)
+/*
+ * Careful: only use this function if you are sure that
+ * the task cannot run in parallel!
+ */
+void __debug_show_held_locks(struct task_struct *task)
 {
        if (unlikely(!debug_locks)) {
                printk("INFO: lockdep is turned off.\n");
@@ -3214,6 +3218,12 @@ void debug_show_held_locks(struct task_struct *task)
        }
        lockdep_print_held_locks(task);
 }
+EXPORT_SYMBOL_GPL(__debug_show_held_locks);
+
+void debug_show_held_locks(struct task_struct *task)
+{
+               __debug_show_held_locks(task);
+}
 
 EXPORT_SYMBOL_GPL(debug_show_held_locks);
 
index c0e2db683e2944b3349c2405dc3665951d2124c4..5b3d46574eebed201abe0dc69c7ca34a394bf483 100644 (file)
@@ -4945,7 +4945,7 @@ out_unlock:
 
 static const char stat_nam[] = "RSDTtZX";
 
-static void show_task(struct task_struct *p)
+void sched_show_task(struct task_struct *p)
 {
        unsigned long free = 0;
        unsigned state;
@@ -4998,7 +4998,7 @@ void show_state_filter(unsigned long state_filter)
                 */
                touch_nmi_watchdog();
                if (!state_filter || (p->state & state_filter))
-                       show_task(p);
+                       sched_show_task(p);
        } while_each_thread(g, p);
 
        touch_all_softlockup_watchdogs();
index 11df812263c8fd3eed16f4f1a57d36a68f6eaedc..02f0ad5344419d73e8716a7af48d0822efcd5b59 100644 (file)
@@ -8,6 +8,7 @@
  */
 #include <linux/mm.h>
 #include <linux/cpu.h>
+#include <linux/nmi.h>
 #include <linux/init.h>
 #include <linux/delay.h>
 #include <linux/freezer.h>
@@ -24,7 +25,7 @@ static DEFINE_PER_CPU(unsigned long, print_timestamp);
 static DEFINE_PER_CPU(struct task_struct *, watchdog_task);
 
 static int did_panic;
-int softlockup_thresh = 10;
+int softlockup_thresh = 60;
 
 static int
 softlock_panic(struct notifier_block *this, unsigned long event, void *ptr)
@@ -45,7 +46,7 @@ static struct notifier_block panic_block = {
  */
 static unsigned long get_timestamp(int this_cpu)
 {
-       return cpu_clock(this_cpu) >> 30;  /* 2^30 ~= 10^9 */
+       return cpu_clock(this_cpu) >> 30LL;  /* 2^30 ~= 10^9 */
 }
 
 void touch_softlockup_watchdog(void)
@@ -100,11 +101,7 @@ void softlockup_tick(void)
 
        now = get_timestamp(this_cpu);
 
-       /* Wake up the high-prio watchdog task every second: */
-       if (now > (touch_timestamp + 1))
-               wake_up_process(per_cpu(watchdog_task, this_cpu));
-
-       /* Warn about unreasonable 10+ seconds delays: */
+       /* Warn about unreasonable delays: */
        if (now <= (touch_timestamp + softlockup_thresh))
                return;
 
@@ -121,12 +118,94 @@ void softlockup_tick(void)
        spin_unlock(&print_lock);
 }
 
+/*
+ * Have a reasonable limit on the number of tasks checked:
+ */
+unsigned long sysctl_hung_task_check_count = 1024;
+
+/*
+ * Zero means infinite timeout - no checking done:
+ */
+unsigned long sysctl_hung_task_timeout_secs = 120;
+
+long sysctl_hung_task_warnings = 10;
+
+/*
+ * Only do the hung-tasks check on one CPU:
+ */
+static int check_cpu __read_mostly = -1;
+
+static void check_hung_task(struct task_struct *t, unsigned long now)
+{
+       unsigned long switch_count = t->nvcsw + t->nivcsw;
+
+       if (t->flags & PF_FROZEN)
+               return;
+
+       if (switch_count != t->last_switch_count || !t->last_switch_timestamp) {
+               t->last_switch_count = switch_count;
+               t->last_switch_timestamp = now;
+               return;
+       }
+       if ((long)(now - t->last_switch_timestamp) <
+                                       sysctl_hung_task_timeout_secs)
+               return;
+       if (sysctl_hung_task_warnings < 0)
+               return;
+       sysctl_hung_task_warnings--;
+
+       /*
+        * Ok, the task did not get scheduled for more than 2 minutes,
+        * complain:
+        */
+       printk(KERN_ERR "INFO: task %s:%d blocked for more than "
+                       "%ld seconds.\n", t->comm, t->pid,
+                       sysctl_hung_task_timeout_secs);
+       printk(KERN_ERR "\"echo 0 > /proc/sys/kernel/hung_task_timeout_secs\""
+                       " disables this message.\n");
+       sched_show_task(t);
+       __debug_show_held_locks(t);
+
+       t->last_switch_timestamp = now;
+       touch_nmi_watchdog();
+}
+
+/*
+ * Check whether a TASK_UNINTERRUPTIBLE does not get woken up for
+ * a really long time (120 seconds). If that happens, print out
+ * a warning.
+ */
+static void check_hung_uninterruptible_tasks(int this_cpu)
+{
+       int max_count = sysctl_hung_task_check_count;
+       unsigned long now = get_timestamp(this_cpu);
+       struct task_struct *g, *t;
+
+       /*
+        * If the system crashed already then all bets are off,
+        * do not report extra hung tasks:
+        */
+       if ((tainted & TAINT_DIE) || did_panic)
+               return;
+
+       read_lock(&tasklist_lock);
+       do_each_thread(g, t) {
+               if (!--max_count)
+                       break;
+               if (t->state & TASK_UNINTERRUPTIBLE)
+                       check_hung_task(t, now);
+       } while_each_thread(g, t);
+
+       read_unlock(&tasklist_lock);
+}
+
 /*
  * The watchdog thread - runs every second and touches the timestamp.
  */
 static int watchdog(void *__bind_cpu)
 {
        struct sched_param param = { .sched_priority = MAX_RT_PRIO-1 };
+       int this_cpu = (long)__bind_cpu;
 
        sched_setscheduler(current, SCHED_FIFO, &param);
 
@@ -135,13 +214,18 @@ static int watchdog(void *__bind_cpu)
 
        /*
         * Run briefly once per second to reset the softlockup timestamp.
-        * If this gets delayed for more than 10 seconds then the
+        * If this gets delayed for more than 60 seconds then the
         * debug-printout triggers in softlockup_tick().
         */
        while (!kthread_should_stop()) {
-               set_current_state(TASK_INTERRUPTIBLE);
                touch_softlockup_watchdog();
-               schedule();
+               msleep_interruptible(10000);
+
+               if (this_cpu != check_cpu)
+                       continue;
+
+               if (sysctl_hung_task_timeout_secs)
+                       check_hung_uninterruptible_tasks(this_cpu);
        }
 
        return 0;
@@ -171,6 +255,7 @@ cpu_callback(struct notifier_block *nfb, unsigned long action, void *hcpu)
                break;
        case CPU_ONLINE:
        case CPU_ONLINE_FROZEN:
+               check_cpu = any_online_cpu(cpu_online_map);
                wake_up_process(per_cpu(watchdog_task, hotcpu));
                break;
 #ifdef CONFIG_HOTPLUG_CPU
@@ -181,6 +266,15 @@ cpu_callback(struct notifier_block *nfb, unsigned long action, void *hcpu)
                /* Unbind so it can run.  Fall thru. */
                kthread_bind(per_cpu(watchdog_task, hotcpu),
                             any_online_cpu(cpu_online_map));
+       case CPU_DOWN_PREPARE:
+       case CPU_DOWN_PREPARE_FROZEN:
+               if (hotcpu == check_cpu) {
+                       cpumask_t temp_cpu_online_map = cpu_online_map;
+
+                       cpu_clear(hotcpu, temp_cpu_online_map);
+                       check_cpu = any_online_cpu(temp_cpu_online_map);
+               }
+               break;
        case CPU_DEAD:
        case CPU_DEAD_FROZEN:
                p = per_cpu(watchdog_task, hotcpu);
index c95f3ed34474af8d6cf89303515180a4815f28ac..96f31c1bc4f0ad3223b92d64a6bfd9a6f22c1eb0 100644 (file)
@@ -753,6 +753,33 @@ static struct ctl_table kern_table[] = {
                .extra1         = &one,
                .extra2         = &sixty,
        },
+       {
+               .ctl_name       = CTL_UNNUMBERED,
+               .procname       = "hung_task_check_count",
+               .data           = &sysctl_hung_task_check_count,
+               .maxlen         = sizeof(int),
+               .mode           = 0644,
+               .proc_handler   = &proc_dointvec_minmax,
+               .strategy       = &sysctl_intvec,
+       },
+       {
+               .ctl_name       = CTL_UNNUMBERED,
+               .procname       = "hung_task_timeout_secs",
+               .data           = &sysctl_hung_task_timeout_secs,
+               .maxlen         = sizeof(int),
+               .mode           = 0644,
+               .proc_handler   = &proc_dointvec_minmax,
+               .strategy       = &sysctl_intvec,
+       },
+       {
+               .ctl_name       = CTL_UNNUMBERED,
+               .procname       = "hung_task_warnings",
+               .data           = &sysctl_hung_task_warnings,
+               .maxlen         = sizeof(int),
+               .mode           = 0644,
+               .proc_handler   = &proc_dointvec_minmax,
+               .strategy       = &sysctl_intvec,
+       },
 #endif
 #ifdef CONFIG_COMPAT
        {