Latest working kernel version:2.6.24 Earliest failing kernel version:2.6.25 Distribution:RHEL4 Hardware Environment:HP DL380G4 and IBM x3650 Software Environment:RHEL4 64-Bit Userland Problem Description: After booting a 2.6.25 kernel, the dmesg timestamps show two problems a) the jump back and forth, even long after startup b) they are much to small, no more meaning "seconds after bootup" For config, dmesg and discussion please see: http://www.ussg.iu.edu/hypermail/linux/kernel/0804.2/1144.html http://www.ussg.iu.edu/hypermail/linux/kernel/0805.0/3288.html http://www.ussg.iu.edu/hypermail/linux/kernel/0805.1/0272.html Steps to reproduce: Configure 2.6.25 kernel with dmesg-timestamps enabled and boot up.
Created attachment 16081 [details] Working 2.6.24 konfig This ist the config of my working 2.6.24 system. Ingnore the messages from nfs at the end. They are unrelated.
Created attachment 16082 [details] Config of 2.6.25 This ist the config for 2.6.25 that shows the described problem
Created attachment 16083 [details] dmesg from working 2.6.24 This is the dmesg output from 2.6.24. The timestamps are meaningfull and stable. Please ignore the nfs messages at the end. They are unrelated.
Created attachment 16084 [details] Dmesg of 2.6.25.2 bootup, showing the problem This is the dmesg from a 2.6.25 bootup. timestamps are to small and jumping. Main differenece to 2.6.24 is that TSC is synced against PM_TIMER instead of HPET and that HPET seems to be detected later in the boot process.
It seemes that the following change to kernel/printk.c causes the problems: @@ -680,7 +742,7 @@ loglev_char = default_message_loglevel + '0'; } - t = printk_clock(); + t = cpu_clock(printk_cpu); nanosec_rem = do_div(t, 1000000000); tlen = sprintf(tbuf, "<%c>[%5lu.%06lu] ", In 2.6.24, printk_clock() translates into sched_clock(). If I call sched_clock() in 2.6.25 instead of cpu_clock(), the dmesg timestamps are back to the expected behaviour. So, something in cpu_clock() seems to be broken. Hope this helps. Martin PS: Ignore the NFS comment on the 2.6.24 config. It was ment for the 2.6.24 dmesg :-(
Ingo, you created this regression: commit d713f519332e029d43eca8462629314eee1ded86 Author: Ingo Molnar <mingo@elte.hu> Date: Fri Jan 25 21:07:58 2008 +0100 sched: fix CONFIG_PRINT_TIME's reliance on sched_clock() Stefano Brivio reported weird printk timestamp behavior during CPU frequency changes: http://bugzilla.kernel.org/show_bug.cgi?id=9475 fix CONFIG_PRINT_TIME's reliance on sched_clock() and use cpu_clock() instead. Reported-and-bisected-by: Stefano Brivio <stefano.brivio@polimi.it> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2.6.26-rc3 looks different now: a) timestamps are to big now, instaed of to small. b) they are still unstable This bug might be (not sure) a duplicate of 10648. [ 0.000000/0] Setting APIC routing to flat [ 0.000000/0] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000/0] Using ACPI (MADT) for SMP configuration information [ 0.000000/0] Allocating PCI resources starting at c2000000 (gap: c0000000:20000000) [ 0.000000/0] PERCPU: Allocating 429616 bytes of per cpu data [ 0.000000/0] NR_CPUS: 8, nr_cpu_ids: 4 [17180642.907074/0] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 2038649 [17180642.907074/0] Policy zone: Normal [17180642.907074/0] Kernel command line: ro root=/dev/sda3 rhgb quiet [17180642.907074/0] Initializing CPU#0 [17180642.907074/0] PID hash table entries: 4096 (order: 12, 32768 bytes) [17180642.907074/0] TSC calibrated against PM_TIMER [17180642.907074/0] time.c: Detected 2327.497 MHz processor. [17180642.907074/0] Console: colour VGA+ 80x25 [17180642.907074/0] console [tty0] enabled [17180642.907074/0] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar [17180642.907074/0] ... MAX_LOCKDEP_SUBCLASSES: 8 [17180642.907074/0] ... MAX_LOCK_DEPTH: 48 [17180642.907074/0] ... MAX_LOCKDEP_KEYS: 2048 [17180642.907074/0] ... CLASSHASH_SIZE: 1024 [17180642.907074/0] ... MAX_LOCKDEP_ENTRIES: 8192 [17180642.907074/0] ... MAX_LOCKDEP_CHAINS: 16384 [17180642.907074/0] ... CHAINHASH_SIZE: 8192 [17180642.907074/0] memory used by lock dependency info: 1712 kB [17180642.907074/0] per task-struct memory footprint: 3456 bytes [17180642.907074/0] Checking aperture... [17180642.907074/0] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [17180642.907074/0] Placing software IO TLB between 0x11af000 - 0x51af000 [17180642.907074/0] Memory: 8110304k/9437184k available (2990k kernel code, 277684k reserved, 1596k data, 872k init) [17180642.907074/0] CPA: page pool initialized 1 of 1 pages preallocated [17180642.907074/0] hpet clockevent registered
OK, the timestamps now seem to stable/monotonic after some time. But they are still much to big. The following is the output of dmesg after 15 Minutes uptime when doing a bunch of 5 sec separated "echo h > /proc/sysrq_trigger". Ignore the nfs messages, they are unrelated: [root@lpsdm60 ~]# dmesg | tail -40 [17182167.579556/0] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182174.815056/0] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182254.281680/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182262.433874/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182269.799724/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182276.414685/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182283.600148/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182290.497381/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182298.208833/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182305.081323/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182313.014920/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182320.767386/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182328.391173/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182336.678734/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182344.971724/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182353.414055/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182362.207355/0] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182369.850269/2] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182375.811178/0] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182383.221895/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182389.221119/2] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182396.499882/3] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182403.136265/2] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182409.800753/2] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182416.127824/3] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182422.776454/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182429.394838/2] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182436.766963/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182444.074071/2] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182452.594471/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182460.537047/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182465.809049/3] nfs_server_set_fsinfo: rsize, wsize, rpages, nfs_ra_factor, ra_pages: 32768 32768 8 1 8 [17182468.391735/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182476.997130/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182483.654213/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182491.006721/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182497.631036/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182505.926140/1] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182514.911054/2] SysRq : HELP : loglevel0-8 reBoot show-all-locks(D) tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [17182706.476426/0] nfs_server_set_fsinfo: rsize, wsize, rpages, nfs_ra_factor, ra_pages: 32768 32768 8 1 8
The timestamps seem to be stable in 2.6.26-rc4, but the numbers are still bogus (not showing any relationship to "seconds since bootup"): [ 0.000000/0] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000/0] Using ACPI (MADT) for SMP configuration information [ 0.000000/0] Allocating PCI resources starting at c2000000 (gap: c0000000:20000000) [ 0.000000/0] PERCPU: Allocating 429616 bytes of per cpu data [ 0.000000/0] NR_CPUS: 8, nr_cpu_ids: 4 [17180642.907074/0] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 2038662 [17180642.907074/0] Policy zone: Normal [17180642.907074/0] Kernel command line: ro root=/dev/sda3 rhgb quiet [17180642.907074/0] Initializing CPU#0 [17180642.907074/0] PID hash table entries: 4096 (order: 12, 32768 bytes) [17180642.907074/0] TSC calibrated against PM_TIMER [17180642.907074/0] time.c: Detected 2327.497 MHz processor. [17180642.907074/0] Console: colour VGA+ 80x25 [17180642.907074/0] console [tty0] enabled [17180642.907074/0] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar [17180642.907074/0] ... MAX_LOCKDEP_SUBCLASSES: 8 [17180642.907074/0] ... MAX_LOCK_DEPTH: 48 [17180642.907074/0] ... MAX_LOCKDEP_KEYS: 2048 [17180642.907074/0] ... CLASSHASH_SIZE: 1024 [17180642.907074/0] ... MAX_LOCKDEP_ENTRIES: 8192 [17180642.907074/0] ... MAX_LOCKDEP_CHAINS: 16384 [17180642.907074/0] ... CHAINHASH_SIZE: 8192 [17180642.907074/0] memory used by lock dependency info: 1712 kB [17180642.907074/0] per task-struct memory footprint: 3456 bytes [17180642.907074/0] Checking aperture... [17180642.907074/0] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [17180642.907074/0] Placing software IO TLB between 0x11af000 - 0x51af000 [17180642.907074/0] Memory: 8110356k/9437184k available (2977k kernel code, 277632k reserved, 1585k data, 872k init) [17180642.907074/0] CPA: page pool initialized 1 of 1 pages preallocated [17180642.907074/0] hpet clockevent registered
you should test more recent kernels, -rc4 is ancient ;-) but seriously though - there is no requirement this clock corresponds to the time since bootup - it has been, and is - but its not a requirement as such (and from what I understand not all arches have it).
> but seriously though - there is no requirement this clock corresponds to the > time since bootup - it has been, and is - but its not a requirement as such > (and from what I understand not all arches have it). I tend to disagree. We really should make this behave as it was before. Thanks, tglx
oh - come on. The numbers should have a meaning, otherwise the feature is pretty much useless. OK, one could argue that it is anyway because of the timestamps from syslog, but it is great if you can relate dmesg output to actual times. Anyway, I will mark this one a duplicate of 10648. They deal with the same issue. *** This bug has been marked as a duplicate of bug 10648 ***