make lost-tick detection more informative

Linus,
Andrew Morton mentioned this when he sent you the lost tick detection patch.

The new lost-tick detection code can be relatively uninformative when something using the common_interrupt->do_IRQ path keeps interrupts disabled for a long time. This patch will record the last interrupt on the current CPU, and spit it out along with the stack trace. I ignore the timer interrupt, because it is always running when this detection occurs, and would overwrite the previous interrupt that took a long time.

You can now turn this on with a boot-time option with the same name as
x86-64: "report_lost_ticks". I don't like the default of 5, so I let it take a plain report_lost_ticks, or report_lost_ticks=100, if you want.

Warning! Detected 4094446 micro-second gap between interrupts.
Compensating for 4093 lost ticks.

Call Trace:
 [<c010ab60>] handle_IRQ_event+0x28/0x50
 [<c010ad44>] do_IRQ+0xa0/0x10c
 [<c01097b3>] common_interrupt+0x43/0x58
  Last run common irq: 24: eth2

 irq.c  |    6 ++++++
 time.c |   41 ++++++++++++++++++++++++++++++++---------
 2 files changed, 38 insertions(+), 9 deletions(-)

Dave Hansen
[email protected]

# This is a BitKeeper generated patch for the following project:
# Project Name: Linux kernel tree
# This patch format is intended for GNU patch command version 2.5 or higher. # This patch includes the following deltas:
# ChangeSet 1.981 -> 1.983
# arch/i386/kernel/irq.c 1.25 -> 1.26
# arch/i386/kernel/time.c 1.25 -> 1.27
#
# The following is the BitKeeper ChangeSet Log
# --------------------------------------------
# 03/02/04 haveblue@elm3b96.(none) 1.982

# report better lock-tick information
# --------------------------------------------
# 03/02/04	haveblue@elm3b96.(none)	1.983
# irq.c:
#   add better last irq description
# time.c:
#   add missing variable
# --------------------------------------------
#
diff -Nru a/arch/i386/kernel/irq.c b/arch/i386/kernel/irq.c
--- a/arch/i386/kernel/irq.c	Tue Feb  4 13:30:21 2003
+++ b/arch/i386/kernel/irq.c	Tue Feb  4 13:30:21 2003
@@ -68,6 +68,9 @@
 irq_desc_t irq_desc[NR_IRQS] __cacheline_aligned =
 	{ [0 ... NR_IRQS-1] = { 0, &no_irq_type, NULL, 0, SPIN_LOCK_UNLOCKED}};

+/* used to determine the culprits who disabled interrupts for a long time */ +int last_do_IRQ_interrupt[NR_CPUS] = { [0 ... NR_CPUS-1] = -1 }; +
static void register_irq_proc (unsigned int irq);

/*
@@ -328,6 +331,9 @@
irq_desc_t *desc = irq_desc + irq;
struct irqaction * action;
unsigned int status;
+
+ if(irq) /* don't count the timer */
+ last_do_IRQ_interrupt[cpu] = irq;

irq_enter();

diff -Nru a/arch/i386/kernel/time.c b/arch/i386/kernel/time.c
@@ -265,25 +265,39 @@
 #endif
 }
 
+static int report_lost_ticks;
+int __init report_lost_ticks_setup(char *str)
+{
+	char* numstr;
+	
+	if (str[0] == '=') {
+		numstr = &str[1];
+		return get_option(&numstr,&report_lost_ticks) ? 1 : 0;
+	} else if (str[0] == '\0') {
+		report_lost_ticks = 5;
+		return 1;
+	}
+
+	return 0;
+}
+
+__setup("report_lost_ticks", report_lost_ticks_setup);
+
 /*
  * Lost tick detection and compensation
  */
+extern int last_do_IRQ_interrupt[];
 static inline void detect_lost_tick(void)
 {
 	/* read time since last interrupt */
 	unsigned long delta = timer->get_offset();
-	static unsigned long dbg_print;
 	
 	/* check if delta is greater then two ticks */
 	if(delta >= 2*(1000000/HZ)){
 
-		/*
-		 * only print debug info first 5 times
-		 */
-		/*
-		 * AKPM: disable this for now; it's nice, but irritating.
-		 */
-		if (0 && dbg_print < 5) {
+		if(report_lost_ticks > 0){
+			int last_irq = last_do_IRQ_interrupt[smp_processor_id()];
+			struct irqaction * action;
 			printk(KERN_WARNING "\nWarning! Detected %lu "
 				"micro-second gap between interrupts.\n",
 				delta);

@@ -291,7 +305,16 @@
 				"ticks.\n",
 				delta/(1000000/HZ)-1);
 			dump_stack();
-			dbg_print++;
+
+			if(last_irq >= 0 && (action = irq_desc[last_irq].action)) {
+				printk(KERN_WARNING "  Last run common irq: %d: %s", 
+					last_irq, action->name);
+				for (action=action->next; action; action = action->next)
+					printk(", %s", action->name);
+				printk("\n");	
+			}
+
+			report_lost_ticks--;
 		}
 		/* calculate number of missed ticks */
 		delta = delta/(1000000/HZ)-1;