Messages in this thread | | | Date | Mon, 1 Mar 2010 09:00:58 +0100 | From | Ingo Molnar <> | Subject | Re: [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
| |