linux-kernel - Re: LTTng finds abnormally long APIC interrupt handler : 58.2 ms

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <alpine.DEB.1.10.0808051523370.28170@gandalf.stny.rr.com>
Date:	Tue, 5 Aug 2008 15:24:33 -0400 (EDT)
From:	Steven Rostedt <rostedt@...dmis.org>
To:	Mathieu Desnoyers <mathieu.desnoyers@...ymtl.ca>
cc:	Ingo Molnar <mingo@...e.hu>, Thomas Gleixner <tglx@...utronix.de>,
	James Bottomley <James.Bottomley@...senPartnership.com>,
	akpm@...ux-foundation.org, Peter Zijlstra <peterz@...radead.org>,
	linux-kernel@...r.kernel.org, ltt-dev@...ts.casi.polymtl.ca
Subject: 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@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/