2005-09-16 20:48:04

by folkert

[permalink] [raw]
Subject: printk timings stay weird, also waaay after 5 seconds

Hi,

I have a pc with a VIA Nehemiah. It runs kernel 2.6.13.1.
At boot of course the timings are high:
thegate:/home/folkert/public_html# dmesg | more
[42949372.960000] Linux version 2.6.13.1 (root@thegate) (gcc version 4.0.1 (Debian 4.0.1-2)) #1 Wed Sep 14 11:56:45 CEST 2005
[42949372.960000] BIOS-provided physical RAM map:
[42949372.960000] BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
...
but stay high:
[42949376.950000] NET: Registered protocol family 1
[42949378.810000] Adding 497972k swap on /dev/hda1. Priority:-1 extents:1
[42949378.910000] EXT3 FS on hda2, internal journal
[42949379.320000] Generic RTC Driver v1.07
[42949383.180000] Probing IDE interface ide1...
[42949385.100000] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 12
[42949385.100000] PCI: setting IRQ 12 as level-triggered
...
[42949626.430000] pwc Dumping frame 41 (last message).
[43132475.940000] pwc Closing video device: 1829087 frames received, dumped 554742 frames, 0 frames with errors.
[43132482.400000] pwc set_video_mode(320x240 @ 10, palette 15).
...
[43132483.920000] pwc Dumping frame 7.
[43132484.120000] pwc Dumping frame 9.

etc.


Folkert van Heusden

--
Try MultiTail! Multiple windows with logfiles, filtered with regular
expressions, colored output, etc. etc. http://www.vanheusden.com/multitail/
----------------------------------------------------------------------
Get your PGP/GPG key signed at http://www.biglumber.com!
----------------------------------------------------------------------
Phone: +31-6-41278122, PGP-key: 1F28D8AE, http://www.vanheusden.com


Attachments:
(No filename) (1.52 kB)
signature.asc (282.00 B)
Digital signature
Download all attachments

2005-09-16 20:55:45

by folkert

[permalink] [raw]
Subject: Re: printk timings stay weird, also waaay after 5 seconds

by the way: ALSO after a COLD boot these values are high:
[42949372.960000] Linux version 2.6.13.1 (root@thegate) (gcc version 4.0.1 (Debian 4.0.1-2)) #1 Wed Sep 14 11:56:45 CEST 2005
[42949372.960000] BIOS-provided physical RAM map:
[42949372.960000] BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
...
[42949376.200000] Freeing unused kernel memory: 140k freed
[42949377.170000] NET: Registered protocol family 1
[42949379.080000] Adding 497972k swap on /dev/hda1. Priority:-1 extents:1
[42949379.180000] EXT3 FS on hda2, internal journal
...
[42949421.150000] pwc Dumping frame 39 (last message).
[42949421.220000] pwc Dumping frame 38 (last message).
[42949425.770000] eth1: no IPv6 routers present

apart from this the computer runs fine without any segfaults, sigs11 or
reboots.

On Fri, Sep 16, 2005 at 10:47:59PM +0200, Folkert van Heusden wrote:
> Hi,
>
> I have a pc with a VIA Nehemiah. It runs kernel 2.6.13.1.
> At boot of course the timings are high:
> thegate:/home/folkert/public_html# dmesg | more
> [42949372.960000] Linux version 2.6.13.1 (root@thegate) (gcc version 4.0.1 (Debian 4.0.1-2)) #1 Wed Sep 14 11:56:45 CEST 2005
> [42949372.960000] BIOS-provided physical RAM map:
> [42949372.960000] BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
> ...
> but stay high:
> [42949376.950000] NET: Registered protocol family 1
> [42949378.810000] Adding 497972k swap on /dev/hda1. Priority:-1 extents:1
> [42949378.910000] EXT3 FS on hda2, internal journal
> [42949379.320000] Generic RTC Driver v1.07
> [42949383.180000] Probing IDE interface ide1...
> [42949385.100000] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 12
> [42949385.100000] PCI: setting IRQ 12 as level-triggered
> ...
> [42949626.430000] pwc Dumping frame 41 (last message).
> [43132475.940000] pwc Closing video device: 1829087 frames received, dumped 554742 frames, 0 frames with errors.
> [43132482.400000] pwc set_video_mode(320x240 @ 10, palette 15).
> ...
> [43132483.920000] pwc Dumping frame 7.
> [43132484.120000] pwc Dumping frame 9.
>
> etc.
>
>
> Folkert van Heusden
>
> --
> Try MultiTail! Multiple windows with logfiles, filtered with regular
> expressions, colored output, etc. etc. http://www.vanheusden.com/multitail/
> ----------------------------------------------------------------------
> Get your PGP/GPG key signed at http://www.biglumber.com!
> ----------------------------------------------------------------------
> Phone: +31-6-41278122, PGP-key: 1F28D8AE, http://www.vanheusden.com




Folkert van Heusden

--
Try MultiTail! Multiple windows with logfiles, filtered with regular
expressions, colored output, etc. etc. http://www.vanheusden.com/multitail/
----------------------------------------------------------------------
Get your PGP/GPG key signed at http://www.biglumber.com!
----------------------------------------------------------------------
Phone: +31-6-41278122, PGP-key: 1F28D8AE, http://www.vanheusden.com


Attachments:
(No filename) (2.85 kB)
signature.asc (282.00 B)
Digital signature
Download all attachments

2005-09-16 21:16:12

by Steven Rostedt

[permalink] [raw]
Subject: Re: printk timings stay weird, also waaay after 5 seconds

On Fri, 2005-09-16 at 22:55 +0200, Folkert van Heusden wrote:
> by the way: ALSO after a COLD boot these values are high:
> [42949372.960000] Linux version 2.6.13.1 (root@thegate) (gcc version 4.0.1 (Debian 4.0.1-2)) #1 Wed Sep 14 11:56:45 CEST 2005
> [42949372.960000] BIOS-provided physical RAM map:
> [42949372.960000] BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
> ...
> [42949376.200000] Freeing unused kernel memory: 140k freed
> [42949377.170000] NET: Registered protocol family 1
> [42949379.080000] Adding 497972k swap on /dev/hda1. Priority:-1 extents:1
> [42949379.180000] EXT3 FS on hda2, internal journal
> ...
> [42949421.150000] pwc Dumping frame 39 (last message).
> [42949421.220000] pwc Dumping frame 38 (last message).
> [42949425.770000] eth1: no IPv6 routers present

[Added CC from a similar thread "early printk timings way off"]

It's using the jiffies counter, and converting that into seconds.
Jiffies are always set to roll over soon, so the times will be high at
start up. If you switch to use the tsc as your timer (instead of HPET
or PM), you will get the time from tsc instead, and not only will they
be much smaller, but they will be much more precise (not the ms
resolution you have here, or is that 4ms resolution?).

Also, am I the only one that would prefer to always use the tsc (on x86)
for sched_clock when possible, no matter which timer I choose? I
usually put in hacks to make sched_clock always return the tsc, since it
is much better to see how long something takes, instead of seeing five
printks with the same time.

-- Steve