[PATCH] printk timestamp post-boot suppression

[PATCH] printk timestamp post-boot suppression

[Joe Korty]

Suppress printk timestamping after system boot.

The timestamp printk prefix seems most useful during boot,
where it easily shows where the boot sequence is spending
its time.

Its utility after boot is questionable, since 1) the
timestamp becomes a rather large, unreadable integer,
as the hours, days and weeks go by, and 2) syslog does
a proper TOD timestamp anyways on these later messages,
as they go into /var/log/messages.

Signed-off-by: Joe Korty <joe.korty@ccur.com>

Index: 2.6.27-rc4-git4/kernel/printk.c
===================================================================
--- 2.6.27-rc4-git4.orig/kernel/printk.c	2008-08-26 16:28:41.000000000 -0400
+++ 2.6.27-rc4-git4/kernel/printk.c	2008-08-26 16:53:11.000000000 -0400
@@ -730,7 +730,7 @@
 			printed_len += 3;
 			new_text_line = 0;
 
-			if (printk_time) {
+			if (printk_time && system_state == SYSTEM_BOOTING) {
 				/* Follow the token with the time */
 				char tbuf[50], *tp;
 				unsigned tlen;

Re: [PATCH] printk timestamp post-boot suppression

[Simon Farnsworth]

Joe Korty wrote:
> Suppress printk timestamping after system boot.
> 
> The timestamp printk prefix seems most useful during boot,
> where it easily shows where the boot sequence is spending
> its time.
> 
It's also very useful while the system is running. We've had problems
with systems where the HDD or libata was "hiccuping" and stalling the
entire system for 30 seconds; our logs were useless, as syslog was
timestamping with the timestamp *after* the stall ended (as that was
when it received the message), and dmesg had no timestamps.

In this case, our problem ran away and hid when we turned on printk
timestamps, but if it recurred, we'd want the timestamps available to
let us work out which operation was taking lots of time, without having
to rebuild the kernel.
-- 
Simon Farnsworth

Re: [PATCH] printk timestamp post-boot suppression

[Mark Brown]

On Wed, Aug 27, 2008 at 11:16:13AM -0400, Joe Korty wrote:

> Its utility after boot is questionable, since 1) the
> timestamp becomes a rather large, unreadable integer,
> as the hours, days and weeks go by, and 2) syslog does
> a proper TOD timestamp anyways on these later messages,
> as they go into /var/log/messages.

It'd be nicer if this were optional - syslog typically only logs at
second resolution and not all systems are going to have logfiles.

[PATCH] printk timestamp post-boot suppression, v2

[Joe Korty]

On Wed, Aug 27, 2008 at 12:16:30PM -0400, Mark Brown wrote:
> It'd be nicer if this were optional - syslog typically only logs at
> second resolution and not all systems are going to have logfiles.


Optionally suppress printk timestamping after system boot.

A new config option is introduced, which if selected
suppresses printk timestamping after the boot sequence
is completed.

Signed-off-by: Joe Korty <joe.korty@ccur.com>

Index: 2.6.27-rc4-git4/kernel/printk.c
===================================================================
--- 2.6.27-rc4-git4.orig/kernel/printk.c	2008-08-27 09:37:52.000000000 -0400
+++ 2.6.27-rc4-git4/kernel/printk.c	2008-08-27 12:35:14.000000000 -0400
@@ -560,6 +560,12 @@
 #endif
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
+#if defined(CONFIG_PRINTK_TIME_BOOTONLY)
+#define printk_time_bootonly (system_state == SYSTEM_BOOTING)
+#else
+#define printk_time_bootonly (1)
+#endif
+
 /* Check if we have any console registered that can be called early in boot. */
 static int have_callable_console(void)
 {
@@ -730,7 +736,7 @@
 			printed_len += 3;
 			new_text_line = 0;
 
-			if (printk_time) {
+			if (printk_time && printk_time_bootonly) {
 				/* Follow the token with the time */
 				char tbuf[50], *tp;
 				unsigned tlen;
Index: 2.6.27-rc4-git4/lib/Kconfig.debug
===================================================================
--- 2.6.27-rc4-git4.orig/lib/Kconfig.debug	2008-08-26 16:28:41.000000000 -0400
+++ 2.6.27-rc4-git4/lib/Kconfig.debug	2008-08-27 12:29:34.000000000 -0400
@@ -9,6 +9,17 @@
 	  operations.  This is useful for identifying long delays
 	  in kernel startup.
 
+config PRINTK_TIME_BOOTONLY
+	bool "Only show printk timing during kernel startup"
+	depends on PRINTK_TIME
+	help
+	  If Y is selected, then timing information will
+	  be prefixed to printk output lines only as long
+	  as the kernel startup phase is in operation.
+
+	  If N is selected, then every printk line will
+	  be prefixed with timing information.
+
 config ENABLE_WARN_DEPRECATED
 	bool "Enable __deprecated logic"
 	default y

Re: [PATCH] printk timestamp post-boot suppression, v2

[Simon Farnsworth]

Joe Korty wrote:
> On Wed, Aug 27, 2008 at 12:16:30PM -0400, Mark Brown wrote:
>> It'd be nicer if this were optional - syslog typically only logs at
>> second resolution and not all systems are going to have logfiles.
> 
> 
> Optionally suppress printk timestamping after system boot.
> 
JOOI, what's wrong with having your init scripts contain a line like:
echo 0 > /sys/module/printk/parameters/time
?

This has the advantage that you can avoid turning the kernel's
timestamps off until you know that syslog is running and timestamp
events that it's receiving.
-- 
Simon Farnsworth

Re: [PATCH] printk timestamp post-boot suppression, v2

[Andi Kleen]

Joe Korty <joe.korty@ccur.com> writes:

> On Wed, Aug 27, 2008 at 12:16:30PM -0400, Mark Brown wrote:
>> It'd be nicer if this were optional - syslog typically only logs at
>> second resolution and not all systems are going to have logfiles.
>
>
> Optionally suppress printk timestamping after system boot.

Such things shouldn't be CONFIGs, but boot options.

But a better option might be to just fix syslog or klogd to convert those
time stamps into its own ones? Then your screen estate issue
would disappear. That would be a user space fix only.

-Andi

-- 
ak@linux.intel.com

Re: [PATCH] printk timestamp post-boot suppression, v2

[Joe Korty]

On Wed, Aug 27, 2008 at 01:13:28PM -0400, Simon Farnsworth wrote:
> Joe Korty wrote:
> > On Wed, Aug 27, 2008 at 12:16:30PM -0400, Mark Brown wrote:
> >> It'd be nicer if this were optional - syslog typically only logs at
> >> second resolution and not all systems are going to have logfiles.
> >
> >
> > Optionally suppress printk timestamping after system boot.
> >
> JOOI, what's wrong with having your init scripts contain a line like:
> echo 0 > /sys/module/printk/parameters/time
> ?
> 
> This has the advantage that you can avoid turning the kernel's
> timestamps off until you know that syslog is running and timestamp
> events that it's receiving.
> --
> Simon Farnsworth


That certainly is the better approach.
Joe

Re: [PATCH] printk timestamp post-boot suppression, v2

[Joe Korty]

On Wed, Aug 27, 2008 at 01:22:58PM -0400, Joe Korty wrote:
> On Wed, Aug 27, 2008 at 01:13:28PM -0400, Simon Farnsworth wrote:
> > Joe Korty wrote:
> > > Optionally suppress printk timestamping after system boot.
> > >
> > JOOI, what's wrong with having your init scripts contain a line like:
> > echo 0 > /sys/module/printk/parameters/time
> > 
> > This has the advantage that you can avoid turning the kernel's
> > timestamps off until you know that syslog is running and timestamp
> > events that it's receiving.
> 
> That certainly is the better approach.

...and is already present in 2.6.27, the module_param_named(...)
stmt in kernel/printk.c sets it all up.

Joe

Re: [PATCH] printk timestamp post-boot suppression, v2

[Ingo Molnar]

* Joe Korty <joe.korty@ccur.com> wrote:

> On Wed, Aug 27, 2008 at 12:16:30PM -0400, Mark Brown wrote:
> > It'd be nicer if this were optional - syslog typically only logs at
> > second resolution and not all systems are going to have logfiles.
> 
> Optionally suppress printk timestamping after system boot.

i think the best approach is to write an initcall tracer - i think Arjan 
has some ideas in that area.

that would be infinitely higher quality than anything printk based 
anyway, as with ftrace you could see the reasons of why a boot delay 
happens - which tasks context-switch, in which code path, etc.

	Ingo