[RFC|PATCH] Compile time printk verbosity

[RFC|PATCH] Compile time printk verbosity

[Marc Andre Tanner]

This series adds a configuration option to selectively compile out
printk message strings based on a verbosity level.

This works by wrapping printk with a macro which evaluates to a 
constant if condition which the compiler will be able to optimize 
out.

However because printk might be wrapped by a macro it no longer has
a return value. This means that constructs like the following ones
don't work: 

   ((void)(SOME_RANDOM_DEBUG_FLAG && printk(...));

   some_random_variable = printk(...);

Therefore printk_unfiltered is introduced which is just an alias
to the standard printk function but not wrapped by a macro.

Patches 4-6 make existing kernel code aware of this fact.

The series was compile tested with make allyesconfig for x86 and 
arm (with a cross compiler) but I might have missed something.

All kinds of comments are welcome.

Marc Andre Tanner (7):
      printk: introduce CONFIG_PRINTK_VERBOSITY
      printk: move printk to the end of the file
      printk: introduce printk_unfiltered as an alias to printk
      drivers: replace printk with printk_unfiltered
      drivers: make macro independent of printk's return value
      video/stk-webcam: change use of STK_ERROR
      printk: provide a filtering macro for printk


 drivers/char/mem.c                 |    2 +-
 drivers/md/md.c                    |    2 +-
 drivers/md/raid5.c                 |    2 +-
 drivers/media/video/stk-webcam.c   |   16 +++---
 drivers/net/e100.c                 |    2 +-
 drivers/net/ixgb/ixgb.h            |    2 +-
 drivers/net/ixgbe/ixgbe.h          |    2 +-
 drivers/scsi/aic7xxx/aic79xx_osm.h |    2 +-
 drivers/scsi/aic7xxx/aic7xxx_osm.h |    2 +-
 include/linux/kernel.h             |   29 +++++++++++
 include/net/sctp/sctp.h            |    2 +-
 init/Kconfig                       |   28 ++++++++++
 kernel/lockdep.c                   |    4 +-
 kernel/printk.c                    |   96 +++++++++++++++++++++++-------------
 14 files changed, 137 insertions(+), 54 deletions(-)

[PATCH 1/7] printk: introduce CONFIG_PRINTK_VERBOSITY

[Marc Andre Tanner]

Introduce a config option which allows to selectively compile out
printk messages based on a specified verbosity level.

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 init/Kconfig |   28 ++++++++++++++++++++++++++++
 1 files changed, 28 insertions(+), 0 deletions(-)

diff --git a/init/Kconfig b/init/Kconfig
index 3f7e609..3618168 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -833,6 +833,34 @@ config PRINTK
 	  very difficult to diagnose system problems, saying N here is
 	  strongly discouraged.
 
+config PRINTK_VERBOSITY
+	int "Printk compile time verbosity"
+	depends on EMBEDDED && PRINTK
+	range 0 7
+	default 0
+	help
+
+	  Select the maximum printk verbosity level to be compiled into
+	  the kernel.
+
+ 	  Messages above the specified verbosity level are removed from
+ 	  the kernel at compile time. This reduces the kernel image size
+ 	  at the cost of a calmer kernel.
+
+ 	  Possible verbosity levels are:
+
+	   0  Disable this feature and compile all messages in.
+
+ 	   1  KERN_ALERT        /* action must be taken immediately  */
+ 	   2  KERN_CRIT         /* critical conditions               */
+ 	   3  KERN_ERR          /* error conditions                  */
+ 	   4  KERN_WARNING      /* warning conditions                */
+ 	   5  KERN_NOTICE       /* normal but significant condition  */
+ 	   6  KERN_INFO         /* informational                     */
+ 	   7  KERN_DEBUG        /* debug-level messages              */
+
+	  If unsure, just move on and leave this option alone.
+
 config BUG
 	bool "BUG() support" if EMBEDDED
 	default y
-- 
1.6.3.3

[PATCH 2/7] printk: move printk to the end of the file

[Marc Andre Tanner]

A later patch will #undef printk because the macro would otherwise
conflict with the function definition. Moving the printk function
to the end of the file makes sure that the macro is expanded within
the rest of the file.

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 kernel/printk.c |   72 ++++++++++++++++++++++++++++--------------------------
 1 files changed, 37 insertions(+), 35 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index b4d97b5..5455d41 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -551,40 +551,6 @@ static int have_callable_console(void)
 	return 0;
 }
 
-/**
- * printk - print a kernel message
- * @fmt: format string
- *
- * This is printk().  It can be called from any context.  We want it to work.
- *
- * We try to grab the console_sem.  If we succeed, it's easy - we log the output and
- * call the console drivers.  If we fail to get the semaphore we place the output
- * into the log buffer and return.  The current holder of the console_sem will
- * notice the new output in release_console_sem() and will send it to the
- * consoles before releasing the semaphore.
- *
- * One effect of this deferred printing is that code which calls printk() and
- * then changes console_loglevel may break. This is because console_loglevel
- * is inspected when the actual printing occurs.
- *
- * See also:
- * printf(3)
- *
- * See the vsnprintf() documentation for format string extensions over C99.
- */
-
-asmlinkage int printk(const char *fmt, ...)
-{
-	va_list args;
-	int r;
-
-	va_start(args, fmt);
-	r = vprintk(fmt, args);
-	va_end(args);
-
-	return r;
-}
-
 /* cpu currently holding logbuf_lock */
 static volatile unsigned int printk_cpu = UINT_MAX;
 
@@ -770,7 +736,6 @@ out_restore_irqs:
 	preempt_enable();
 	return printed_len;
 }
-EXPORT_SYMBOL(printk);
 EXPORT_SYMBOL(vprintk);
 
 #else
@@ -1337,3 +1302,40 @@ bool printk_timed_ratelimit(unsigned long *caller_jiffies,
 }
 EXPORT_SYMBOL(printk_timed_ratelimit);
 #endif
+
+#ifdef CONFIG_PRINTK
+/**
+ * printk - print a kernel message
+ * @fmt: format string
+ *
+ * This is printk().  It can be called from any context.  We want it to work.
+ *
+ * We try to grab the console_sem.  If we succeed, it's easy - we log the output and
+ * call the console drivers.  If we fail to get the semaphore we place the output
+ * into the log buffer and return.  The current holder of the console_sem will
+ * notice the new output in release_console_sem() and will send it to the
+ * consoles before releasing the semaphore.
+ *
+ * One effect of this deferred printing is that code which calls printk() and
+ * then changes console_loglevel may break. This is because console_loglevel
+ * is inspected when the actual printing occurs.
+ *
+ * See also:
+ * printf(3)
+ *
+ * See the vsnprintf() documentation for format string extensions over C99.
+ */
+
+asmlinkage int printk(const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	r = vprintk(fmt, args);
+	va_end(args);
+
+	return r;
+}
+EXPORT_SYMBOL(printk);
+#endif
-- 
1.6.3.3

[PATCH 3/7] printk: introduce printk_unfiltered as an alias to printk

[Marc Andre Tanner]

The standard printk function will be wrapped by a macro.
However this doesn't work in all situations (for example
when the return value of printk is of interest). We
therefore provide a new function which is just an alias
to printk and therefore bypasses the macro.

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 include/linux/kernel.h |    5 +++++
 kernel/printk.c        |   24 ++++++++++++++++++++++++
 2 files changed, 29 insertions(+), 0 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index d6320a3..c2b3047 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -239,6 +239,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
+asmlinkage int printk_unfiltered(const char *fmt, ...)
+	__attribute__ ((format (printf, 1, 2))) __cold;
 
 extern struct ratelimit_state printk_ratelimit_state;
 extern int printk_ratelimit(void);
@@ -265,6 +267,9 @@ static inline int vprintk(const char *s, va_list args) { return 0; }
 static inline int printk(const char *s, ...)
 	__attribute__ ((format (printf, 1, 2)));
 static inline int __cold printk(const char *s, ...) { return 0; }
+static inline int printk_unfiltered(const char *s, ...)
+	__attribute__ ((format (printf, 1, 2)));
+static inline int __cold printk_unfiltered(const char *s, ...) { return 0; }
 static inline int printk_ratelimit(void) { return 0; }
 static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies, \
 					  unsigned int interval_msec)	\
diff --git a/kernel/printk.c b/kernel/printk.c
index 5455d41..20379b5 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1310,6 +1310,11 @@ EXPORT_SYMBOL(printk_timed_ratelimit);
  *
  * This is printk().  It can be called from any context.  We want it to work.
  *
+ * Note that depending on the kernel configuration printk might be wrapped by
+ * a macro. In cases where it's important that the implementation is a function
+ * (for example when the return value of printk is of interest) printk_unfiltered
+ * which bypasses the macro should be used instead.
+ *
  * We try to grab the console_sem.  If we succeed, it's easy - we log the output and
  * call the console drivers.  If we fail to get the semaphore we place the output
  * into the log buffer and return.  The current holder of the console_sem will
@@ -1326,6 +1331,14 @@ EXPORT_SYMBOL(printk_timed_ratelimit);
  * See the vsnprintf() documentation for format string extensions over C99.
  */
 
+/*
+ * We need to #undef the printk macro from <linux/kernel.h> because
+ * it would otherwise conflict with the function implementation.
+ */
+#ifdef printk
+# undef printk
+#endif
+
 asmlinkage int printk(const char *fmt, ...)
 {
 	va_list args;
@@ -1338,4 +1351,15 @@ asmlinkage int printk(const char *fmt, ...)
 	return r;
 }
 EXPORT_SYMBOL(printk);
+ 
+/*
+ * Because printk might be wrapped by a macro which doesn't work in all
+ * circumstances (for example when the return value of printk is of
+ * interest) we make the functionality also available as a normal
+ * function.
+ */
+
+asmlinkage int printk_unfiltered(const char *fmt, ...)
+	__attribute__((alias("printk")));
+EXPORT_SYMBOL(printk_unfiltered);
 #endif
-- 
1.6.3.3

[PATCH 4/7] drivers: replace printk with printk_unfiltered

[Marc Andre Tanner]

Use the unfiltered variant in cases where the return value
is of interest.

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 drivers/char/mem.c                 |    2 +-
 drivers/md/md.c                    |    2 +-
 drivers/scsi/aic7xxx/aic79xx_osm.h |    2 +-
 drivers/scsi/aic7xxx/aic7xxx_osm.h |    2 +-
 kernel/lockdep.c                   |    4 ++--
 5 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/drivers/char/mem.c b/drivers/char/mem.c
index afa8813..ba48b82 100644
--- a/drivers/char/mem.c
+++ b/drivers/char/mem.c
@@ -850,7 +850,7 @@ static ssize_t kmsg_write(struct file * file, const char __user * buf,
 	ret = -EFAULT;
 	if (!copy_from_user(tmp, buf, count)) {
 		tmp[count] = 0;
-		ret = printk("%s", tmp);
+		ret = printk_unfiltered("%s", tmp);
 		if (ret > count)
 			/* printk can add a prefix */
 			ret = count;
diff --git a/drivers/md/md.c b/drivers/md/md.c
index 9dd8720..85c31bf 100644
--- a/drivers/md/md.c
+++ b/drivers/md/md.c
@@ -51,7 +51,7 @@
 #include "bitmap.h"
 
 #define DEBUG 0
-#define dprintk(x...) ((void)(DEBUG && printk(x)))
+#define dprintk(x...) ((void)(DEBUG && printk_unfiltered(x)))
 
 
 #ifndef MODULE
diff --git a/drivers/scsi/aic7xxx/aic79xx_osm.h b/drivers/scsi/aic7xxx/aic79xx_osm.h
index 55c1fe0..65a30c5 100644
--- a/drivers/scsi/aic7xxx/aic79xx_osm.h
+++ b/drivers/scsi/aic7xxx/aic79xx_osm.h
@@ -364,7 +364,7 @@ struct ahd_platform_data {
 };
 
 /************************** OS Utility Wrappers *******************************/
-#define printf printk
+#define printf printk_unfiltered
 #define M_NOWAIT GFP_ATOMIC
 #define M_WAITOK 0
 #define malloc(size, type, flags) kmalloc(size, flags)
diff --git a/drivers/scsi/aic7xxx/aic7xxx_osm.h b/drivers/scsi/aic7xxx/aic7xxx_osm.h
index 56f07e5..cf05c2b 100644
--- a/drivers/scsi/aic7xxx/aic7xxx_osm.h
+++ b/drivers/scsi/aic7xxx/aic7xxx_osm.h
@@ -369,7 +369,7 @@ struct ahc_platform_data {
 };
 
 /************************** OS Utility Wrappers *******************************/
-#define printf printk
+#define printf printk_unfiltered
 #define M_NOWAIT GFP_ATOMIC
 #define M_WAITOK 0
 #define malloc(size, type, flags) kmalloc(size, flags)
diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 8bbeef9..154756a 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -564,8 +564,8 @@ static void print_lock_class_header(struct lock_class *class, int depth)
 		if (class->usage_mask & (1 << bit)) {
 			int len = depth;
 
-			len += printk("%*s   %s", depth, "", usage_str[bit]);
-			len += printk(" at:\n");
+			len += printk_unfiltered("%*s   %s", depth, "", usage_str[bit]);
+			len += printk_unfiltered(" at:\n");
 			print_stack_trace(class->usage_traces + bit, len);
 		}
 	}
-- 
1.6.3.3

[PATCH 5/7] drivers: make macro independent of printk's return value

[Marc Andre Tanner]

Because printk might be wrapped by a macro avoid constructs which
assume that the return value can be interpreted as a boolean value.

This doesn't work because the macro has no return value which
results in a compile error "void value not ignored as it ought to be".

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 drivers/md/raid5.c        |    2 +-
 drivers/net/e100.c        |    2 +-
 drivers/net/ixgb/ixgb.h   |    2 +-
 drivers/net/ixgbe/ixgbe.h |    2 +-
 include/net/sctp/sctp.h   |    2 +-
 5 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/drivers/md/raid5.c b/drivers/md/raid5.c
index b8a2c5d..d0dac07 100644
--- a/drivers/md/raid5.c
+++ b/drivers/md/raid5.c
@@ -92,7 +92,7 @@
 #define __inline__
 #endif
 
-#define printk_rl(args...) ((void) (printk_ratelimit() && printk(args)))
+#define printk_rl(args...) ((void)(!printk_ratelimit() ?: printk(args)))
 
 /*
  * We maintain a biased count of active stripes in the bottom 16 bits of
diff --git a/drivers/net/e100.c b/drivers/net/e100.c
index 3a6735d..3598d49 100644
--- a/drivers/net/e100.c
+++ b/drivers/net/e100.c
@@ -199,7 +199,7 @@ MODULE_PARM_DESC(debug, "Debug level (0=none,...,16=all)");
 MODULE_PARM_DESC(eeprom_bad_csum_allow, "Allow bad eeprom checksums");
 MODULE_PARM_DESC(use_io, "Force use of i/o access mode");
 #define DPRINTK(nlevel, klevel, fmt, args...) \
-	(void)((NETIF_MSG_##nlevel & nic->msg_enable) && \
+	(void)(!(NETIF_MSG_##nlevel & nic->msg_enable) ?: \
 	printk(KERN_##klevel PFX "%s: %s: " fmt, nic->netdev->name, \
 		__func__ , ## args))
 
diff --git a/drivers/net/ixgb/ixgb.h b/drivers/net/ixgb/ixgb.h
index d85717e..5208677 100644
--- a/drivers/net/ixgb/ixgb.h
+++ b/drivers/net/ixgb/ixgb.h
@@ -83,7 +83,7 @@ struct ixgb_adapter;
 
 #define PFX "ixgb: "
 #define DPRINTK(nlevel, klevel, fmt, args...) \
-	(void)((NETIF_MSG_##nlevel & adapter->msg_enable) && \
+	(void)(!(NETIF_MSG_##nlevel & adapter->msg_enable) ?: \
 	printk(KERN_##klevel PFX "%s: %s: " fmt, adapter->netdev->name, \
 		__func__ , ## args))
 
diff --git a/drivers/net/ixgbe/ixgbe.h b/drivers/net/ixgbe/ixgbe.h
index 2c4dc82..eb67b31 100644
--- a/drivers/net/ixgbe/ixgbe.h
+++ b/drivers/net/ixgbe/ixgbe.h
@@ -46,7 +46,7 @@
 
 #define PFX "ixgbe: "
 #define DPRINTK(nlevel, klevel, fmt, args...) \
-	((void)((NETIF_MSG_##nlevel & adapter->msg_enable) && \
+	((void)(!(NETIF_MSG_##nlevel & adapter->msg_enable) ?: \
 	printk(KERN_##klevel PFX "%s: %s: " fmt, adapter->netdev->name, \
 		__func__ , ## args)))
 
diff --git a/include/net/sctp/sctp.h b/include/net/sctp/sctp.h
index d16a304..c13fcf9 100644
--- a/include/net/sctp/sctp.h
+++ b/include/net/sctp/sctp.h
@@ -276,7 +276,7 @@ struct sctp_mib {
 #if SCTP_DEBUG
 extern int sctp_debug_flag;
 #define SCTP_DEBUG_PRINTK(whatever...) \
-	((void) (sctp_debug_flag && printk(KERN_DEBUG whatever)))
+	((void) (!sctp_debug_flag ?: printk(KERN_DEBUG whatever)))
 #define SCTP_DEBUG_PRINTK_IPADDR(lead, trail, leadparm, saddr, otherparms...) \
 	if (sctp_debug_flag) { \
 		if (saddr->sa.sa_family == AF_INET6) { \
-- 
1.6.3.3

[PATCH 6/7] video/stk-webcam: change use of STK_ERROR

[Marc Andre Tanner]

Don't rely on the return value of STK_ERROR which is a wrapper
around printk use a normal if clause instead.

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 drivers/media/video/stk-webcam.c |   16 ++++++++--------
 1 files changed, 8 insertions(+), 8 deletions(-)

diff --git a/drivers/media/video/stk-webcam.c b/drivers/media/video/stk-webcam.c
index b154bd9..ea7e70e 100644
--- a/drivers/media/video/stk-webcam.c
+++ b/drivers/media/video/stk-webcam.c
@@ -386,8 +386,8 @@ static void stk_isoc_handler(struct urb *urb)
 
 	if (list_empty(&dev->sio_avail)) {
 		/*FIXME Stop streaming after a while */
-		(void) (printk_ratelimit() &&
-		STK_ERROR("isoc_handler without available buffer!\n"));
+		if (printk_ratelimit())
+			STK_ERROR("isoc_handler without available buffer!\n");
 		goto resubmit;
 	}
 	fb = list_first_entry(&dev->sio_avail,
@@ -422,10 +422,10 @@ static void stk_isoc_handler(struct urb *urb)
 			/* This marks a new frame */
 			if (fb->v4lbuf.bytesused != 0
 				&& fb->v4lbuf.bytesused != dev->frame_size) {
-				(void) (printk_ratelimit() &&
-				STK_ERROR("frame %d, "
-					"bytesused=%d, skipping\n",
-					i, fb->v4lbuf.bytesused));
+				if (printk_ratelimit())
+					STK_ERROR("frame %d, "
+						"bytesused=%d, skipping\n",
+						i, fb->v4lbuf.bytesused);
 				fb->v4lbuf.bytesused = 0;
 				fill = fb->buffer;
 			} else if (fb->v4lbuf.bytesused == dev->frame_size) {
@@ -450,8 +450,8 @@ static void stk_isoc_handler(struct urb *urb)
 
 		/* Our buffer is full !!! */
 		if (framelen + fb->v4lbuf.bytesused > dev->frame_size) {
-			(void) (printk_ratelimit() &&
-			STK_ERROR("Frame buffer overflow, lost sync\n"));
+			if (printk_ratelimit())
+				STK_ERROR("Frame buffer overflow, lost sync\n");
 			/*FIXME Do something here? */
 			continue;
 		}
-- 
1.6.3.3

[PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

The macro filters out printk messages based on a configurable verbosity
level (CONFIG_PRINTK_VERBOSITY).

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 include/linux/kernel.h |   24 ++++++++++++++++++++++++
 1 files changed, 24 insertions(+), 0 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index c2b3047..1f5d01f 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -242,6 +242,30 @@ asmlinkage int printk(const char * fmt, ...)
 asmlinkage int printk_unfiltered(const char *fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
 
+#if defined(CONFIG_PRINTK_VERBOSITY) && CONFIG_PRINTK_VERBOSITY > 0
+/*
+ * The idea here is to wrap the actual printk function with a macro which
+ * will filter out all messages above a certain verbosity level. Because
+ * the if condition evaluates to a constant expression the compiler will be
+ * able to eliminate it and the resulting kernel image will be smaller.
+ *
+ * The check with sizeof(void*) should make sure that we don't operate on
+ * pointers, which the compiler wouldn't be able to optimize out, but only
+ * on string constants.
+ */
+
+#include <linux/stringify.h>
+
+#define printk(fmt, ...) ({ 							 \
+	if (sizeof(fmt) == sizeof(void *) ||					 \
+	    (((const char *)(fmt))[0] != '<' && CONFIG_PRINTK_VERBOSITY >= 4) || \
+	    (((const char *)(fmt))[0] == '<' && 				 \
+	     ((const char *)(fmt))[1] <= *__stringify(CONFIG_PRINTK_VERBOSITY))) \
+		printk((fmt), ##__VA_ARGS__); 					 \
+})
+
+#endif /* CONFIG_PRINTK_VERBOSITY */
+
 extern struct ratelimit_state printk_ratelimit_state;
 extern int printk_ratelimit(void);
 extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
-- 
1.6.3.3

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Tim Bird]

Marc Andre Tanner wrote:
> The macro filters out printk messages based on a configurable verbosity
> level (CONFIG_PRINTK_VERBOSITY).
> 
> Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
> ---
>  include/linux/kernel.h |   24 ++++++++++++++++++++++++
>  1 files changed, 24 insertions(+), 0 deletions(-)
> 
> diff --git a/include/linux/kernel.h b/include/linux/kernel.h
> index c2b3047..1f5d01f 100644
> --- a/include/linux/kernel.h
> +++ b/include/linux/kernel.h
> @@ -242,6 +242,30 @@ asmlinkage int printk(const char * fmt, ...)
>  asmlinkage int printk_unfiltered(const char *fmt, ...)
>  	__attribute__ ((format (printf, 1, 2))) __cold;
>  
> +#if defined(CONFIG_PRINTK_VERBOSITY) && CONFIG_PRINTK_VERBOSITY > 0
> +/*
> + * The idea here is to wrap the actual printk function with a macro which
> + * will filter out all messages above a certain verbosity level. Because
> + * the if condition evaluates to a constant expression the compiler will be
> + * able to eliminate it and the resulting kernel image will be smaller.
> + *
> + * The check with sizeof(void*) should make sure that we don't operate on
> + * pointers, which the compiler wouldn't be able to optimize out, but only
> + * on string constants.
> + */
> +
> +#include <linux/stringify.h>
> +
> +#define printk(fmt, ...) ({ 							 \
> +	if (sizeof(fmt) == sizeof(void *) ||					 \
> +	    (((const char *)(fmt))[0] != '<' && CONFIG_PRINTK_VERBOSITY >= 4) || \
> +	    (((const char *)(fmt))[0] == '<' && 				 \
> +	     ((const char *)(fmt))[1] <= *__stringify(CONFIG_PRINTK_VERBOSITY))) \
> +		printk((fmt), ##__VA_ARGS__); 					 \
> +})
> +
> +#endif /* CONFIG_PRINTK_VERBOSITY */
> +
>  extern struct ratelimit_state printk_ratelimit_state;
>  extern int printk_ratelimit(void);
>  extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,



Some places in the kernel break the message into pieces, like so:

printk(KERN_ERR, "Error: first part ");
...
printk(" more info for error.\n");

These parts would not be handled consistently under certain
conditions.

It would be confusing to see only part of the message,
but I don't know how often this construct is used.  Maybe
another mechanism is needed to ensure that continuation
printk lines have the same log level as their start strings.

But, overall, very slick!  It's nice to see a solution that doesn't
require changing all printks statements in the kernel.
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

RE: [PATCH 7/7] printk: provide a filtering macro for printk

[H Hartley Sweeten]

On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
> Marc Andre Tanner wrote:
>> The macro filters out printk messages based on a configurable verbosity
>> level (CONFIG_PRINTK_VERBOSITY).
>>
>> Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
>> ---
>>  include/linux/kernel.h |   24 ++++++++++++++++++++++++
>>  1 files changed, 24 insertions(+), 0 deletions(-)
>> 
>> diff --git a/include/linux/kernel.h b/include/linux/kernel.h
>> index c2b3047..1f5d01f 100644
>> --- a/include/linux/kernel.h
>> +++ b/include/linux/kernel.h
>> @@ -242,6 +242,30 @@ asmlinkage int printk(const char * fmt, ...)
>>  asmlinkage int printk_unfiltered(const char *fmt, ...)
>>  	__attribute__ ((format (printf, 1, 2))) __cold;
>>  
>> +#if defined(CONFIG_PRINTK_VERBOSITY) && CONFIG_PRINTK_VERBOSITY > 0
>> +/*
>> + * The idea here is to wrap the actual printk function with a macro which
>> + * will filter out all messages above a certain verbosity level. Because
>> + * the if condition evaluates to a constant expression the compiler will be
>> + * able to eliminate it and the resulting kernel image will be smaller.
>> + *
>> + * The check with sizeof(void*) should make sure that we don't operate on
>> + * pointers, which the compiler wouldn't be able to optimize out, but only
>> + * on string constants.
>> + */
>> +
>> +#include <linux/stringify.h>
>> +
>> +#define printk(fmt, ...) ({ 							 \
>> +	if (sizeof(fmt) == sizeof(void *) ||					 \
>> +	    (((const char *)(fmt))[0] != '<' && CONFIG_PRINTK_VERBOSITY >= 4) || \
>> +	    (((const char *)(fmt))[0] == '<' && 				 \
>> +	     ((const char *)(fmt))[1] <= *__stringify(CONFIG_PRINTK_VERBOSITY))) \
>> +		printk((fmt), ##__VA_ARGS__); 					 \
>> +})
>> +
>> +#endif /* CONFIG_PRINTK_VERBOSITY */
>> +
>>  extern struct ratelimit_state printk_ratelimit_state;
>>  extern int printk_ratelimit(void);
>>  extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
>
>
>
> Some places in the kernel break the message into pieces, like so:
>
> printk(KERN_ERR, "Error: first part ");
> ...
> printk(" more info for error.\n");

Technically, shouldn't the second part of the message actually be:

printk(KERN_CONT " more info for error.\n");

Maybe some mechanism could be created to handle the continued message
if they have the KERN_CONT?

> These parts would not be handled consistently under certain
> conditions.
>
> It would be confusing to see only part of the message,
> but I don't know how often this construct is used.  Maybe
> another mechanism is needed to ensure that continuation
> printk lines have the same log level as their start strings.
>
> But, overall, very slick!  It's nice to see a solution that doesn't
> require changing all printks statements in the kernel.

I haven't looked over this patch series yet but does it work with the
pr_<level> macros (pr_info, pr_err, etc.)?

Regards,
Hartley

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Jamie Lokier]

Marc Andre Tanner wrote:
> + * The check with sizeof(void*) should make sure that we don't operate on
> + * pointers, which the compiler wouldn't be able to optimize out, but only
> + * on string constants.

Take a look at __builtin_constant_p in the GCC manual.

You'll probably find that wrapping the whole of the rest of the
expression (without the sizeof) in __builtin_constant_p is a good
way to know when to depend on the result of the expression.

-- Jamie

Re: [RFC|PATCH] Compile time printk verbosity

[Mike Frysinger]

On Tue, Sep 1, 2009 at 18:31, Marc Andre Tanner wrote:
> This series adds a configuration option to selectively compile out
> printk message strings based on a verbosity level.
>
> This works by wrapping printk with a macro which evaluates to a
> constant if condition which the compiler will be able to optimize
> out.
>
> However because printk might be wrapped by a macro it no longer has
> a return value. This means that constructs like the following ones
> don't work:
>
>   ((void)(SOME_RANDOM_DEBUG_FLAG && printk(...));
>
>   some_random_variable = printk(...);
>
> Therefore printk_unfiltered is introduced which is just an alias
> to the standard printk function but not wrapped by a macro.

why dont you return 0 if it gets optimized away ?  then you wont have
to screw with external code at all and things "just work".
-mike

Re: [RFC|PATCH] Compile time printk verbosity

[Marc Andre Tanner]

On Tue, Sep 01, 2009 at 07:37:27PM -0400, Mike Frysinger wrote:
> On Tue, Sep 1, 2009 at 18:31, Marc Andre Tanner wrote:
> > This series adds a configuration option to selectively compile out
> > printk message strings based on a verbosity level.
> >
> > This works by wrapping printk with a macro which evaluates to a
> > constant if condition which the compiler will be able to optimize
> > out.
> >
> > However because printk might be wrapped by a macro it no longer has
> > a return value. This means that constructs like the following ones
> > don't work:
> >
> >   ((void)(SOME_RANDOM_DEBUG_FLAG && printk(...));
> >
> >   some_random_variable = printk(...);
> >
> > Therefore printk_unfiltered is introduced which is just an alias
> > to the standard printk function but not wrapped by a macro.
> 
> why dont you return 0 if it gets optimized away ?  then you wont have
> to screw with external code at all and things "just work".

This won't work because it would for example also return from functions
which call printk but aren't checking for the return value (which is
the common case).

Or am I missing something?

> -mike

Marc

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 12:35:42AM +0100, Jamie Lokier wrote:
> Marc Andre Tanner wrote:
> > + * The check with sizeof(void*) should make sure that we don't operate on
> > + * pointers, which the compiler wouldn't be able to optimize out, but only
> > + * on string constants.
> 
> Take a look at __builtin_constant_p in the GCC manual.
> 
> You'll probably find that wrapping the whole of the rest of the
> expression (without the sizeof) in __builtin_constant_p is a good
> way to know when to depend on the result of the expression.

Thanks, so if I understood it correctly this should be used like this:

#define PRINTK_FILTER(fmt) (							\
	(((const char *)(fmt))[0] != '<' && CONFIG_PRINTK_VERBOSITY >= 4) ||	\
	(((const char *)(fmt))[0] == '<' && 					\
	 ((const char *)(fmt))[1] <= *__stringify(CONFIG_PRINTK_VERBOSITY))	\
)

#define printk(fmt, ...) ({ 							\
	if (__builtin_constant_p(PRINTK_FILTER(fmt)) && PRINTK_FILTER(fmt))	\
		printk((fmt), ##__VA_ARGS__); 					\
})

The sizeof check wouldn't be necessary. Is this correct?

Marc

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [RFC|PATCH] Compile time printk verbosity

[Mike Frysinger]

On Wed, Sep 2, 2009 at 04:57, Marc Andre Tanner wrote:
> On Tue, Sep 01, 2009 at 07:37:27PM -0400, Mike Frysinger wrote:
>> On Tue, Sep 1, 2009 at 18:31, Marc Andre Tanner wrote:
>> > This series adds a configuration option to selectively compile out
>> > printk message strings based on a verbosity level.
>> >
>> > This works by wrapping printk with a macro which evaluates to a
>> > constant if condition which the compiler will be able to optimize
>> > out.
>> >
>> > However because printk might be wrapped by a macro it no longer has
>> > a return value. This means that constructs like the following ones
>> > don't work:
>> >
>> >   ((void)(SOME_RANDOM_DEBUG_FLAG && printk(...));
>> >
>> >   some_random_variable = printk(...);
>> >
>> > Therefore printk_unfiltered is introduced which is just an alias
>> > to the standard printk function but not wrapped by a macro.
>>
>> why dont you return 0 if it gets optimized away ?  then you wont have
>> to screw with external code at all and things "just work".
>
> This won't work because it would for example also return from functions
> which call printk but aren't checking for the return value (which is
> the common case).

why would it matter ?

({
    int __printk_ret = 0;
    if (crazy stuff you're adding)
        __printk_ret = printk(.....);
    __printk_ret;
})
-mike

Re: [RFC|PATCH] Compile time printk verbosity

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 05:11:12AM -0400, Mike Frysinger wrote:
> On Wed, Sep 2, 2009 at 04:57, Marc Andre Tanner wrote:
> > On Tue, Sep 01, 2009 at 07:37:27PM -0400, Mike Frysinger wrote:
> >> On Tue, Sep 1, 2009 at 18:31, Marc Andre Tanner wrote:
> >> > This series adds a configuration option to selectively compile out
> >> > printk message strings based on a verbosity level.
> >> >
> >> > This works by wrapping printk with a macro which evaluates to a
> >> > constant if condition which the compiler will be able to optimize
> >> > out.
> >> >
> >> > However because printk might be wrapped by a macro it no longer has
> >> > a return value. This means that constructs like the following ones
> >> > don't work:
> >> >
> >> >   ((void)(SOME_RANDOM_DEBUG_FLAG && printk(...));
> >> >
> >> >   some_random_variable = printk(...);
> >> >
> >> > Therefore printk_unfiltered is introduced which is just an alias
> >> > to the standard printk function but not wrapped by a macro.
> >>
> >> why dont you return 0 if it gets optimized away ?  then you wont have
> >> to screw with external code at all and things "just work".
> >
> > This won't work because it would for example also return from functions
> > which call printk but aren't checking for the return value (which is
> > the common case).
> 
> why would it matter ?
> 
> ({
>     int __printk_ret = 0;
>     if (crazy stuff you're adding)
>         __printk_ret = printk(.....);
>     __printk_ret;
> })

Yes I missunderstood your "return 0" statement in the first mail. 
The same effect could also be achieved by:

((crazy stuff) ? printk(...) : 0; 

Marc

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 11:03:13AM +0200, Marc Andre Tanner wrote:
> On Wed, Sep 02, 2009 at 12:35:42AM +0100, Jamie Lokier wrote:
> > Marc Andre Tanner wrote:
> > > + * The check with sizeof(void*) should make sure that we don't operate on
> > > + * pointers, which the compiler wouldn't be able to optimize out, but only
> > > + * on string constants.
> > 
> > Take a look at __builtin_constant_p in the GCC manual.
> > 
> > You'll probably find that wrapping the whole of the rest of the
> > expression (without the sizeof) in __builtin_constant_p is a good
> > way to know when to depend on the result of the expression.
> 
> Thanks, so if I understood it correctly this should be used like this:
> 
> #define PRINTK_FILTER(fmt) (							\
> 	(((const char *)(fmt))[0] != '<' && CONFIG_PRINTK_VERBOSITY >= 4) ||	\
> 	(((const char *)(fmt))[0] == '<' && 					\
> 	 ((const char *)(fmt))[1] <= *__stringify(CONFIG_PRINTK_VERBOSITY))	\
> )
> 
> #define printk(fmt, ...) ({ 							\
> 	if (__builtin_constant_p(PRINTK_FILTER(fmt)) && PRINTK_FILTER(fmt))	\

This should have been:
	
 	if (!__builtin_constant_p(PRINTK_FILTER(fmt)) || PRINTK_FILTER(fmt))	\

> 		printk((fmt), ##__VA_ARGS__); 					\
> })
> 
> The sizeof check wouldn't be necessary. Is this correct?

Marc

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [RFC|PATCH] Compile time printk verbosity

[Mike Frysinger]

On Wed, Sep 2, 2009 at 05:47, Marc Andre Tanner wrote:
> On Wed, Sep 02, 2009 at 05:11:12AM -0400, Mike Frysinger wrote:
>> On Wed, Sep 2, 2009 at 04:57, Marc Andre Tanner wrote:
>> > On Tue, Sep 01, 2009 at 07:37:27PM -0400, Mike Frysinger wrote:
>> >> On Tue, Sep 1, 2009 at 18:31, Marc Andre Tanner wrote:
>> >> > This series adds a configuration option to selectively compile out
>> >> > printk message strings based on a verbosity level.
>> >> >
>> >> > This works by wrapping printk with a macro which evaluates to a
>> >> > constant if condition which the compiler will be able to optimize
>> >> > out.
>> >> >
>> >> > However because printk might be wrapped by a macro it no longer has
>> >> > a return value. This means that constructs like the following ones
>> >> > don't work:
>> >> >
>> >> >   ((void)(SOME_RANDOM_DEBUG_FLAG && printk(...));
>> >> >
>> >> >   some_random_variable = printk(...);
>> >> >
>> >> > Therefore printk_unfiltered is introduced which is just an alias
>> >> > to the standard printk function but not wrapped by a macro.
>> >>
>> >> why dont you return 0 if it gets optimized away ?  then you wont have
>> >> to screw with external code at all and things "just work".
>> >
>> > This won't work because it would for example also return from functions
>> > which call printk but aren't checking for the return value (which is
>> > the common case).
>>
>> why would it matter ?
>>
>> ({
>>     int __printk_ret = 0;
>>     if (crazy stuff you're adding)
>>         __printk_ret = printk(.....);
>>     __printk_ret;
>> })
>
> Yes I missunderstood your "return 0" statement in the first mail.
> The same effect could also be achieved by:
>
> ((crazy stuff) ? printk(...) : 0;

while true, i thought your (crazy stuff) pretty verbose and the
tertiary operator might get swallowed in the noise.  not that it
matters that much to me as this is now a pure style choice ... your
patch, you pick.
-mike

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Jamie Lokier]

Marc Andre Tanner wrote:
> Thanks, so if I understood it correctly this should be used like this:
> 
> #define PRINTK_FILTER(fmt) (							\
> 	(((const char *)(fmt))[0] != '<' && CONFIG_PRINTK_VERBOSITY >= 4) ||	\
> 	(((const char *)(fmt))[0] == '<' && 					\
> 	 ((const char *)(fmt))[1] <= *__stringify(CONFIG_PRINTK_VERBOSITY))	\
> )
> 
> #define printk(fmt, ...) ({ 							\
> 	if (__builtin_constant_p(PRINTK_FILTER(fmt)) && PRINTK_FILTER(fmt))	\
> 		printk((fmt), ##__VA_ARGS__); 					\
> })
> 
> The sizeof check wouldn't be necessary. Is this correct?

Looks good, except that I think kernel style is to use "do {...} while
(0)" rather than "({ ... })"

-- Jamie

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Bill Gatliff]

Jamie Lokier wrote:
> Looks good, except that I think kernel style is to use "do {...} while
> (0)" rather than "({ ... })"
>   

And IIRC, there was some reason for the do{...} while(0) that made other 
alternatives not work.  So it might be more than just style at issue.


b.g.

-- 
Bill Gatliff
bgat@billgatliff.com

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 07:25:43AM -0500, Bill Gatliff wrote:
> Jamie Lokier wrote:
> >Looks good, except that I think kernel style is to use "do {...} while
> >(0)" rather than "({ ... })"
> 
> And IIRC, there was some reason for the do{...} while(0) that made
> other alternatives not work.  So it might be more than just style at
> issue.

Do you remember the reason? I found the oposite to be ture, I actually 
started with the do { } while(0) construct but it failed in certain 
situations so I wrapped it with ({ }) and then later removed
the now useless do { } while(0).

By the way printk_once which is defined a few lines further down in
kernel.h also uses ({ }).

Anyway the next version of my patch will no longer need it.

Regards,
Marc

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Mike Frysinger]

On Wed, Sep 2, 2009 at 08:44, Marc Andre Tanner wrote:
> On Wed, Sep 02, 2009 at 07:25:43AM -0500, Bill Gatliff wrote:
>> Jamie Lokier wrote:
>> >Looks good, except that I think kernel style is to use "do {...} while
>> >(0)" rather than "({ ... })"
>>
>> And IIRC, there was some reason for the do{...} while(0) that made
>> other alternatives not work.  So it might be more than just style at
>> issue.
>
> Do you remember the reason? I found the oposite to be ture, I actually
> started with the do { } while(0) construct but it failed in certain
> situations so I wrapped it with ({ }) and then later removed
> the now useless do { } while(0).
>
> By the way printk_once which is defined a few lines further down in
> kernel.h also uses ({ }).
>
> Anyway the next version of my patch will no longer need it.

it depends completely on how the macro is intended to be used.  if you
want to maintain the "this macro has a return value", then you have to
use ({...}).  if you want the macro to return a void, then you have to
use do{...}while(0).
-mike

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
> > Some places in the kernel break the message into pieces, like so:
> >
> > printk(KERN_ERR, "Error: first part ");
> > ...
> > printk(" more info for error.\n");
> 
> Technically, shouldn't the second part of the message actually be:
> 
> printk(KERN_CONT " more info for error.\n");
> 
> Maybe some mechanism could be created to handle the continued message
> if they have the KERN_CONT?

Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
to change that.

> > These parts would not be handled consistently under certain
> > conditions.
> >
> > It would be confusing to see only part of the message,
> > but I don't know how often this construct is used.  

$ grep -R KERN_CONT linux-2.6 | wc -l
373

> > Maybe
> > another mechanism is needed to ensure that continuation
> > printk lines have the same log level as their start strings.

I currently don't see a way to achieve this with the CPP.

> > But, overall, very slick!  It's nice to see a solution that doesn't
> > require changing all printks statements in the kernel.

Yes that's what I thought too. Thanks to the comments so far the next 
version of the patch will contain even less changes to the rest of the 
kernel.
 
> I haven't looked over this patch series yet but does it work with the
> pr_<level> macros (pr_info, pr_err, etc.)?

It should work, yes.

Regards,
Marc

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 08:54:47AM -0400, Mike Frysinger wrote:
> On Wed, Sep 2, 2009 at 08:44, Marc Andre Tanner wrote:
> > On Wed, Sep 02, 2009 at 07:25:43AM -0500, Bill Gatliff wrote:
> >> Jamie Lokier wrote:
> >> >Looks good, except that I think kernel style is to use "do {...} while
> >> >(0)" rather than "({ ... })"
> >>
> >> And IIRC, there was some reason for the do{...} while(0) that made
> >> other alternatives not work.  So it might be more than just style at
> >> issue.
> >
> > Do you remember the reason? I found the oposite to be ture, I actually
> > started with the do { } while(0) construct but it failed in certain
> > situations so I wrapped it with ({ }) and then later removed
> > the now useless do { } while(0).
> >
> > By the way printk_once which is defined a few lines further down in
> > kernel.h also uses ({ }).
> >
> > Anyway the next version of my patch will no longer need it.
> 
> it depends completely on how the macro is intended to be used.  if you
> want to maintain the "this macro has a return value", then you have to
> use ({...}).  if you want the macro to return a void, then you have to
> use do{...}while(0).

Ok, thanks for the clarification. This makes sense.

Marc

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Jamie Lokier]

Mike Frysinger wrote:
> it depends completely on how the macro is intended to be used.  if you
> want to maintain the "this macro has a return value", then you have to
> use ({...}).  if you want the macro to return a void, then you have to
> use do{...}while(0).

Actually no.  The difference is do {...} while(0) is a _statement_ and
cannot be used in an expression.  Whereas a void value can be used in
expressions like A?B:C, (A,B) and returned from a function, it just
has type void.

-- Jamie

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Tim Bird]

Marc Andre Tanner wrote:
> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
>>> Some places in the kernel break the message into pieces, like so:
>>>
>>> printk(KERN_ERR, "Error: first part ");
>>> ...
>>> printk(" more info for error.\n");
>> Technically, shouldn't the second part of the message actually be:
>>
>> printk(KERN_CONT " more info for error.\n");
>>
>> Maybe some mechanism could be created to handle the continued message
>> if they have the KERN_CONT?
> 
> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
> to change that.
> 
>>> These parts would not be handled consistently under certain
>>> conditions.
>>>
>>> It would be confusing to see only part of the message,
>>> but I don't know how often this construct is used.  
> 
> $ grep -R KERN_CONT linux-2.6 | wc -l
> 373
> 
>>> Maybe
>>> another mechanism is needed to ensure that continuation
>>> printk lines have the same log level as their start strings.
> 
> I currently don't see a way to achieve this with the CPP.

If it's that few, then maybe it's OK to actually change
the code for those printk statements. (Heck, these locations
were all changed in the last 2 years anyway.)

I'm just brainstorming here, but how about changing them from:
  printk(KERN_INFO "foo");
  printk(KERN_CONT "bar\n");
to:
  printk(KERN_INFO "foo");
  printk_cont(KERN_INFO "bar\n");

This way the continuation line has the log level, and can
be conditionally compiled based on the VERBOSITY level.  A little
magic would be needed to strip the first 3 chars of the fmt
string in printk_cont().

I think this makes the printk messages a bit more consistent anyway,
and still marks lines that are continuation lines.

>>> But, overall, very slick!  It's nice to see a solution that doesn't
>>> require changing all printks statements in the kernel.
> 
> Yes that's what I thought too. Thanks to the comments so far the next 
> version of the patch will contain even less changes to the rest of the 
> kernel.
>  
>> I haven't looked over this patch series yet but does it work with the
>> pr_<level> macros (pr_info, pr_err, etc.)?
> 
> It should work, yes.

 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Tim Bird]

Tim Bird wrote:
> Marc Andre Tanner wrote:
>> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
>>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
>>>> Some places in the kernel break the message into pieces, like so:
>>>>
>>>> printk(KERN_ERR, "Error: first part ");
>>>> ...
>>>> printk(" more info for error.\n");
>>> Technically, shouldn't the second part of the message actually be:
>>>
>>> printk(KERN_CONT " more info for error.\n");
>>>
>>> Maybe some mechanism could be created to handle the continued message
>>> if they have the KERN_CONT?
>> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
>> to change that.
>>
>>>> These parts would not be handled consistently under certain
>>>> conditions.
>>>>
>>>> It would be confusing to see only part of the message,
>>>> but I don't know how often this construct is used.  
>> $ grep -R KERN_CONT linux-2.6 | wc -l
>> 373
>>
>>>> Maybe
>>>> another mechanism is needed to ensure that continuation
>>>> printk lines have the same log level as their start strings.
>> I currently don't see a way to achieve this with the CPP.
> 
> If it's that few, then maybe it's OK to actually change
> the code for those printk statements. (Heck, these locations
> were all changed in the last 2 years anyway.)
> 
> I'm just brainstorming here, but how about changing them from:
>   printk(KERN_INFO "foo");
>   printk(KERN_CONT "bar\n");
> to:
>   printk(KERN_INFO "foo");
>   printk_cont(KERN_INFO "bar\n");
> 
> This way the continuation line has the log level, and can
> be conditionally compiled based on the VERBOSITY level.  A little
> magic would be needed to strip the first 3 chars of the fmt
> string in printk_cont().
> 
> I think this makes the printk messages a bit more consistent anyway,
> and still marks lines that are continuation lines.

Just another note.  Detecting continuation lines also complicates
the printk timestamping code.  If all continuation lines were
distinguishable by the printk code, then it might be possible
to simplify the timestamping code as a side effect of the
change.
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

RE: [PATCH 7/7] printk: provide a filtering macro for printk

[H Hartley Sweeten]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 2664 bytes --]

On Wednesday, September 02, 2009 10:05 AM, Tim Bird wrote:
> Marc Andre Tanner wrote:
>> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
>>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
>>>> Some places in the kernel break the message into pieces, like so:
>>>>
>>>> printk(KERN_ERR, "Error: first part ");
>>>> ...
>>>> printk(" more info for error.\n");
>>> Technically, shouldn't the second part of the message actually be:
>>>
>>> printk(KERN_CONT " more info for error.\n");
>>>
>>> Maybe some mechanism could be created to handle the continued message
>>> if they have the KERN_CONT?
>> 
>> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
>> to change that.
>> 
>>>> These parts would not be handled consistently under certain
>>>> conditions.
>>>>
>>>> It would be confusing to see only part of the message,
>>>> but I don't know how often this construct is used.  
>> 
>> $ grep -R KERN_CONT linux-2.6 | wc -l
>> 373
>> 
>>>> Maybe
>>>> another mechanism is needed to ensure that continuation
>>>> printk lines have the same log level as their start strings.
>> 
>> I currently don't see a way to achieve this with the CPP.
>
> If it's that few, then maybe it's OK to actually change
> the code for those printk statements. (Heck, these locations
> were all changed in the last 2 years anyway.)
> 
> I'm just brainstorming here, but how about changing them from:
>   printk(KERN_INFO "foo");
>   printk(KERN_CONT "bar\n");
> to:
>   printk(KERN_INFO "foo");
>   printk_cont(KERN_INFO "bar\n");
> 

Unfortunately not all the continued printk statements in the kernel are
properly tagged with KERN_CONT (or pr_cont, etc.).

> This way the continuation line has the log level, and can
> be conditionally compiled based on the VERBOSITY level.  A little
> magic would be needed to strip the first 3 chars of the fmt
> string in printk_cont().
> 
> I think this makes the printk messages a bit more consistent anyway,
> and still marks lines that are continuation lines.
> 
>>>> But, overall, very slick!  It's nice to see a solution that doesn't
>>>> require changing all printks statements in the kernel.
>> 
>> Yes that's what I thought too. Thanks to the comments so far the next 
>> version of the patch will contain even less changes to the rest of the 
>> kernel.
>>  
>>> I haven't looked over this patch series yet but does it work with the
>>> pr_<level> macros (pr_info, pr_err, etc.)?
>> 
>> It should work, yes.

Regards,
Hartley
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

RE: [PATCH 7/7] printk: provide a filtering macro for printk

[H Hartley Sweeten]

On Wednesday, September 02, 2009 10:05 AM, Tim Bird wrote:
> Marc Andre Tanner wrote:
>> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
>>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
>>>> Some places in the kernel break the message into pieces, like so:
>>>>
>>>> printk(KERN_ERR, "Error: first part ");
>>>> ...
>>>> printk(" more info for error.\n");
>>> Technically, shouldn't the second part of the message actually be:
>>>
>>> printk(KERN_CONT " more info for error.\n");
>>>
>>> Maybe some mechanism could be created to handle the continued message
>>> if they have the KERN_CONT?
>> 
>> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
>> to change that.
>> 
>>>> These parts would not be handled consistently under certain
>>>> conditions.
>>>>
>>>> It would be confusing to see only part of the message,
>>>> but I don't know how often this construct is used.  
>> 
>> $ grep -R KERN_CONT linux-2.6 | wc -l
>> 373
>> 
>>>> Maybe
>>>> another mechanism is needed to ensure that continuation
>>>> printk lines have the same log level as their start strings.
>> 
>> I currently don't see a way to achieve this with the CPP.
>
> If it's that few, then maybe it's OK to actually change
> the code for those printk statements. (Heck, these locations
> were all changed in the last 2 years anyway.)
> 
> I'm just brainstorming here, but how about changing them from:
>   printk(KERN_INFO "foo");
>   printk(KERN_CONT "bar\n");
> to:
>   printk(KERN_INFO "foo");
>   printk_cont(KERN_INFO "bar\n");
> 

Unfortunately not all the continued printk statements in the kernel are
properly tagged with KERN_CONT (or pr_cont, etc.).

> This way the continuation line has the log level, and can
> be conditionally compiled based on the VERBOSITY level.  A little
> magic would be needed to strip the first 3 chars of the fmt
> string in printk_cont().
> 
> I think this makes the printk messages a bit more consistent anyway,
> and still marks lines that are continuation lines.
> 
>>>> But, overall, very slick!  It's nice to see a solution that doesn't
>>>> require changing all printks statements in the kernel.
>> 
>> Yes that's what I thought too. Thanks to the comments so far the next 
>> version of the patch will contain even less changes to the rest of the 
>> kernel.
>>  
>>> I haven't looked over this patch series yet but does it work with the
>>> pr_<level> macros (pr_info, pr_err, etc.)?
>> 
>> It should work, yes.

Regards,
Hartley

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 02:22:52PM -0400, H Hartley Sweeten wrote:
> On Wednesday, September 02, 2009 10:05 AM, Tim Bird wrote:
> > Marc Andre Tanner wrote:
> >> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
> >>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
> >>>> Some places in the kernel break the message into pieces, like so:
> >>>>
> >>>> printk(KERN_ERR, "Error: first part ");
> >>>> ...
> >>>> printk(" more info for error.\n");
> >>> Technically, shouldn't the second part of the message actually be:
> >>>
> >>> printk(KERN_CONT " more info for error.\n");
> >>>
> >>> Maybe some mechanism could be created to handle the continued message
> >>> if they have the KERN_CONT?
> >> 
> >> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
> >> to change that.
> >> 
> >>>> These parts would not be handled consistently under certain
> >>>> conditions.
> >>>>
> >>>> It would be confusing to see only part of the message,
> >>>> but I don't know how often this construct is used.  
> >> 
> >> $ grep -R KERN_CONT linux-2.6 | wc -l
> >> 373
> >> 
> >>>> Maybe
> >>>> another mechanism is needed to ensure that continuation
> >>>> printk lines have the same log level as their start strings.
> >> 
> >> I currently don't see a way to achieve this with the CPP.
> >
> > If it's that few, then maybe it's OK to actually change
> > the code for those printk statements. (Heck, these locations
> > were all changed in the last 2 years anyway.)
> > 
> > I'm just brainstorming here, but how about changing them from:
> >   printk(KERN_INFO "foo");
> >   printk(KERN_CONT "bar\n");
> > to:
> >   printk(KERN_INFO "foo");
> >   printk_cont(KERN_INFO "bar\n");
> 
> Unfortunately not all the continued printk statements in the kernel are
> properly tagged with KERN_CONT (or pr_cont, etc.).

Yes and a quick search revealed that there are actually quite a lot of
those untagged messages.

As I needed some distraction from some other work I played around a bit
more with a solution which wouldn't require to change existing kernel
code. It uses a variable which would have to be available in every
function to store the loglevel of messages which are split over multiple
printk calls. Here is what I came up with so far:

#define PRINTK_IS_LINE(fmt) (					\
	((const char*)(fmt))[sizeof((fmt)) - 2] == '\n'		\
)

#define PRINTK_LEVEL(fmt) (					\
	(((const char *)(fmt))[0] == '<' &&			\
	 ((const char *)(fmt))[1] >= '0' &&			\
	 ((const char *)(fmt))[1] <= '9'			\
	) ? ((const char *)(fmt))[1] - '0' : 4			\
)

#define printk(fmt, ...) ({ 								\
	int __printk_ret = 0;								\
	int __printk_level = __printk_cont_level;					\
											\
	if (__builtin_constant_p((fmt)) && ((fmt))) {					\
		/* check if we are dealing with a line ending */			\
		if (PRINTK_IS_LINE((fmt))) {						\
			/* check if it was a whole line */				\
			if (__printk_cont_level == -1)					\
				__printk_level = PRINTK_LEVEL((fmt));			\
			__printk_cont_level = -1;					\
		} else if (__printk_cont_level == -1) /* first part of a line? */	\
			__printk_level = __printk_cont_level = PRINTK_LEVEL((fmt));	\
	}										\
											\
	if (!__builtin_constant_p((fmt)) || __printk_level <= CONFIG_PRINTK_VERBOSITY)	\
		__printk_ret = printk((fmt), ##__VA_ARGS__); 				\
											\
	__printk_ret;									\
})

Apart from the fact that it's getting uglier it obviously depends on
the availability of __printk_cont_level (which would get compiled out,
at least I hope so) in every function. 

So

void demo() {
	...
}

would have to become:

void demo() {
	int __printk_cont_level = -1;
	...	
}

I don't know whether this is possible at all through some kind of gcc
magic. There is also the problem of introducing warnings when 
__prink_cont_level isn't used in a function but I guess this could be
dealt with some __attribute__ setting.

Anyway just wanted to share the results of a brainstorming session.

Marc 

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Geert Uytterhoeven]

On Wed, 2 Sep 2009, Tim Bird wrote:
> Marc Andre Tanner wrote:
> > On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
> >> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
> >>> Some places in the kernel break the message into pieces, like so:
> >>>
> >>> printk(KERN_ERR, "Error: first part ");
> >>> ...
> >>> printk(" more info for error.\n");
> >> Technically, shouldn't the second part of the message actually be:
> >>
> >> printk(KERN_CONT " more info for error.\n");
> >>
> >> Maybe some mechanism could be created to handle the continued message
> >> if they have the KERN_CONT?
> > 
> > Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
> > to change that.
> > 
> >>> These parts would not be handled consistently under certain
> >>> conditions.
> >>>
> >>> It would be confusing to see only part of the message,
> >>> but I don't know how often this construct is used.  
> > 
> > $ grep -R KERN_CONT linux-2.6 | wc -l
> > 373
> > 
> >>> Maybe
> >>> another mechanism is needed to ensure that continuation
> >>> printk lines have the same log level as their start strings.
> > 
> > I currently don't see a way to achieve this with the CPP.
> 
> If it's that few, then maybe it's OK to actually change
> the code for those printk statements. (Heck, these locations
> were all changed in the last 2 years anyway.)
> 
> I'm just brainstorming here, but how about changing them from:
>   printk(KERN_INFO "foo");
>   printk(KERN_CONT "bar\n");
> to:
>   printk(KERN_INFO "foo");
>   printk_cont(KERN_INFO "bar\n");
> 
> This way the continuation line has the log level, and can
> be conditionally compiled based on the VERBOSITY level.  A little
> magic would be needed to strip the first 3 chars of the fmt
> string in printk_cont().

You could strip the first 3 chars by adding 3 to the pointer. Which will
fail horribly if the KERN_* is forgotten and the format string is very short.
And the KERN_* still consumes memory.

Or make the KERN_* an explicit first parameter:

    printk_cont(KERN_INFO, "bar\n");

Is "strcmp(p, KERN_INFO)" optimized away for constant strings?

> I think this makes the printk messages a bit more consistent anyway,
> and still marks lines that are continuation lines.

With kind regards,

Geert Uytterhoeven
Software Architect
Techsoft Centre

Technology and Software Centre Europe
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone:    +32 (0)2 700 8453
Fax:      +32 (0)2 700 8622
E-mail:   Geert.Uytterhoeven@sonycom.com
Internet: http://www.sony-europe.com/

A division of Sony Europe (Belgium) N.V.
VAT BE 0413.825.160 · RPR Brussels
Fortis · BIC GEBABEBB · IBAN BE41293037680010