Re: early printk timings way off

[Tim Schmielau]

On Fri, 16 Sep 2005, Jesper Juhl wrote:

> On 9/15/05, Randy.Dunlap <rdunlap@xxxxxxxxxxxx> wrote:
> > On Thu, 15 Sep 2005, Jesper Juhl wrote:
> >
> > > Early during boot the printk timings are way off :
> > >
[...]
> > > [4294667.296000] Initializing CPU#0
> > > [4294667.296000] CPU 0 irqstacks, hard=c03d2000 soft=c03d1000
> > > [4294667.296000] PID hash table entries: 2048 (order: 11, 32768 bytes)
> > >
> > > ^^^^^ These I can buy as the result of an uninitialized variable. Why are
> > >       we not initializing this counter to zero?
> > >
> > > [    0.000000] Detected 1400.279 MHz processor.
> > >
> > > ^^^^^ Ok, we finally seem to have initialized the counter...
> > >
> > > [   27.121583] Using tsc for high-res timesource
> > >
> > > ^^^^^ 27 seconds??? Something is off here. It certainly doesn't take 27 sec
> > >       to get from the previous message to this one during the actual boot.
> > >       What's up with that?
> > >
> > > [   27.121620] Console: colour dummy device 80x25
> > > [   27.122909] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
> > > ...
> > >
> > > No big deal, but it sure would look better (and be actually useful for the
> > > first few messages) if things started out at zero and then actually
> > > increased sanely from the very beginning.  :-)
> >
> > For purposes of testing rollover and/or finding broken drivers etc.,
> > jiffies is init to something like -5 seconds (or max_jiffies - 5)
> > and then it rolls over soon.

Yep, 4294667.296 = 2^32/1000-300 is exactly the value jiffies gets
initialized to on i386. Supposedly subtraction of INITIAL_JIFFIES is
missing here.

> I'm aware of that fact, but I thought the printk timings were supposed
> to be releative to the kernel starting - surely the known initial
> value of jiffies could be accounted/corrected for when printing the
> timing values.  Also, that still doesn't explain why the first many
> lines seem to be just printing some fixed value (my guess is an
> uninitialized var, but I haven't actually looked). It also doesn't
> explain why two lines, the first with timing value 0.000, and the next
> with 27.121 don't seem to match reality - the *actual* delta between
> printing those two lines is far lower than 27 seconds.

Yes, this seems to be different, possibly unrelated problem.
It's interesting that the value jumps _exactly_to_zero_, though.
Will need to dig into the code...

Tim
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/