lkml.org 
[lkml]   [2008]   [Aug]   [5]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: 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 ?
>


\
 
 \ /
  Last update: 2008-08-05 21:27    [W:0.088 / U:0.280 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site