Re: LTTng finds abnormally long APIC interrupt handler : 58.2 ms


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 ?

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Relevant Pages