make lost-tick detection more informative
PATCH 1/1 make lost-tick detection more informative
The new lost-tick detection code is pretty cool, but it 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.
There are no guarantees here. If preemption is enabled, all bets are off, and this data could be incorrect. It would be relatively silly to disable preemption, just to get some debugging data to be more accurate.
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
Signature · 2 lines
Dave Hansen [email protected]
arch/i386/kernel/irq.c +6 -0
@@ -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);/*
@@ -330,6 +333,9 @@struct irqaction * action;unsigned int status; +if (irq)/* don't count the timer */ + last_do_IRQ_interrupt[cpu] = irq; +irq_enter ();#ifdef CONFIG_DEBUG_STACKOVERFLOW
arch/i386/kernel/time.c +10 -1
@@ -267,7 +267,7 @@#endif } - +extern int last_do_IRQ_interrupt[];/* Lost tick detection and compensation */ static inline void detect_lost_tick (void ) {
@@ -280,12 +280,21 @@/* only print debug info first 5 times */ if (dbg_print <5 ){ +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);printk (KERN_WARNING " Compensating for %lu lost ticks.\n" , delta/(1000000 /HZ )-1 );/* dump trace info */ show_trace (NULL ); +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" ); + } dbg_print++; }/* calculate number of missed ticks */
Quoted 2 lines · Dave Hansen
The new lost-tick detection code is pretty cool,
I've actually disabled it in -mmnext, because I get too much mail already.
If you want to slap this on top of that and some new kernel-hacking debug config option, that would be neat.
arch/i386/kernel/time.c | 36 ++++++++++++++++++++++++++++++++++++ 1 files changed, 36 insertions(+)
arch/i386/kernel/time.c renamed from arch/i386/kernel/time.c~lost-tick +36 -0
@@ -266,6 +266,41 @@ static inline void do_timer_interrupt(in }/* +* Lost tick detection and compensation +*/ +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 ) { +printk (KERN_WARNING "\nWarning! Detected %lu " +"micro-second gap between interrupts.\n" , + delta); +printk (KERN_WARNING " Compensating for %lu lost " +"ticks.\n" , + delta/(1000000 /HZ )-1 ); +dump_stack (); + dbg_print++; + } +/* calculate number of missed ticks */ + delta = delta/(1000000 /HZ )-1 ; + jiffies += delta; + } + +} + +/* * This is the same as the above, except we _also_ save the current * Time Stamp Counter value at the time of the timer interrupt, so that * we later on can estimate the time of day more exactly.
@@ -281,6 +316,7 @@ void timer_interrupt(int irq, void *dev_*/ write_lock (&xtime_lock); +detect_lost_tick (); timer->mark_offset ();do_timer_interrupt (irq,NULL , regs);
_