Bug 9936 - CONFIG_PRINTK_TIME is broken
Summary: CONFIG_PRINTK_TIME is broken
Status: RESOLVED INVALID
Alias: None
Product: Other
Classification: Unclassified
Component: Other (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: other_other
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-02-11 05:27 UTC by Bart Van Assche
Modified: 2009-03-25 13:52 UTC (History)
3 users (show)

See Also:
Kernel Version: 2.6.24.2
Subsystem:
Regression: No
Bisected commit-id:


Attachments
Kernel config (.config) (75.49 KB, text/plain)
2008-02-11 05:28 UTC, Bart Van Assche
Details
cfs-debug-info from Randy's system with same timestamps (all 0.000) (150.53 KB, application/octet-stream)
2008-02-27 13:03 UTC, Randy Dunlap
Details
Kernel config (.config) (41.27 KB, text/plain)
2008-02-28 01:28 UTC, Bart Van Assche
Details
cfs-debug-info from Bart's system. (232.20 KB, text/plain)
2008-02-28 01:29 UTC, Bart Van Assche
Details
cfs-debug-info from Bart's system with kernel 2.6.25-rc3-00081-g7704a8b. (242.04 KB, text/plain)
2008-02-28 02:02 UTC, Bart Van Assche
Details

Description Bart Van Assche 2008-02-11 05:27:59 UTC
Latest working kernel version: (not known)
Earliest failing kernel version: Broken in 2.6.22.9 and 2.6.24.2
Distribution: Ubuntu 7.10 server
Hardware Environment: (not relevant here)
Software Environment: (not relevant here)
Problem Description:

All kernel messages have timestamp [    0.000000] instead of a meaningful timestamp.

Steps to reproduce:

Compile the kernel with the attached kernel config, boot that kernel, run dmesg and look at the output.
Comment 1 Bart Van Assche 2008-02-11 05:28:18 UTC
Created attachment 14780 [details]
Kernel config (.config)
Comment 2 Bart Van Assche 2008-02-25 06:49:30 UTC
Correction: works with 2.6.20.21, 2.6.21.7, 2.6.22.18 but not with 2.6.24.2.
Comment 3 Randy Dunlap 2008-02-25 21:15:12 UTC
*All* messages have a timestamp of 0.000?  With both 2.6.24 and 2.6.25-rc3,
I see timestamps of 0.000 until the timesource has been calibrated, then I
start seeing meaningful timestamps.  Example (2.6.24):

[    0.000000] Initializing CPU#0
[    0.000000] PID hash table entries: 4096 (order: 12, 32768 bytes)
[    0.000000] hpet clockevent registered
[    0.000000] TSC calibrated against HPET
[   40.141362] time.c: Detected 2397.602 MHz processor.
[   40.148029] Console: colour dummy device 80x25
[   40.164024] console [tty0] enabled
Comment 4 Bart Van Assche 2008-02-25 23:06:09 UTC
Yes, all messages:

[    0.000000] Initializing CPU#0
[    0.000000] PID hash table entries: 4096 (order: 12, 32768 bytes)
[    0.000000] TSC calibrated against PIT
[    0.000000] time.c: Detected 1995.043 MHz processor.
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.000000] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.000000] Checking aperture...
Comment 5 Randy Dunlap 2008-02-27 11:15:46 UTC
So your .config is close to allmodconfig, except that it has PM=n and ACPI=n.
Is that done on purpose?

And just so that I can understand it, why this nearly-allmodconfig anyway?
Comment 6 Ingo Molnar 2008-02-27 12:48:18 UTC
Could you attach the output of cfs-debug-info.sh:

  http://people.redhat.com/mingo/cfs-scheduler/tools/cfs-debug-info.sh

that will give us a good idea of where this problems comes from.
Comment 7 Randy Dunlap 2008-02-27 13:03:45 UTC
Created attachment 15030 [details]
cfs-debug-info from Randy's system with same timestamps (all 0.000)

Note: CONFIG_PM=n, CONFIG_ACPI=n
Comment 8 Randy Dunlap 2008-02-27 13:13:03 UTC
Enabling PM and ACPI "fixes" the timestamps....
Comment 9 Bart Van Assche 2008-02-28 01:19:55 UTC
(In reply to comment #5)
> So your .config is close to allmodconfig, except that it has PM=n and ACPI=n.
> Is that done on purpose?

I had disabled PM and ACPI while trying to find the cause of another issue (PAE memory leak on SMP systems, #9991).

> And just so that I can understand it, why this nearly-allmodconfig anyway?

I started from the Ubuntu 7.10 server kernel .config, and that's how the Ubuntu kernel config looks like.
Comment 10 Ingo Molnar 2008-02-28 01:21:46 UTC
> ------- Comment #8 from randy.dunlap@oracle.com  2008-02-27 13:13 -------
> Enabling PM and ACPI "fixes" the timestamps....

hm, does this occur with latest -git as well? At least 3 fixes come to 
mind: we now use rq_clock() instead of sched_clock(), and there are two 
other fixes as well that impact how the TSC is utilized. Zero timestamps 
means the sched clock returns 0 all the time, and your logs seem to 
support that.
Comment 11 Bart Van Assche 2008-02-28 01:28:46 UTC
Created attachment 15051 [details]
Kernel config (.config)

Simplified kernel config.
Comment 12 Bart Van Assche 2008-02-28 01:29:48 UTC
Created attachment 15052 [details]
cfs-debug-info from Bart's system.

cfs-debug-info-2008.02.28-10.24.02
Comment 13 Bart Van Assche 2008-02-28 02:02:18 UTC
Created attachment 15054 [details]
cfs-debug-info from Bart's system with kernel 2.6.25-rc3-00081-g7704a8b.

Behavior with latest git kernel and with PM and ACPI disabled is different but still not completely correct: as you can see in the kernel messages, the time source is reset a few times.
Comment 14 Alan 2009-03-25 13:52:36 UTC
Closing out old stale bugs

Note You need to log in before you can comment on or make changes to this bug.