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

Previous thread: [PATCH] acpi-wmi: Enable event methods when registering notifiers by Matthew Garrett on Wednesday, August 27, 2008 - 8:04 am. (2 messages)

Next thread: [PATCH] shrink printk timestamp field by Joe Korty on Wednesday, August 27, 2008 - 8:17 am. (9 messages)
From: Joe Korty
Date: Wednesday, August 27, 2008 - 8:16 am

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;
--

From: Mark Brown
Date: Wednesday, August 27, 2008 - 9:16 am

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

From: Joe Korty
Date: Wednesday, August 27, 2008 - 10:04 am

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
--

From: Simon Farnsworth
Date: Wednesday, August 27, 2008 - 10:13 am

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

--

From: Joe Korty
Date: Wednesday, August 27, 2008 - 10:22 am

That certainly is the better approach.
Joe
--

From: Joe Korty
Date: Wednesday, August 27, 2008 - 10:27 am

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

Joe
--

From: Andi Kleen
Date: Wednesday, August 27, 2008 - 10:22 am

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
--

From: Ingo Molnar
Date: Thursday, August 28, 2008 - 2:40 am

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
--

From: Simon Farnsworth
Date: Wednesday, August 27, 2008 - 8:26 am

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

--

Previous thread: [PATCH] acpi-wmi: Enable event methods when registering notifiers by Matthew Garrett on Wednesday, August 27, 2008 - 8:04 am. (2 messages)

Next thread: [PATCH] shrink printk timestamp field by Joe Korty on Wednesday, August 27, 2008 - 8:17 am. (9 messages)