softlockup: detect bottom-half lockups

This patch adds a new kernel debug feature: CONFIG_DETECT_BHLOCKUP.

This feature is an extension of the softlockup detector.

When enabled, per-CPU watchdog tasklets are created, which try to run periodically and update a timestamp. If they get delayed for more than then the configured threshold a callback from the timer interrupt detects this condition and prints out a warning message similar to what is currently printing when a softlockup is detected.

The feature should be useful to real-time developers and developers of network and other high-performance drivers.

Background:

Colleague noticed that a server was experiencing periodic packet drops:
a burst of packets every n minutes. After a lot of head scratching, it was root caused to a daemon reading /proc/net/tcp. In this particular kernel, the code disabled bottom-halves while iterating over all TCP buckets.

There was no softlockup because the burst wasn't long enough. With a bottom-half only lockup detector it should be possible to set the threshold very low (100s of ms) since the expected maximum delay for a temporary bhlockup is much less than a softlockup.

The bug was fixed with this patch:

commit a7ab4b501f9b8a9dc4d5cee542db67b6ccd1088b
Author: Herbert Xu <[email protected]>
Date: Mon, 11 Jun 2007 00:33:08 +0000 (17:33 -0700)

[TCPv4]: Improve BH latency in /proc/net/tcp

---
 include/linux/sched.h |    6 +++
 kernel/softlockup.c   |  119 ++++++++++++++++++++++++++++++++++++++++++++++++-
 kernel/sysctl.c       |   33 ++++++++++++++
 lib/Kconfig.debug     |   14 ++++++
 4 files changed, 171 insertions(+), 1 deletions(-)

index 55e30d1..ad01824 100644
@@ -314,6 +314,12 @@ static inline void touch_all_softlockup_watchdogs(void)
 {
 }
 #endif
+#ifdef CONFIG_DETECT_BHLOCKUP
+extern int bhlockup_thresh;
+extern int proc_dobhlockup_thresh(struct ctl_table *table, int write,
+				  struct file *filp, void __user *buffer,
+				  size_t *lenp, loff_t *ppos);
+#endif
 
 
 /* Attach to any functions which should be ignored in wchan output. */

index 3d56fe7..94d234d 100644
@@ -799,6 +799,19 @@ static struct ctl_table kern_table[] = {
 		.strategy	= &sysctl_intvec,
 	},
 #endif
+#ifdef CONFIG_DETECT_SOFTLOCKUP
+	{
+		.ctl_name	= CTL_UNNUMBERED,
+		.procname	= "bhlockup_thresh_ms",
+		.data		= &bhlockup_thresh,
+		.maxlen		= sizeof(int),
+		.mode		= 0644,
+		.proc_handler	= &proc_dobhlockup_thresh,
+		.strategy	= &sysctl_intvec,
+		.extra1		= &neg_one,
+		.extra2		= &sixty,
+	},
+#endif
 #ifdef CONFIG_COMPAT
 	{
 		.ctl_name	= KERN_COMPAT_LOG,

@@ -2010,6 +2023,26 @@ void sysctl_head_put(struct ctl_table_header *head)
  * /proc/sys support
  */
 
+int proc_dobhlockupnow(ctl_table *table, int write, struct file *filp,
+		      void *buffer, size_t *lenp, loff_t *ppos)
+{
+	if (write) {
+		char magic[20];
+		/* just crash in kernel mode. */
+		if(copy_from_user(magic, buffer, min(*lenp, sizeof(magic))))
+			return -EFAULT;
+		magic[min(*lenp, sizeof(magic))-1] = 0;
+		if (!strcmp(magic, "elgooG")) {
+			local_bh_disable();
+			mdelay(20000);
+			local_bh_enable();
+		}
+		return 0;
+	}
+	*lenp = 0;
+	return 0;
+}
+
 #ifdef CONFIG_PROC_SYSCTL
 
 static int _proc_do_string(void* data, int maxlen, int write,

index b0f239e..a7c8b2c 100644
@@ -186,6 +186,20 @@ config BOOTPARAM_SOFTLOCKUP_PANIC_VALUE
 	default 0 if !BOOTPARAM_SOFTLOCKUP_PANIC
 	default 1 if BOOTPARAM_SOFTLOCKUP_PANIC
 
+config DETECT_BHLOCKUP
+	bool "Detect Bottom-half Lockups"
+	depends on DETECT_SOFTLOCKUP
+	default y
+	help
+	  Say Y here to enable the kernel to detect "bottom-half lockups",
+	  which are bugs that cause the kernel to delay soft interrupt
+	  processing for more than 5 seconds.
+
+	  When a bottom-half lockup is detected, the kernel will print the
+	  current stack trace (which you should report), but the
+	  system will stay locked up. This feature has negligible
+	  overhead.
+
 config SCHED_DEBUG
 	bool "Collect scheduler debugging info"
 	depends on DEBUG_KERNEL && PROC_FS

1.5.4.5

hm, did you know about the ftrace latency tracers:

config IRQSOFF_TRACER
bool "Interrupts-off Latency Tracer"

config PREEMPT_TRACER
bool "Preemption-off Latency Tracer"

config SCHED_TRACER
bool "Scheduling Latency Tracer"

PREEMPT_TRACER would have shown you that softirqs-off section very nicely.

(And if you also enable the function tracer then not just the latency endpoint is shown, but also all the function calls that happened in the critical section.)

Ingo

Stumbled upon ftrace tracepoints while writing this patch. Should make life a lot easier for debugging latency issues.

bhlockup should complement ftrace. Once you've found that there's a problem, tracing can be a big help in debugging. But assertions are nice for finding problems you didn't know exist.