lkml.org 
[lkml]   [2003]   [Feb]   [4]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
Subject[PATCH] 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
haveblue@us.ibm.com

# 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
--- a/arch/i386/kernel/time.c Tue Feb 4 13:30:21 2003
+++ b/arch/i386/kernel/time.c Tue Feb 4 13:30:21 2003
@@ -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;
\
 
 \ /
  Last update: 2005-03-22 13:32    [W:0.034 / U:0.160 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site