[RFC PATCH] printk: Make functions of pr_<level> macros

[RFC PATCH] printk: Make functions of pr_<level> macros

[Joe Perches]

Can save the space that the KERN_<LEVEL> headers require.

The biggest negative here is the %pV use which needs
recursion and adds stack depth.

$ size vmlinux.o* (defconfig, x86-64)
   text     data     bss      dec     hex  filename
12586135  1909841  777528 15273504  e90e20 vmlinux.o.new
12590348  1909841  777528 15277717  e91e95 vmlinux.o.old

Signed-off-by: Joe Perches <joe@perches.com>
---
 include/linux/printk.h | 57 ++++++++++++++++++++++++++++++++++++--------------
 kernel/printk/printk.c | 28 +++++++++++++++++++++++++
 2 files changed, 69 insertions(+), 16 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 3c635b610bdc..0e912e393ed5 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -171,6 +171,28 @@ int printk_emit(int facility, int level,
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 
+asmlinkage __printf(1, 2) __cold
+int __pr_emerg(const char *fmt, ...);
+asmlinkage __printf(1, 2) __cold
+int __pr_alert(const char *fmt, ...);
+asmlinkage __printf(1, 2) __cold
+int __pr_crit(const char *fmt, ...);
+asmlinkage __printf(1, 2) __cold
+int __pr_err(const char *fmt, ...);
+asmlinkage __printf(1, 2) __cold
+int __pr_warn(const char *fmt, ...);
+asmlinkage __printf(1, 2) __cold
+int __pr_notice(const char *fmt, ...);
+asmlinkage __printf(1, 2) __cold
+int __pr_info(const char *fmt, ...);
+/*
+ * Like KERN_CONT, pr_cont() should only be used when continuing
+ * a line with no newline ('\n') enclosed. Otherwise it defaults
+ * back to KERN_DEFAULT.
+ */
+asmlinkage __printf(1, 2) __cold
+int pr_cont(const char *fmt, ...);
+
 /*
  * Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
  */
@@ -217,6 +239,15 @@ int printk(const char *s, ...)
 {
 	return 0;
 }
+#define __pr_emerg	printk
+#define __pr_alert	printk
+#define __pr_crit	printk
+#define __pr_err	printk
+#define __pr_warn	printk
+#define __pr_notice	printk
+#define __pr_info	printk
+#define pr_cont		printk
+
 static inline __printf(1, 2) __cold
 int printk_deferred(const char *s, ...)
 {
@@ -292,27 +323,21 @@ extern asmlinkage void dump_stack(void) __cold;
  * or CONFIG_DYNAMIC_DEBUG is set.
  */
 #define pr_emerg(fmt, ...) \
-	printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
+	__pr_emerg(pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_alert(fmt, ...) \
-	printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
+	__pr_alert(pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_crit(fmt, ...) \
-	printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
+	__pr_crit(pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_err(fmt, ...) \
-	printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_warning(fmt, ...) \
-	printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_warn pr_warning
+	__pr_err(pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn(fmt, ...) \
+	__pr_warn(pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_notice(fmt, ...) \
-	printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
+	__pr_notice(pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_info(fmt, ...) \
-	printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
-/*
- * Like KERN_CONT, pr_cont() should only be used when continuing
- * a line with no newline ('\n') enclosed. Otherwise it defaults
- * back to KERN_DEFAULT.
- */
-#define pr_cont(fmt, ...) \
-	printk(KERN_CONT fmt, ##__VA_ARGS__)
+	__pr_info(pr_fmt(fmt), ##__VA_ARGS__)
+
+#define pr_warning pr_warn
 
 /* pr_devel() should produce zero code unless DEBUG is defined */
 #ifdef DEBUG
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 34da86e73d00..8d3d93f27921 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1843,6 +1843,34 @@ asmlinkage __visible int printk(const char *fmt, ...)
 }
 EXPORT_SYMBOL(printk);
 
+#define define_pr_func(func, level)			\
+asmlinkage __visible int func(const char *fmt, ...)	\
+{							\
+	va_list args;					\
+	int r;						\
+	struct va_format vaf;				\
+							\
+	va_start(args, fmt);				\
+	vaf.fmt = fmt;					\
+	vaf.va = &args;					\
+							\
+	r = printk(level "%pV", &vaf);			\
+							\
+	va_end(args);					\
+							\
+	return r;					\
+}							\
+EXPORT_SYMBOL(func)
+
+define_pr_func(__pr_emerg,	KERN_EMERG);
+define_pr_func(__pr_alert,	KERN_ALERT);
+define_pr_func(__pr_crit,	KERN_CRIT);
+define_pr_func(__pr_err,	KERN_ERR);
+define_pr_func(__pr_warn,	KERN_WARNING);
+define_pr_func(__pr_notice,	KERN_NOTICE);
+define_pr_func(__pr_info,	KERN_INFO);
+define_pr_func(pr_cont,		KERN_CONT);
+
 #else /* CONFIG_PRINTK */
 
 #define LOG_LINE_MAX		0
-- 
2.10.0.rc2.1.g053435c

Re: [RFC PATCH] printk: Make functions of pr_<level> macros

[Sergey Senozhatsky]

Hello Joe,

On (02/28/17 19:17), Joe Perches wrote:
> Can save the space that the KERN_<LEVEL> headers require.
> 
> The biggest negative here is the %pV use which needs
> recursion and adds stack depth.
> 
> $ size vmlinux.o* (defconfig, x86-64)
>    text     data     bss      dec     hex  filename
> 12586135  1909841  777528 15273504  e90e20 vmlinux.o.new
> 12590348  1909841  777528 15277717  e91e95 vmlinux.o.old

interesting. 4K.

[..]
> +#define define_pr_func(func, level)			\
> +asmlinkage __visible int func(const char *fmt, ...)	\
> +{							\
> +	va_list args;					\
> +	int r;						\
> +	struct va_format vaf;				\
> +							\
> +	va_start(args, fmt);				\
> +	vaf.fmt = fmt;					\
> +	vaf.va = &args;					\
> +							\
> +	r = printk(level "%pV", &vaf);			\
> +							\
> +	va_end(args);					\
> +							\
> +	return r;					\
> +}							\

hm. that's really hacky (which is a compliment) and a bit complicated.
my quick thought was to tweak vprintk_emit() for 'facility != 0' so it
could get loglevel (and adjust lflags) from the passed level, not from
the text, and then do something like this

#define define_pr_func(func, level) asmlinkage __visible int func(const char *fmt, ...)
{
	va_start(args, fmt);
	r = vprintk_emit(level[0], level[1], NULL, 0, fmt, args);
	va_end();
}

but this won't do the trick. because func()->vprintk_emit() shortcut
disables the printk-safe mechanism:
	func()->printk()->vprintk_func()->this_cpu(printk_context)::print()

this *probably* and *may be* works for dev_printk() /* assuming that
dev_printk() is never called fomr under sched/sempahore/etc locks */,
but for printk() in general it's a huge no-no-no.

so I see that you did the very same thing in 99bcf217183e02ebae for
dev_printk(), which is, once again, probably ok for dev_print(). and
now the question is do we want to add %pV recursion to non-dev
printk-s, and I'm, frankly, don't have any answers at the moment.
sorry.

there are already %pV pr_foo() calls in the kernel. and we even have %pV in
OOM path. now those calls are going to be %pV->%pV = recursion depth 2.

for example I can easily do this thing:

[   38.006766] WARNING: CPU: 2 PID: 368 at lib/vsprintf.c:1901 format_decode+0x226/0x2fd
[   38.006766] Please remove unsupported %] in format string
[..]
[   38.006783] Call Trace:
[   38.006783]  dump_stack+0x68/0x92
[   38.006784]  __warn+0xc2/0xdd
[   38.006784]  warn_slowpath_fmt+0x4b/0x53
[   38.006785]  ? __lock_acquire+0x2ac/0x1501
[   38.006785]  format_decode+0x226/0x2fd
[   38.006786]  vsnprintf+0x89/0x3b7
[   38.006786]  pointer+0x1c3/0x378
[   38.006787]  vsnprintf+0x22d/0x3b7
[   38.006787]  pointer+0x1c3/0x378
[   38.006788]  vsnprintf+0x22d/0x3b7
[   38.006788]  vscnprintf+0xd/0x26
[   38.006788]  vprintk_emit+0x81/0x294
[   38.006789]  ? 0xffffffffa0096000
[   38.006789]  vprintk_default+0x1d/0x1f
[   38.006790]  vprintk_func+0x6c/0x73
[   38.006790]  ? 0xffffffffa0096000
[   38.006791]  printk+0x43/0x4b
[   38.006791]  pr_cont+0x56/0x5e


I wonder if it can get any worse than that. I sort of suspect
it can. in trivial case, dump_stack() can add at least one more
level of recursion by using pr_{err, etc.} instead of corresponding
printk(KERN_{ERR, etc}.

can it be even worse? um... NMI?
any thoughts?

dunno, at the moment I'm not really comfortable with %pV recursion
for every pr_foo() call.

	-ss

Re: [RFC PATCH] printk: Make functions of pr_<level> macros

[Joe Perches]

On Thu, 2017-03-02 at 14:35 +0900, Sergey Senozhatsky wrote:
> Hello Joe,
> 
> On (02/28/17 19:17), Joe Perches wrote:
> > Can save the space that the KERN_<LEVEL> headers require.
> > 
> > The biggest negative here is the %pV use which needs
> > recursion and adds stack depth.
> > 
> > $ size vmlinux.o* (defconfig, x86-64)
> >    text     data     bss      dec     hex  filename
> > 12586135  1909841  777528 15273504  e90e20 vmlinux.o.new
> > 12590348  1909841  777528 15277717  e91e95 vmlinux.o.old
> 
> interesting. 4K.

Yeah, more when more calls are converted,

Maybe more like 12k, still the goal is to 
create singletons for the pr_fmt prefixes
and whatever __func__ uses that are most
common via a SOH + flag and using
__builtin_return_address where possible and
appropriate.  That could shrink another 10k
or so.

> [..]
> > +#define define_pr_func(func, level)			\
> > +asmlinkage __visible int func(const char *fmt, ...)	\
> > +{							\ 
> > +	va_list args;					\
> > +	int r;						\
> > +	struct va_format vaf;				\
> > +							\
> > +	va_start(args, fmt);				\
> > +	vaf.fmt = fmt;					\
> > +	vaf.va = &args;					\
> > +							\
> > +	r = printk(level "%pV", &vaf);			\
> > +							\
> > +	va_end(args);					\
> > +							\
> > +	return r;					\
> > +}							\
> 
> hm. that's really hacky (which is a compliment) and a bit complicated.
> my quick thought was to tweak vprintk_emit() for 'facility != 0' so it
> could get loglevel (and adjust lflags) from the passed level, not from
> the text, and then do something like this


> #define define_pr_func(func, level) asmlinkage __visible int func(const char *fmt, ...)
> {
> 	va_start(args, fmt);
> 	r = vprintk_emit(level[0], level[1], NULL, 0, fmt, args);
> 	va_end();
> }
> 
> but this won't do the trick. because func()->vprintk_emit() shortcut
> disables the printk-safe mechanism:
> 	func()->printk()->vprintk_func()->this_cpu(printk_context)::print()

That was what I had done originally a while ago
https://lkml.org/lkml/2016/6/23/652

Now the with "safe" version, it's a bit more complicated.

[stack depth can be high, ~400 bytes per recursion]

> dunno, at the moment I'm not really comfortable with %pV recursion
> for every pr_foo() call

Me neither really.  I'd much prefer a direct vprintk_emit.

Re: [RFC PATCH] printk: Make functions of pr_<level> macros

[Petr Mladek]

On Wed 2017-03-01 21:58:54, Joe Perches wrote:
> On Thu, 2017-03-02 at 14:35 +0900, Sergey Senozhatsky wrote:
> > Hello Joe,
> > 
> > On (02/28/17 19:17), Joe Perches wrote:
> > > Can save the space that the KERN_<LEVEL> headers require.
> > > 
> > > The biggest negative here is the %pV use which needs
> > > recursion and adds stack depth.
> > > 
> > > $ size vmlinux.o* (defconfig, x86-64)
> > >    text     data     bss      dec     hex  filename
> > > 12586135  1909841  777528 15273504  e90e20 vmlinux.o.new
> > > 12590348  1909841  777528 15277717  e91e95 vmlinux.o.old
> > 
> > interesting. 4K.
> 
> Yeah, more when more calls are converted,
> 
> Maybe more like 12k, still the goal is to 
> create singletons for the pr_fmt prefixes
> and whatever __func__ uses that are most
> common via a SOH + flag and using
> __builtin_return_address where possible and
> appropriate.  That could shrink another 10k
> or so.
> 
> > [..]
> > > +#define define_pr_func(func, level)			\
> > > +asmlinkage __visible int func(const char *fmt, ...)	\
> > > +{							\ 
> > > +	va_list args;					\
> > > +	int r;						\
> > > +	struct va_format vaf;				\
> > > +							\
> > > +	va_start(args, fmt);				\
> > > +	vaf.fmt = fmt;					\
> > > +	vaf.va = &args;					\
> > > +							\
> > > +	r = printk(level "%pV", &vaf);			\
> > > +							\
> > > +	va_end(args);					\
> > > +							\
> > > +	return r;					\
> > > +}							\
> > 
> > hm. that's really hacky (which is a compliment) and a bit complicated.
> > my quick thought was to tweak vprintk_emit() for 'facility != 0' so it
> > could get loglevel (and adjust lflags) from the passed level, not from
> > the text, and then do something like this
> 
> 
> > #define define_pr_func(func, level) asmlinkage __visible int func(const char *fmt, ...)
> > {
> > 	va_start(args, fmt);
> > 	r = vprintk_emit(level[0], level[1], NULL, 0, fmt, args);
> > 	va_end();
> > }
> > 
> > but this won't do the trick. because func()->vprintk_emit() shortcut
> > disables the printk-safe mechanism:
> > 	func()->printk()->vprintk_func()->this_cpu(printk_context)::print()
> 
> That was what I had done originally a while ago
> https://lkml.org/lkml/2016/6/23/652

BTW: The above mentioned commit adds one argument to
vprintk_default(). But the symbol is exported. I am
not sure if we could break the API.

We might need to create alternative vprintk_* functions
(called vlprintk_* or so) that would have the extra parameter.
And call them from the existing vprintk_* ones. Sigh.

Also note that we might need to pass more information
via the extra parameter, for example, KERN_ERR + KERN_CONT.

> Now the with "safe" version, it's a bit more complicated.

:-(

> [stack depth can be high, ~400 bytes per recursion]
> 
> > dunno, at the moment I'm not really comfortable with %pV recursion
> > for every pr_foo() call

Same here. We should avoid the recursion.

Best Regards,
Petr

Re: [RFC PATCH] printk: Make functions of pr_<level> macros

[Joe Perches]

On Thu, 2017-04-27 at 17:11 +0200, Petr Mladek wrote:
> On Wed 2017-03-01 21:58:54, Joe Perches wrote:
> > On Thu, 2017-03-02 at 14:35 +0900, Sergey Senozhatsky wrote:
> > > On (02/28/17 19:17), Joe Perches wrote:
> > > > Can save the space that the KERN_<LEVEL> headers require.
> > > > 
> > > > The biggest negative here is the %pV use which needs
> > > > recursion and adds stack depth.
[]
> > Maybe more like 12k, still the goal is to 
> > create singletons for the pr_fmt prefixes
> > and whatever __func__ uses that are most
> > common via a SOH + flag and using
> > __builtin_return_address where possible and
> > appropriate.  That could shrink another 10k
> > or so.
[]
> > #define define_pr_func(func, level) asmlinkage __visible int func(const char *fmt, ...)
> > > {
> > > 	va_start(args, fmt);
> > > 	r = vprintk_emit(level[0], level[1], NULL, 0, fmt, args);
> > > 	va_end();
> > > }
> > > 
> > > but this won't do the trick. because func()->vprintk_emit() shortcut
> > > disables the printk-safe mechanism:
> > > 	func()->printk()->vprintk_func()->this_cpu(printk_context)::print()
> > 
> > That was what I had done originally a while ago
> > https://lkml.org/lkml/2016/6/23/652
> 
> BTW: The above mentioned commit adds one argument to
> vprintk_default(). But the symbol is exported. I am
> not sure if we could break the API.

I believe EXPORT_SYMBOL functions have been modified
in the past, but don't have an example at hand.

> We might need to create alternative vprintk_* functions
> (called vlprintk_* or so) that would have the extra parameter.
> And call them from the existing vprintk_* ones. Sigh.

That might work.

> Also note that we might need to pass more information
> via the extra parameter, for example, KERN_ERR + KERN_CONT.
> 
> > Now the with "safe" version, it's a bit more complicated.
> 
> :-(

Yeah, that too.

Re: [RFC PATCH] printk: Make functions of pr_<level> macros

[Steven Rostedt]

On Thu, 27 Apr 2017 17:11:21 +0200
Petr Mladek <pmladek@suse.com> wrote:

> BTW: The above mentioned commit adds one argument to
> vprintk_default(). But the symbol is exported. I am
> not sure if we could break the API.

There is no kernel ABI/API. Exported kernel functions can change at will
as long as a make allmodconfig still works. We don't care about out of
tree users.

-- Steve