[ltt-dev] LTTng finds abnormally long APIC interrupt handler : 58.2 ms

[Steven Rostedt]

On Tue, 5 Aug 2008, Mathieu Desnoyers wrote:

> Hi,
> 
> I would like to bring an interesting kernel latency issue I am
> experiencing.
> 
> A trace taken with LTTng on a x86_64 dual quad-core, Linux kernel
> 2.6.26.1, shows that IRQ 239 handler (LOCAL_TIMER_VECTOR ->
> smp_apic_timer_interrupt) runs for about 58.2 ms on 2 of the 8 cores,
> and a bit later on the other 6. It can be repeated by taking a trace
> shortly after boot : it happens at about 120 seconds after the cycle
> counters has been reset.
> 
> The execution trace of one interrupt handler is (edited for clarity) :

Mathieu,

Have you tried using ftrace to see what functions are being called here?

-- Steve

> 
> Format :
> event name: timestamp
>   pid, tgid, process name, execution mode
>   { event data }
> 
> kernel_irq_entry: 121.733399510
>   0, 0, swapper, IRQ
>   { irq_id = 239, kernel_mode = 1, ip = 0xFFFFFFFF80213936 }
> kernel_softirq_raise: 121.733400143
>   0, 0, swapper, IRQ
>   { softirq_id = 1 [run_timer_softirq+0x0/0x230] }
> 
> (takes a while : 58.2 ms)
> 
> kernel_sched_try_wakeup: 121.791694536
>   0, 0, swapper, IRQ
>   { pid = 8, state = 1 }
> kernel_softirq_raise: 121.791696762
>   0, 0, swapper, IRQ
>   { softirq_id = 6 [run_rebalance_domains+0x0/0x6e0] }
> kernel_irq_exit: 121.791697692
>   0, 0, swapper, SYSCALL
>   { handled = 1 }
> 
> Where pid = 8  is kernel thread watchdog/1
> 
> The same trace happens on the other CPUs which also have a long
> interrupt handler. The surroundings of the problem points out to
> run_local_timers(), which is the function responsible for raising the
> TIMER_SOFTIRQ. (which is the last event that occurs on the system for a
> while). It could also be the caller : update_process_times(), any
> function called from update_process_times() after the run_local_timers()
> call or actually any function executing between the "raise" and the "try
> wakeup" events.
> 
> The kernel config is attached below, so is the dmesg.
> 
> Any idea regarding what is happening here ?
>