lkml.org 
[lkml]   [2010]   [Mar]   [1]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [GIT PULL] x86/cpu changes for v2.6.34

* Linus Torvalds <torvalds@linux-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@nehalem 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



\
 
 \ /
  Last update: 2010-03-01 09:03    [from the cache]
©2003-2011 Jasper Spaans