linux-kernel - Re: [GIT PULL] x86/cpu changes for v2.6.34

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: <20100301080058.GA8049@elte.hu>
Date:	Mon, 1 Mar 2010 09:00:58 +0100
From:	Ingo Molnar <mingo@...e.hu>
To:	Linus Torvalds <torvalds@...ux-foundation.org>,
	Steven Rostedt <rostedt@...dmis.org>,
	Fr??d??ric Weisbecker <fweisbec@...il.com>,
	Thomas Gleixner <tglx@...utronix.de>
Cc:	linux-kernel@...r.kernel.org, "H. Peter Anvin" <hpa@...or.com>,
	Thomas Gleixner <tglx@...utronix.de>,
	Borislav Petkov <borislav.petkov@....com>,
	Andrew Morton <akpm@...ux-foundation.org>
Subject: Re: [GIT PULL] x86/cpu changes for v2.6.34


* Linus Torvalds <torvalds@...ux-foundation.org> wrote:

> On Sun, 28 Feb 2010, Linus Torvalds wrote:
> > 
> > I haven't bisected this, but something slowed down in bootup on my machine 
> > recently.
> 
> Hmm. I take that back. It's not consistent, and it's not recent after all. 
> 
> It comes and goes:
> 
> 	[torvalds@...alem linux]$ grep "CPU 7 MCA" /var/log/messages-* /var/log/messages | cut -d: -f5-
> 	 [    0.898396] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898400] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    1.596240] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898394] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    1.600229] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898395] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.901211] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    2.633298] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898393] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.901210] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898395] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898393] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898393] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898402] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.901213] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898392] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898395] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    1.601467] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898401] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898395] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 	 [    0.898397] CPU 7 MCA banks SHD:2 SHD:3 SHD:5 SHD:6 SHD:8
> 
> note how it's pretty consistently at about the 0.89s mark, but then there's 
> a _couple_ of times when it's taken rather longer to boot. But the delay is 
> always in that CPU bringup phase, because doing the same grep for "CPU 0 
> MCA" gives consistently low numbers (0.0005s).

Weird. It seems to be around multiples of .8: 0.8, 1.6, 2.4, with some extra 
overhead.

Almost as if some calibration routine or some other busy-loop misses the train 
occasionally.

The way i'd go about debugging this is to narrow down the approximate place 
the slowdown happens, then enable CONFIG_FUNCTION_TRACER (and disable 
CONFIG_DYNAMIC_FTRACE=y, to not have to deal with the dynamic patching 
aspects), and do a single-shot tracing session of only that section, on only 
one CPU:

	if (smp_processor_id() == 7)
		ftrace_enabled = 1;

	... bootup sequence ...

	if (smp_processor_id() == 7)
		ftrace_enabled = 0;

And recover the resulting trace from /debug/tracing/trace - it should have the reason
in it plain and simple.

( Unfortunately i'm not 100% sure that setting ftrace_enabled to 1 is enough. 
  I asked for a simple ad-hoc enable/disable function tracing mechanism _ages_ 
  ago - Steve, Frederic, what happened to that? ftrace_start()/stop() does not 
  seem to allow that. )

Or you could sprinkle the code with printk's, and see where the overhead 
concentrates into. (But printks ca change timings - etc. So can the function 
tracer as well ...)

	Ingo

--
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/