early printk timings way off

early printk timings way off

[Jesper Juhl]

Early during boot the printk timings are way off : 

[4294667.296000] Linux version 2.6.14-rc1-git1 (juhl@dragon) (gcc version 3.3.6) #1 PREEMPT Thu Sep 15 22:25:37 CEST 2005
[4294667.296000] BIOS-provided physical RAM map:
[4294667.296000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
[4294667.296000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
[4294667.296000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
[4294667.296000]  BIOS-e820: 0000000000100000 - 000000001ffec000 (usable)
[4294667.296000]  BIOS-e820: 000000001ffec000 - 000000001ffef000 (ACPI data)
[4294667.296000]  BIOS-e820: 000000001ffef000 - 000000001ffff000 (reserved)
[4294667.296000]  BIOS-e820: 000000001ffff000 - 0000000020000000 (ACPI NVS)
[4294667.296000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
[4294667.296000] 511MB LOWMEM available.
[4294667.296000] On node 0 totalpages: 131052
[4294667.296000]   DMA zone: 4096 pages, LIFO batch:1
[4294667.296000]   Normal zone: 126956 pages, LIFO batch:31
[4294667.296000]   HighMem zone: 0 pages, LIFO batch:1
[4294667.296000] DMI 2.3 present.
[4294667.296000] ACPI: RSDP (v000 ASUS                                  ) @ 0x000f69e0
[4294667.296000] ACPI: RSDT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec000
[4294667.296000] ACPI: FADT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec080
[4294667.296000] ACPI: BOOT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec040
[4294667.296000] ACPI: DSDT (v001   ASUS A7M266   0x00001000 MSFT 0x0100000b) @ 0x00000000
[4294667.296000] Allocating PCI resources starting at 30000000 (gap: 20000000:dfff0000)
[4294667.296000] Built 1 zonelists
[4294667.296000] Kernel command line: auto BOOT_IMAGE=2.6.14-rc1-git1 ro root=801 pci=usepirqmask
[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.  :-)


-- 
 Jesper Juhl <jesper.juhl@gmail.com>

Re: early printk timings way off

[Randy.Dunlap]

On Thu, 15 Sep 2005, Jesper Juhl wrote:

> Early during boot the printk timings are way off :
>
> [4294667.296000] Linux version 2.6.14-rc1-git1 (juhl@dragon) (gcc version 3.3.6) #1 PREEMPT Thu Sep 15 22:25:37 CEST 2005
> [4294667.296000] BIOS-provided physical RAM map:
> [4294667.296000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
> [4294667.296000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
> [4294667.296000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
> [4294667.296000]  BIOS-e820: 0000000000100000 - 000000001ffec000 (usable)
> [4294667.296000]  BIOS-e820: 000000001ffec000 - 000000001ffef000 (ACPI data)
> [4294667.296000]  BIOS-e820: 000000001ffef000 - 000000001ffff000 (reserved)
> [4294667.296000]  BIOS-e820: 000000001ffff000 - 0000000020000000 (ACPI NVS)
> [4294667.296000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
> [4294667.296000] 511MB LOWMEM available.
> [4294667.296000] On node 0 totalpages: 131052
> [4294667.296000]   DMA zone: 4096 pages, LIFO batch:1
> [4294667.296000]   Normal zone: 126956 pages, LIFO batch:31
> [4294667.296000]   HighMem zone: 0 pages, LIFO batch:1
> [4294667.296000] DMI 2.3 present.
> [4294667.296000] ACPI: RSDP (v000 ASUS                                  ) @ 0x000f69e0
> [4294667.296000] ACPI: RSDT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec000
> [4294667.296000] ACPI: FADT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec080
> [4294667.296000] ACPI: BOOT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec040
> [4294667.296000] ACPI: DSDT (v001   ASUS A7M266   0x00001000 MSFT 0x0100000b) @ 0x00000000
> [4294667.296000] Allocating PCI resources starting at 30000000 (gap: 20000000:dfff0000)
> [4294667.296000] Built 1 zonelists
> [4294667.296000] Kernel command line: auto BOOT_IMAGE=2.6.14-rc1-git1 ro root=801 pci=usepirqmask
> [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.

-- 
~Randy

Re: early printk timings way off

[Jesper Juhl]

On 9/15/05, Randy.Dunlap <rdunlap@xenotime.net> wrote:
> On Thu, 15 Sep 2005, Jesper Juhl wrote:
> 
> > Early during boot the printk timings are way off :
> >
> > [4294667.296000] Linux version 2.6.14-rc1-git1 (juhl@dragon) (gcc version 3.3.6) #1 PREEMPT Thu Sep 15 22:25:37 CEST 2005
> > [4294667.296000] BIOS-provided physical RAM map:
> > [4294667.296000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
> > [4294667.296000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
> > [4294667.296000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
> > [4294667.296000]  BIOS-e820: 0000000000100000 - 000000001ffec000 (usable)
> > [4294667.296000]  BIOS-e820: 000000001ffec000 - 000000001ffef000 (ACPI data)
> > [4294667.296000]  BIOS-e820: 000000001ffef000 - 000000001ffff000 (reserved)
> > [4294667.296000]  BIOS-e820: 000000001ffff000 - 0000000020000000 (ACPI NVS)
> > [4294667.296000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
> > [4294667.296000] 511MB LOWMEM available.
> > [4294667.296000] On node 0 totalpages: 131052
> > [4294667.296000]   DMA zone: 4096 pages, LIFO batch:1
> > [4294667.296000]   Normal zone: 126956 pages, LIFO batch:31
> > [4294667.296000]   HighMem zone: 0 pages, LIFO batch:1
> > [4294667.296000] DMI 2.3 present.
> > [4294667.296000] ACPI: RSDP (v000 ASUS                                  ) @ 0x000f69e0
> > [4294667.296000] ACPI: RSDT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec000
> > [4294667.296000] ACPI: FADT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec080
> > [4294667.296000] ACPI: BOOT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec040
> > [4294667.296000] ACPI: DSDT (v001   ASUS A7M266   0x00001000 MSFT 0x0100000b) @ 0x00000000
> > [4294667.296000] Allocating PCI resources starting at 30000000 (gap: 20000000:dfff0000)
> > [4294667.296000] Built 1 zonelists
> > [4294667.296000] Kernel command line: auto BOOT_IMAGE=2.6.14-rc1-git1 ro root=801 pci=usepirqmask
> > [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.
> 

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.


-- 
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: early printk timings way off

[Randy.Dunlap]

On Fri, 16 Sep 2005, Jesper Juhl wrote:

> On 9/15/05, Randy.Dunlap <rdunlap@xenotime.net> wrote:
> > On Thu, 15 Sep 2005, Jesper Juhl wrote:
> >
> > > Early during boot the printk timings are way off :
> > >
> > > [4294667.296000] Linux version 2.6.14-rc1-git1 (juhl@dragon) (gcc version 3.3.6) #1 PREEMPT Thu Sep 15 22:25:37 CEST 2005
> > > [4294667.296000] BIOS-provided physical RAM map:
> > > [4294667.296000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
> > > [4294667.296000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
> > > [4294667.296000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
> > > [4294667.296000]  BIOS-e820: 0000000000100000 - 000000001ffec000 (usable)
> > > [4294667.296000]  BIOS-e820: 000000001ffec000 - 000000001ffef000 (ACPI data)
> > > [4294667.296000]  BIOS-e820: 000000001ffef000 - 000000001ffff000 (reserved)
> > > [4294667.296000]  BIOS-e820: 000000001ffff000 - 0000000020000000 (ACPI NVS)
> > > [4294667.296000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
> > > [4294667.296000] 511MB LOWMEM available.
> > > [4294667.296000] On node 0 totalpages: 131052
> > > [4294667.296000]   DMA zone: 4096 pages, LIFO batch:1
> > > [4294667.296000]   Normal zone: 126956 pages, LIFO batch:31
> > > [4294667.296000]   HighMem zone: 0 pages, LIFO batch:1
> > > [4294667.296000] DMI 2.3 present.
> > > [4294667.296000] ACPI: RSDP (v000 ASUS                                  ) @ 0x000f69e0
> > > [4294667.296000] ACPI: RSDT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec000
> > > [4294667.296000] ACPI: FADT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec080
> > > [4294667.296000] ACPI: BOOT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec040
> > > [4294667.296000] ACPI: DSDT (v001   ASUS A7M266   0x00001000 MSFT 0x0100000b) @ 0x00000000
> > > [4294667.296000] Allocating PCI resources starting at 30000000 (gap: 20000000:dfff0000)
> > > [4294667.296000] Built 1 zonelists
> > > [4294667.296000] Kernel command line: auto BOOT_IMAGE=2.6.14-rc1-git1 ro root=801 pci=usepirqmask
> > > [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.
> >
>
> 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.

OK, thanks for the extended explanation.  Good luck.  8:)

-- 
~Randy

Re: early printk timings way off

[Jesper Juhl]

On 9/16/05, Randy.Dunlap <rdunlap@xenotime.net> wrote:
> On Fri, 16 Sep 2005, Jesper Juhl wrote:
> 
> > On 9/15/05, Randy.Dunlap <rdunlap@xenotime.net> wrote:
> > > On Thu, 15 Sep 2005, Jesper Juhl wrote:
> > >
> > > > Early during boot the printk timings are way off :
> > > >
> > > > [4294667.296000] Linux version 2.6.14-rc1-git1 (juhl@dragon) (gcc version 3.3.6) #1 PREEMPT Thu Sep 15 22:25:37 CEST 2005
> > > > [4294667.296000] BIOS-provided physical RAM map:
> > > > [4294667.296000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
> > > > [4294667.296000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
> > > > [4294667.296000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
> > > > [4294667.296000]  BIOS-e820: 0000000000100000 - 000000001ffec000 (usable)
> > > > [4294667.296000]  BIOS-e820: 000000001ffec000 - 000000001ffef000 (ACPI data)
> > > > [4294667.296000]  BIOS-e820: 000000001ffef000 - 000000001ffff000 (reserved)
> > > > [4294667.296000]  BIOS-e820: 000000001ffff000 - 0000000020000000 (ACPI NVS)
> > > > [4294667.296000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
> > > > [4294667.296000] 511MB LOWMEM available.
> > > > [4294667.296000] On node 0 totalpages: 131052
> > > > [4294667.296000]   DMA zone: 4096 pages, LIFO batch:1
> > > > [4294667.296000]   Normal zone: 126956 pages, LIFO batch:31
> > > > [4294667.296000]   HighMem zone: 0 pages, LIFO batch:1
> > > > [4294667.296000] DMI 2.3 present.
> > > > [4294667.296000] ACPI: RSDP (v000 ASUS                                  ) @ 0x000f69e0
> > > > [4294667.296000] ACPI: RSDT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec000
> > > > [4294667.296000] ACPI: FADT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec080
> > > > [4294667.296000] ACPI: BOOT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec040
> > > > [4294667.296000] ACPI: DSDT (v001   ASUS A7M266   0x00001000 MSFT 0x0100000b) @ 0x00000000
> > > > [4294667.296000] Allocating PCI resources starting at 30000000 (gap: 20000000:dfff0000)
> > > > [4294667.296000] Built 1 zonelists
> > > > [4294667.296000] Kernel command line: auto BOOT_IMAGE=2.6.14-rc1-git1 ro root=801 pci=usepirqmask
> > > > [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.
> > >
> >
> > 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.
> 
> OK, thanks for the extended explanation.  Good luck.  8:)
> 

Ok, I don't quite know how to interpret that comment, but I'm going to
read it as "if you think this is a problem then go find a solution
yourself" - would that be fairly accurate?

It doesn't really bother me much, I just find the behaviour odd. I
haven't bothered to actually look at the code responsible for it yet
(since it really is not that big of a deal), but I just wanted to
point it out and hoped that maybe someone could give me a reason for
why it is as it is...

-- 
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: early printk timings way off

[Randy.Dunlap]

On Fri, 16 Sep 2005, Jesper Juhl wrote:

> On 9/16/05, Randy.Dunlap <rdunlap@xenotime.net> wrote:
> > On Fri, 16 Sep 2005, Jesper Juhl wrote:
> >
> > > On 9/15/05, Randy.Dunlap <rdunlap@xenotime.net> wrote:
> > > > On Thu, 15 Sep 2005, Jesper Juhl wrote:
> > > >
> > > > > Early during boot the printk timings are way off :
> > > > >
> > > > > [4294667.296000] Linux version 2.6.14-rc1-git1 (juhl@dragon) (gcc version 3.3.6) #1 PREEMPT Thu Sep 15 22:25:37 CEST 2005
> > > > > [4294667.296000] BIOS-provided physical RAM map:
> > > > > [4294667.296000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
> > > > > [4294667.296000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
> > > > > [4294667.296000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
> > > > > [4294667.296000]  BIOS-e820: 0000000000100000 - 000000001ffec000 (usable)
> > > > > [4294667.296000]  BIOS-e820: 000000001ffec000 - 000000001ffef000 (ACPI data)
> > > > > [4294667.296000]  BIOS-e820: 000000001ffef000 - 000000001ffff000 (reserved)
> > > > > [4294667.296000]  BIOS-e820: 000000001ffff000 - 0000000020000000 (ACPI NVS)
> > > > > [4294667.296000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
> > > > > [4294667.296000] 511MB LOWMEM available.
> > > > > [4294667.296000] On node 0 totalpages: 131052
> > > > > [4294667.296000]   DMA zone: 4096 pages, LIFO batch:1
> > > > > [4294667.296000]   Normal zone: 126956 pages, LIFO batch:31
> > > > > [4294667.296000]   HighMem zone: 0 pages, LIFO batch:1
> > > > > [4294667.296000] DMI 2.3 present.
> > > > > [4294667.296000] ACPI: RSDP (v000 ASUS                                  ) @ 0x000f69e0
> > > > > [4294667.296000] ACPI: RSDT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec000
> > > > > [4294667.296000] ACPI: FADT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec080
> > > > > [4294667.296000] ACPI: BOOT (v001 ASUS   A7M266   0x30303031 MSFT 0x31313031) @ 0x1ffec040
> > > > > [4294667.296000] ACPI: DSDT (v001   ASUS A7M266   0x00001000 MSFT 0x0100000b) @ 0x00000000
> > > > > [4294667.296000] Allocating PCI resources starting at 30000000 (gap: 20000000:dfff0000)
> > > > > [4294667.296000] Built 1 zonelists
> > > > > [4294667.296000] Kernel command line: auto BOOT_IMAGE=2.6.14-rc1-git1 ro root=801 pci=usepirqmask
> > > > > [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.
> > > >
> > >
> > > 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.
> >
> > OK, thanks for the extended explanation.  Good luck.  8:)
> >
>
> Ok, I don't quite know how to interpret that comment, but I'm going to
> read it as "if you think this is a problem then go find a solution
> yourself" - would that be fairly accurate?

Yes, that's close.  I have "bigger fish to fry" is another way.

> It doesn't really bother me much, I just find the behaviour odd. I
> haven't bothered to actually look at the code responsible for it yet
> (since it really is not that big of a deal), but I just wanted to
> point it out and hoped that maybe someone could give me a reason for
> why it is as it is...

ISTM that there have been a few other comments about it, but I'm
not sure.  Maybe Tim Bird (Sony, CELF) would recall.

-- 
~Randy

Re: early printk timings way off

[Jesper Juhl]

On 9/16/05, Randy.Dunlap <rdunlap@xenotime.net> wrote:
[snip]
> > >
> > > OK, thanks for the extended explanation.  Good luck.  8:)
> > >
> >
> > Ok, I don't quite know how to interpret that comment, but I'm going to
> > read it as "if you think this is a problem then go find a solution
> > yourself" - would that be fairly accurate?
> 
> Yes, that's close.  I have "bigger fish to fry" is another way.
> 
Ok, thanks. English is not my native language and sometimes the actual
meaning of sarcasm, slang etc escapes me...

> > It doesn't really bother me much, I just find the behaviour odd. I
> > haven't bothered to actually look at the code responsible for it yet
> > (since it really is not that big of a deal), but I just wanted to
> > point it out and hoped that maybe someone could give me a reason for
> > why it is as it is...
> 
> ISTM that there have been a few other comments about it, but I'm
> not sure.  Maybe Tim Bird (Sony, CELF) would recall.
> 

I'll just dig into it myself for now, but thank you, if I get really
stuck I may ask him.


-- 
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: early printk timings way off

[Rogier Wolff]

On Fri, Sep 16, 2005 at 01:00:45AM +0200, Jesper Juhl wrote:
> 
> I'll just dig into it myself for now, but thank you, if I get really
> stuck I may ask him.

The explanation: "jiffies starts at rollover minus a bit" seems to be
spot-on: If jiffies are 32bit, and counting at 1000 per second, the
2^32 / 1000 works out. 

I expect the kernel to run without turning on (timer) interrupts for a
while during boot: It is still initializing things like memory and the
processor. Without those, interrupts won't work. This means that the
timer interrupt will not count in real-time.

A "jump" of 27 seconds seems unlikely, except if somehow the
interrupts are somehow accounted. It could very well be that the
kernel nowadays has a mechanism of measuring the fact that it missed a
timer interrupt and corrects for that. This would mean that around the
"jump", the kernel suddenly realized it missed around 27000 interrupts
and added 27000 to "jiffies"....

I'd say: Would be nice to get the timings right, but not worth the
trouble: There are good technical reasons for the observed facts.

	Roger. 

-- 
** R.E.Wolff@BitWizard.nl ** http://www.BitWizard.nl/ ** +31-15-2600998 **
*-- BitWizard writes Linux device drivers for any device you may have! --*
Q: It doesn't work. A: Look buddy, doesn't work is an ambiguous statement. 
Does it sit on the couch all day? Is it unemployed? Please be specific! 
Define 'it' and what it isn't doing. --------- Adapted from lxrbot FAQ

Re: early printk timings way off

[Jesper Juhl]

On 9/16/05, Rogier Wolff <R.E.Wolff@bitwizard.nl> wrote:
> On Fri, Sep 16, 2005 at 01:00:45AM +0200, Jesper Juhl wrote:
> >
> > I'll just dig into it myself for now, but thank you, if I get really
> > stuck I may ask him.
> 
> The explanation: "jiffies starts at rollover minus a bit" seems to be
> spot-on: If jiffies are 32bit, and counting at 1000 per second, the
> 2^32 / 1000 works out.
> 
> I expect the kernel to run without turning on (timer) interrupts for a
> while during boot: It is still initializing things like memory and the
> processor. Without those, interrupts won't work. This means that the
> timer interrupt will not count in real-time.
> 
> A "jump" of 27 seconds seems unlikely, except if somehow the
> interrupts are somehow accounted. It could very well be that the
> kernel nowadays has a mechanism of measuring the fact that it missed a
> timer interrupt and corrects for that. This would mean that around the
> "jump", the kernel suddenly realized it missed around 27000 interrupts
> and added 27000 to "jiffies"....
> 
> I'd say: Would be nice to get the timings right, but not worth the
> trouble: There are good technical reasons for the observed facts.
> 
Thank you for that explanation Rogier.

-- 
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: early printk timings way off

[Tim Bird]

Jesper Juhl wrote:
>>>>>Early during boot the printk timings are way off :
>>>>>
>>>>>[4294667.296000] Linux version 2.6.14-rc1-git1 (juhl@dragon)
>
> (gcc version 3.3.6) #1 PREEMPT Thu Sep 15 22:25:37 CEST 2005
>
>>>>>[4294667.296000] BIOS-provided physical RAM map:
>>>>>[4294667.296000]  BIOS-e820: 0000000000000000 - 000000000009f800

> It doesn't really bother me much, I just find the behaviour odd. I
> haven't bothered to actually look at the code responsible for it yet
> (since it really is not that big of a deal), but I just wanted to
> point it out and hoped that maybe someone could give me a reason for
> why it is as it is...
>

Since I was the one that put this code there, I can explain some of it,
and the rationale for why it works the way it does.

On most platforms, this code uses sched_clock(), which may or may not
be initialized until after init_time().  On x86 (a common platform),
this usually ends up calling read_tsc(), which uses the current
TSC value for the machine.  On a reboot (or warm reset), this
value is not re-initialized, so you see really high values.
If you're seeing this high number on a cold boot, then I'm not sure
where it's coming from.

The reason this was not normalized to 0 on x86 was because during
a cold boot, you can use the value to determine time from actual
cold start, rather than just kernel start.  This is useful for
measuring firmware startup time.  There are other platforms which
use a firmware-initialized timer source, for the same purpose.

In my own usage of this, I usually post-process the data with
scripts/show_delta, which gives reasonable deltas for all of the
lines except where there are anomolies due to clock initialization,
etc. Thus, the bogus absolutes on startup didn't bother me too much.

I know that this timing data is now being used for lots of other
purposes (which I think is great), so if improvements are desired
in the early handling of this, I would be happy to see changes
and/or help out.

UPDATE:
[Based on Tim Schmielau's analysis, maybe it's not the raw TSC
value, but an unititialized jiffy value coming back from sched_clock().
In this case, the value is worthless until after time_init().
This may be why you're seeing a jump in the first "real" value
returned.
Previously on x86, the pre-time_init() value was useful (wrong as an absolute
number, but right in relatives values.)

I'll try to take a look at this.]

Regards,
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Electronics
=============================

Re: early printk timings way off

[Tim Schmielau]

On Fri, 16 Sep 2005, Tim Bird wrote:

> UPDATE:
> [Based on Tim Schmielau's analysis, maybe it's not the raw TSC
> value, but an unititialized jiffy value coming back from sched_clock().
> In this case, the value is worthless until after time_init().

Well, it's not uninitialized, but initialized to a very high value. So 
the differences between the large values still contain useful information.

> This may be why you're seeing a jump in the first "real" value
> returned.

Yep.

> Previously on x86, the pre-time_init() value was useful (wrong as an absolute
> number, but right in relatives values.)

This should still be the case.


So, one jump (probably the first) happens when time_init sets use_tsc.
Do we understand the other jump as well?

Tim

Re: early printk timings way off

[Tim Schmielau]

On Fri, 16 Sep 2005, Tim Schmielau wrote:

> So, one jump (probably the first) happens when time_init sets use_tsc.
> Do we understand the other jump as well?

OK, looking at the numbers we have just one time-jump:

> [4294667.296000] CPU 0 irqstacks, hard=c03d2000 soft=c03d1000
> [4294667.296000] PID hash table entries: 2048 (order: 11, 32768 bytes)
> [    0.000000] Detected 1400.279 MHz processor.
> [   27.121583] Using tsc for high-res timesource
> [   27.121620] Console: colour dummy device 80x25
> [   27.122909] Dentry cache hash table entries: 131072 (order: 7, 524288

The "Detected 1400.279 MHz processor." line just happens to be written
_during_ time_init, when use_tsc is already set, but cycles_2_ns is not
yet initialized.

So I think everything is well-understood. It's just a matter of whether 
it's worth fixing.

Tim

Re: early printk timings way off

[Tim Bird]

Tim Schmielau wrote:
> On Fri, 16 Sep 2005, Tim Schmielau wrote:
> The "Detected 1400.279 MHz processor." line just happens to be written
> _during_ time_init, when use_tsc is already set, but cycles_2_ns is not
> yet initialized.

That's exactly what I surmised as well.  Our e-mails must
have crossed each other.  :-)

> So I think everything is well-understood. It's just a matter of whether 
> it's worth fixing.

Exactly.  My own testing has focused on bootup time measurement.
Historically, the time spent before time_init() has been relatively
small and so I haven't (often) focused on trying to measure it
accurately.  Although, I have done this on occasion to get
complete results.

Andrew's suggestion of a replaceable clock function would
satisfy me.  What do other's think?

 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Electronics
=============================

Re: early printk timings way off

[Tony Luck]

> Andrew's suggestion of a replaceable clock function would
> satisfy me.  What do other's think?

Yes please! (on ia64 we cannot use early printk() because our implementation
of sched_clock() accesses per-cpu memory, which is not mapped until long
after the first call to printk()).

-Tony

Re: early printk timings way off

[Tim Bird]

Tim Schmielau wrote:
> So, one jump (probably the first) happens when time_init sets use_tsc.
> Do we understand the other jump as well?

I haven't specifically tested, but I'd put good money on it being
a result of the initialization of cyc2ns_scale.  Before this
is set, cycles_2_ns() returns 0 (which would explain the _exactly_
0 value).  The value of 27.<something> seconds is very likely the
real value based on the TSC (which would mean the BIOS took
a good long time during boot).

So, in summary, this is probably what's happening:

 * from start_kernel - sched_clock() returns jiffies_64 (which
  is pre-initialized high and is not incrementing yet)
 * when use_tsc is set, sched_clock returns 0, until
 * when cyc2ns_scale is set, sched_clock returns TSC-based values,
  representing time from cold machine start

On other platforms, I have sometimes replaced the call to sched_clock()
in printk() with something else that gives valid data from the very first
kernel instruction.

A while ago Andrew Morton said that maybe the clock used here should be
replaceable, using something like the code below.  Does anyone know
if someone worked on this.  If not I'll take a stab at submitting it.

--- devel/kernel/printk.c~printk_clock	2005-08-21 02:14:05.000000000
-0700
+++ devel-akpm/kernel/printk.c	2005-08-21 02:15:14.000000000 -0700
@@ -488,6 +488,11 @@ static int __init printk_time_setup(char

 __setup("time", printk_time_setup);

+__attribute__((weak)) unsigned long long printk_clock(void)
+{
+	return sched_clock();
+}
+
 /*
  * This is printk.  It can be called from any context.  We want it to
work.
  *
@@ -558,7 +563,7 @@ asmlinkage int vprintk(const char *fmt,
 					loglev_char =
default_message_loglevel
 						+ '0';
 				}
-				t = sched_clock();
+				t = printk_clock();
 				nanosec_rem = do_div(t, 1000000000);
 				tlen = sprintf(tbuf,
 						"<%c>[%5lu.%06lu] ",

Regards,
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Electronics
=============================

Re: early printk timings way off

[Tim Schmielau]

On Fri, 16 Sep 2005, Jesper Juhl wrote:

> On 9/15/05, Randy.Dunlap <rdunlap@xenotime.net> 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

Re: early printk timings way off

[Tim Schmielau]

On Fri, 16 Sep 2005, Tim Schmielau wrote:

> On Fri, 16 Sep 2005, Jesper Juhl wrote:
> > 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...

Did that.
The problem is that printk uses sched_clock() to determine the time, which
just isn't supposed to be a reliable long-time clock. We need to base the
output on a different clock.

Btw, the rate-limiting logic in printk.c looks 'interesting'. Will look
into that, too.

Tim

Re: early printk timings way off

[Jesper Juhl]

On 9/16/05, Tim Schmielau <tim@physik3.uni-rostock.de> wrote:
> On Fri, 16 Sep 2005, Tim Schmielau wrote:
> 
> > On Fri, 16 Sep 2005, Jesper Juhl wrote:
> > > 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...
> 
> Did that.
> The problem is that printk uses sched_clock() to determine the time, which
> just isn't supposed to be a reliable long-time clock. We need to base the
> output on a different clock.
> 
> Btw, the rate-limiting logic in printk.c looks 'interesting'. Will look
> into that, too.
> 

Thanks Tim, much appreciated.

-- 
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html