[RFC|PATCHv2] Compile time printk verbosity

[RFC|PATCHv2] 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.

For situation were this filtering mechanism is not desired an 
unfiltered variant is introduced: printk_unfiltered.

Currently the unfiltered variant is only used within
drivers/char/mem.c because we don't want to filter user space
data which comes is sent to /dev/kmsg.

Are there other places where the unfiltered variant should be used?

A known problem is that KERN_CONT messages aren't handled correctly.

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

Thanks to Mike Frysinger and Jamie Lokier for their suggestions for
improvement. 

All kinds of comments are welcome.

Marc Andre Tanner (5):
      printk: introduce CONFIG_PRINTK_VERBOSITY
      printk: move printk to the end of the file
      printk: introduce printk_unfiltered as an alias to printk
      char/mem: replace printk with printk_unfiltered
      printk: provide a filtering macro for printk

 drivers/char/mem.c     |    2 +-
 include/linux/kernel.h |   28 ++++++++++++++
 init/Kconfig           |   28 ++++++++++++++
 kernel/printk.c        |   95 ++++++++++++++++++++++++++++++------------------
 4 files changed, 117 insertions(+), 36 deletions(-)

[PATCH 1/5] 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 |   29 +++++++++++++++++++++++++++++
 1 files changed, 29 insertions(+), 0 deletions(-)

diff --git a/init/Kconfig b/init/Kconfig
index 3f7e609..549ed95 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -833,6 +833,35 @@ 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 listed below. Note that messages
+	  without an explicit loglevel will be classified as KERN_WARNING.
+
+	   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

Re: [PATCH 1/5] printk: introduce CONFIG_PRINTK_VERBOSITY

[Marco Stornelli]

Marc Andre Tanner ha scritto:
> 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 |   29 +++++++++++++++++++++++++++++
>  1 files changed, 29 insertions(+), 0 deletions(-)
> 
> diff --git a/init/Kconfig b/init/Kconfig
> index 3f7e609..549ed95 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -833,6 +833,35 @@ 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 listed below. Note that messages
> +	  without an explicit loglevel will be classified as KERN_WARNING.
> +
> +	   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

If there are some problems to handle KERN_CONT you should say something
here. You should even add in cc: the kernel ML, however it seems a good
work.

Marco

Re: [PATCH 1/5] printk: introduce CONFIG_PRINTK_VERBOSITY

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 06:44:06PM +0200, Marco Stornelli wrote:
> Marc Andre Tanner ha scritto:
> > 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 |   29 +++++++++++++++++++++++++++++
> >  1 files changed, 29 insertions(+), 0 deletions(-)
> > 
> > diff --git a/init/Kconfig b/init/Kconfig
> > index 3f7e609..549ed95 100644
> > --- a/init/Kconfig
> > +++ b/init/Kconfig
> > @@ -833,6 +833,35 @@ 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 listed below. Note that messages
> > +	  without an explicit loglevel will be classified as KERN_WARNING.
> > +
> > +	   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
> 
> If there are some problems to handle KERN_CONT you should say something
> here.

ACK.

> You should even add in cc: the kernel ML, however it seems a good
> work.

Well I first wanted to get some feedback from the embedded people.
I will probably send it to LKML after the 2.6.31 release, don't know
how the chances for inclusion are though.

Marc 

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

[PATCH 2/5] 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/5] printk: introduce printk_unfiltered as an alias to printk

[Marc Andre Tanner]

The standard printk function will be wrapped by a macro which
filters out messages above a certain verbosity level. Because
this might not be desired in certain situations we provide an
unfiltered variant.

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 include/linux/kernel.h |    5 +++++
 kernel/printk.c        |   23 +++++++++++++++++++++++
 2 files changed, 28 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..0a2f654 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 which will filter out messages above a certain verbosity level.
+ * In cases where it's important that the message will get through independenly
+ * of the configuration setting printk_unfiltered 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,14 @@ asmlinkage int printk(const char *fmt, ...)
 	return r;
 }
 EXPORT_SYMBOL(printk);
+
+/*
+ * Because printk might be wrapped by a macro which will filter out messages
+ * above a certain verbosity level we provide an unfiltered variant for use
+ * cases where the filtering isn't desired.
+ */
+
+asmlinkage int printk_unfiltered(const char *fmt, ...)
+	__attribute__((alias("printk")));
+EXPORT_SYMBOL(printk_unfiltered);
 #endif
-- 
1.6.3.3

[PATCH 4/5] char/mem: replace printk with printk_unfiltered

[Marc Andre Tanner]

We don't want to filter user space data which comes from /dev/kmsg.

Signed-off-by: Marc Andre Tanner <mat@brain-dump.org>
---
 drivers/char/mem.c |    2 +-
 1 files changed, 1 insertions(+), 1 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;
-- 
1.6.3.3

[PATCH 5/5] 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 |   23 +++++++++++++++++++++++
 1 files changed, 23 insertions(+), 0 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index c2b3047..1ecc338 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -242,6 +242,29 @@ 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.
+ */
+
+#include <linux/stringify.h>
+
+#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, ...) ( 							\
+	(!__builtin_constant_p(PRINTK_FILTER((fmt))) || PRINTK_FILTER((fmt))) ?	\
+		printk((fmt), ##__VA_ARGS__) : 0				\
+)
+
+#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 5/5] printk: provide a filtering macro for printk

[Marco Stornelli]

Marc Andre Tanner ha scritto:
> +#define printk(fmt, ...) ( 							\

Shouldn't it be an and?

> +	(!__builtin_constant_p(PRINTK_FILTER((fmt))) || PRINTK_FILTER((fmt))) ?	\
> +		printk((fmt), ##__VA_ARGS__) : 0				\
> +)
> +
> +#endif /* CONFIG_PRINTK_VERBOSITY */
> +


Marco

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

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 06:44:19PM +0200, Marco Stornelli wrote:
> 
> 
> Marc Andre Tanner ha scritto:
> > +#define printk(fmt, ...) ( 							\
> 
> Shouldn't it be an and?

Don't think so. If the expression isn't constant we are unable to filter it
and therefore printk is called anyway. However if the expression is constant
the second part of the condition is evaluated and we filter based on the 
verbosity level.

> > +	(!__builtin_constant_p(PRINTK_FILTER((fmt))) || PRINTK_FILTER((fmt))) ?	\
> > +		printk((fmt), ##__VA_ARGS__) : 0				\
> > +)
> > +
> > +#endif /* CONFIG_PRINTK_VERBOSITY */
> > +

Marc

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

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

[Marco Stornelli]

2009/9/2 Marc Andre Tanner <mat@brain-dump.org>:
> On Wed, Sep 02, 2009 at 06:44:19PM +0200, Marco Stornelli wrote:
>>
>>
>> Marc Andre Tanner ha scritto:
>> > +#define printk(fmt, ...) (                                                         \
>>
>> Shouldn't it be an and?
>
> Don't think so. If the expression isn't constant we are unable to filter it
> and therefore printk is called anyway. However if the expression is constant
> the second part of the condition is evaluated and we filter based on the
> verbosity level.
>

Yes, you're right.

Marco