[PATCH 0/3] make printk work again

[PATCH 0/3] make printk work again

[Peter Zijlstra]

This basically fixes printk by evading everything it does.

There's too many problems with printk, from sleeping locks to broken console
drivers. Stop using it.

The early_console drivers are the most robust and simple, use those.

[PATCH 1/3] printk: Fix kdb_trap_printk placement

[Peter Zijlstra]

[-- Attachment #1: peterz-printk-kdb.patch --]
[-- Type: text/plain, Size: 1276 bytes --]

Some people figured vprintk_emit() makes for a nice API and exported
it, bypassing the kdb trap.

This still leaves vprintk_nmi() outside of the kbd reach, should that
be fixed too?

Cc: Jason Wessel <jason.wessel@windriver.com>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
---
 kernel/printk/printk.c |   19 ++++++++-----------
 1 file changed, 8 insertions(+), 11 deletions(-)

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1750,6 +1750,13 @@ asmlinkage int vprintk_emit(int facility
 	/* cpu currently holding logbuf_lock in this function */
 	static unsigned int logbuf_cpu = UINT_MAX;
 
+#ifdef CONFIG_KGDB_KDB
+	if (unlikely(kdb_trap_printk)) {
+		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
+		return r;
+	}
+#endif
+
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
 		in_sched = true;
@@ -1932,17 +1939,7 @@ EXPORT_SYMBOL(printk_emit);
 
 int vprintk_default(const char *fmt, va_list args)
 {
-	int r;
-
-#ifdef CONFIG_KGDB_KDB
-	if (unlikely(kdb_trap_printk)) {
-		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
-		return r;
-	}
-#endif
-	r = vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
-
-	return r;
+	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
 }
 EXPORT_SYMBOL_GPL(vprintk_default);
 

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Petr Mladek]

On Tue 2016-10-18 19:08:31, Peter Zijlstra wrote:
> Some people figured vprintk_emit() makes for a nice API and exported
> it, bypassing the kdb trap.
> 
> This still leaves vprintk_nmi() outside of the kbd reach, should that
> be fixed too?

Good question! vkdb_printf() tries to avoid a deadlock but the code is racy:

int vkdb_printf(enum kdb_msgsrc src, const char *fmt, va_list ap)
{
[...]
	/* Serialize kdb_printf if multiple cpus try to write at once.
	 * But if any cpu goes recursive in kdb, just print the output,
	 * even if it is interleaved with any other text.
	 */
	if (!KDB_STATE(PRINTF_LOCK)) {
		KDB_STATE_SET(PRINTF_LOCK);
		spin_lock_irqsave(&kdb_printf_lock, flags);
		got_printf_lock = 1;
		atomic_inc(&kdb_event);
	} else {
		__acquire(kdb_printf_lock);
	}


Let's have the following situation:

CPU1					CPU2

if (!KDB_STATE(PRINTF_LOCK)) {
	KDB_STATE_SET(PRINTF_LOCK);

					if (!KDB_STATE(PRINTF_LOCK)) {
					} else {
						__acquire(kdb_printf_lock);
					}

Now, both CPUs are in the critical section and happily writing over each
other, e.g. in

	vsnprintf(next_avail, size_avail, fmt, ap);

I quess that we want to fix this race. But I am not sure if it will
be done an NMI-safe way. I am going to send a patch for this.

Well, vkdb_printf() is called later when the messages are pushed
to the main logbuffer by printk_nmi_flush_line(). It is not perfect
but...


> Cc: Jason Wessel <jason.wessel@windriver.com>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>

Otherwise, your patch makes sense:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Peter Zijlstra]

On Wed, Oct 19, 2016 at 04:41:40PM +0200, Petr Mladek wrote:
> On Tue 2016-10-18 19:08:31, Peter Zijlstra wrote:
> > Some people figured vprintk_emit() makes for a nice API and exported
> > it, bypassing the kdb trap.
> > 
> > This still leaves vprintk_nmi() outside of the kbd reach, should that
> > be fixed too?
> 
> Good question! vkdb_printf() tries to avoid a deadlock but the code is racy:
> 
> int vkdb_printf(enum kdb_msgsrc src, const char *fmt, va_list ap)
> {
> [...]
> 	/* Serialize kdb_printf if multiple cpus try to write at once.
> 	 * But if any cpu goes recursive in kdb, just print the output,
> 	 * even if it is interleaved with any other text.
> 	 */
> 	if (!KDB_STATE(PRINTF_LOCK)) {
> 		KDB_STATE_SET(PRINTF_LOCK);
> 		spin_lock_irqsave(&kdb_printf_lock, flags);
> 		got_printf_lock = 1;
> 		atomic_inc(&kdb_event);
> 	} else {
> 		__acquire(kdb_printf_lock);
> 	}
> 
> 
> Let's have the following situation:
> 
> CPU1					CPU2
> 
> if (!KDB_STATE(PRINTF_LOCK)) {
> 	KDB_STATE_SET(PRINTF_LOCK);
> 
> 					if (!KDB_STATE(PRINTF_LOCK)) {
> 					} else {
> 						__acquire(kdb_printf_lock);
> 					}
> 
> Now, both CPUs are in the critical section and happily writing over each
> other, e.g. in
> 
> 	vsnprintf(next_avail, size_avail, fmt, ap);
> 
> I quess that we want to fix this race. But I am not sure if it will
> be done an NMI-safe way. I am going to send a patch for this.

Something like patch 3 in this series should do I suppose. But the
vkdb_printf() thing using spin_lock_irqsave() seems to suggest it was
never meant to be used from NMI context.

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Sergey Senozhatsky]

On (10/18/16 19:08), Peter Zijlstra wrote:
> 
> Some people figured vprintk_emit() makes for a nice API and exported
> it, bypassing the kdb trap.
> 
> This still leaves vprintk_nmi() outside of the kbd reach, should that
> be fixed too?
> 
> Cc: Jason Wessel <jason.wessel@windriver.com>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>

looks good to me.

Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

	-ss

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Petr Mladek]

On Tue 2016-10-18 19:08:31, Peter Zijlstra wrote:
> Some people figured vprintk_emit() makes for a nice API and exported
> it, bypassing the kdb trap.

I think that nobody saw this problem because kdb_trap_printk was
used only for a limited number of printk's. It is just a trick
how to use generic functions to print messages in the kdb context,
e.g. for getting backtraces.

But the patch makes sense.


> This still leaves vprintk_nmi() outside of the kbd reach, should that
> be fixed too?

It is perfectly fine. Messages from NMI context are not meant for
kdb anyway.

> Cc: Jason Wessel <jason.wessel@windriver.com>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> ---
>  kernel/printk/printk.c |   19 ++++++++-----------
>  1 file changed, 8 insertions(+), 11 deletions(-)
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1750,6 +1750,13 @@ asmlinkage int vprintk_emit(int facility
>  	/* cpu currently holding logbuf_lock in this function */
>  	static unsigned int logbuf_cpu = UINT_MAX;
>  
> +#ifdef CONFIG_KGDB_KDB
> +	if (unlikely(kdb_trap_printk)) {
> +		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
> +		return r;

r is not defined. It is fixed in the next patch but it breaks
bisectability.

Please, find below an updated patch that also includes
my Reviewed-by.


>From 5adf18de45ba986ea3ae611446828238f4d65fe0 Mon Sep 17 00:00:00 2001
From: Peter Zijlstra <peterz@infradead.org>
Date: Tue, 18 Oct 2016 19:08:31 +0200
Subject: [PATCH 1/3] printk: Fix kdb_trap_printk placement

Some people figured vprintk_emit() makes for a nice API and exported
it, bypassing the kdb trap.

This still leaves vprintk_nmi() outside of the kbd reach, should that
be fixed too?

Cc: Jason Wessel <jason.wessel@windriver.com>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 17 ++++++-----------
 1 file changed, 6 insertions(+), 11 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f7a55e9ff2f7..541ce7705353 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1781,6 +1781,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 	/* cpu currently holding logbuf_lock in this function */
 	static unsigned int logbuf_cpu = UINT_MAX;
 
+#ifdef CONFIG_KGDB_KDB
+	if (unlikely(kdb_trap_printk))
+		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
+#endif
+
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
 		in_sched = true;
@@ -1923,17 +1928,7 @@ asmlinkage int printk_emit(int facility, int level,
 
 int vprintk_default(const char *fmt, va_list args)
 {
-	int r;
-
-#ifdef CONFIG_KGDB_KDB
-	if (unlikely(kdb_trap_printk)) {
-		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
-		return r;
-	}
-#endif
-	r = vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
-
-	return r;
+	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
 }
 EXPORT_SYMBOL_GPL(vprintk_default);
 
-- 
1.8.5.6

[PATCH 2/3] early_printk: Add force_early_printk kernel parameter

[Peter Zijlstra]

[-- Attachment #1: peterz-force_early_printk.patch --]
[-- Type: text/plain, Size: 2661 bytes --]

Add add the 'force_early_printk' kernel parameter to override printk()
and force it into early_printk(). This bypasses all the cruft and fail
from printk() and makes things work again.

Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
---
 kernel/printk/printk.c |   74 ++++++++++++++++++++++++++++++++-----------------
 1 file changed, 49 insertions(+), 25 deletions(-)

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -344,6 +344,42 @@ __packed __aligned(4)
 #endif
 ;
 
+#ifdef CONFIG_EARLY_PRINTK
+struct console *early_console;
+
+static bool __read_mostly force_early_printk;
+
+static int __init force_early_printk_setup(char *str)
+{
+	force_early_printk = true;
+	return 0;
+}
+early_param("force_early_printk", force_early_printk_setup);
+
+static int early_vprintk(const char *fmt, va_list args)
+{
+	char buf[512];
+	int n;
+
+	n = vscnprintf(buf, sizeof(buf), fmt, args);
+	early_console->write(early_console, buf, n);
+
+	return n;
+}
+
+asmlinkage __visible void early_printk(const char *fmt, ...)
+{
+	va_list ap;
+
+	if (!early_console)
+		return;
+
+	va_start(ap, fmt);
+	early_vprintk(fmt, ap);
+	va_end(ap);
+}
+#endif
+
 /*
  * The logbuf_lock protects kmsg buffer, indices, counters.  This can be taken
  * within the scheduler's rq lock. It must be released before calling
@@ -1751,10 +1787,13 @@ asmlinkage int vprintk_emit(int facility
 	static unsigned int logbuf_cpu = UINT_MAX;
 
 #ifdef CONFIG_KGDB_KDB
-	if (unlikely(kdb_trap_printk)) {
-		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
-		return r;
-	}
+	if (unlikely(kdb_trap_printk))
+		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
+#endif
+
+#ifdef CONFIG_EARLY_PRINTK
+	if (force_early_printk && early_console)
+		return early_vprintk(fmt, args);
 #endif
 
 	if (level == LOGLEVEL_SCHED) {
@@ -1970,7 +2009,12 @@ asmlinkage __visible int printk(const ch
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk_func(fmt, args);
+#ifdef CONFIG_EARLY_PRINTK
+	if (force_early_printk && early_console)
+		r = vprintk_default(fmt, args);
+	else
+#endif
+		r = vprintk_func(fmt, args);
 	va_end(args);
 
 	return r;
@@ -2020,26 +2064,6 @@ DEFINE_PER_CPU(printk_func_t, printk_fun
 
 #endif /* CONFIG_PRINTK */
 
-#ifdef CONFIG_EARLY_PRINTK
-struct console *early_console;
-
-asmlinkage __visible void early_printk(const char *fmt, ...)
-{
-	va_list ap;
-	char buf[512];
-	int n;
-
-	if (!early_console)
-		return;
-
-	va_start(ap, fmt);
-	n = vscnprintf(buf, sizeof(buf), fmt, ap);
-	va_end(ap);
-
-	early_console->write(early_console, buf, n);
-}
-#endif
-
 static int __add_preferred_console(char *name, int idx, char *options,
 				   char *brl_options)
 {

Re: [PATCH 2/3] early_printk: Add force_early_printk kernel parameter

[Petr Mladek]

On Tue 2016-10-18 19:08:32, Peter Zijlstra wrote:
> Add add the 'force_early_printk' kernel parameter to override printk()
> and force it into early_printk(). This bypasses all the cruft and fail
> from printk() and makes things work again.

IMHO, the patch makes perfect sense and helps with debugging
hard problems.

> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1751,10 +1787,13 @@ asmlinkage int vprintk_emit(int facility
>  	static unsigned int logbuf_cpu = UINT_MAX;
>  
>  #ifdef CONFIG_KGDB_KDB
> -	if (unlikely(kdb_trap_printk)) {
> -		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
> -		return r;
> -	}
> +	if (unlikely(kdb_trap_printk))
> +		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
> +#endif

Please, find below an updated patch that has also my Reviewed-by.

In particular, the above change was moved to the first patch
to fix bisectability. The result after applying both patches
is still exactly the same.


>From e1c00ae67d07767ec8e5bddb1113c2badf31f4bd Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Tue, 29 Nov 2016 13:32:56 +0100
Subject: [PATCH 2/3] early_printk: Add force_early_printk kernel parameter

Add add the 'force_early_printk' kernel parameter to override printk()
and force it into early_printk(). This bypasses all the cruft and fail
from printk() and makes things work again.

Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 68 ++++++++++++++++++++++++++++++++++----------------
 1 file changed, 47 insertions(+), 21 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 541ce7705353..bb612e5c2e00 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -344,6 +344,42 @@ __packed __aligned(4)
 #endif
 ;
 
+#ifdef CONFIG_EARLY_PRINTK
+struct console *early_console;
+
+static bool __read_mostly force_early_printk;
+
+static int __init force_early_printk_setup(char *str)
+{
+	force_early_printk = true;
+	return 0;
+}
+early_param("force_early_printk", force_early_printk_setup);
+
+static int early_vprintk(const char *fmt, va_list args)
+{
+	char buf[512];
+	int n;
+
+	n = vscnprintf(buf, sizeof(buf), fmt, args);
+	early_console->write(early_console, buf, n);
+
+	return n;
+}
+
+asmlinkage __visible void early_printk(const char *fmt, ...)
+{
+	va_list ap;
+
+	if (!early_console)
+		return;
+
+	va_start(ap, fmt);
+	early_vprintk(fmt, ap);
+	va_end(ap);
+}
+#endif
+
 /*
  * The logbuf_lock protects kmsg buffer, indices, counters.  This can be taken
  * within the scheduler's rq lock. It must be released before calling
@@ -1786,6 +1822,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
 #endif
 
+#ifdef CONFIG_EARLY_PRINTK
+	if (force_early_printk && early_console)
+		return early_vprintk(fmt, args);
+#endif
+
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
 		in_sched = true;
@@ -1959,7 +2000,12 @@ asmlinkage __visible int printk(const char *fmt, ...)
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk_func(fmt, args);
+#ifdef CONFIG_EARLY_PRINTK
+	if (force_early_printk && early_console)
+		r = vprintk_default(fmt, args);
+	else
+#endif
+		r = vprintk_func(fmt, args);
 	va_end(args);
 
 	return r;
@@ -2009,26 +2055,6 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
 
 #endif /* CONFIG_PRINTK */
 
-#ifdef CONFIG_EARLY_PRINTK
-struct console *early_console;
-
-asmlinkage __visible void early_printk(const char *fmt, ...)
-{
-	va_list ap;
-	char buf[512];
-	int n;
-
-	if (!early_console)
-		return;
-
-	va_start(ap, fmt);
-	n = vscnprintf(buf, sizeof(buf), fmt, ap);
-	va_end(ap);
-
-	early_console->write(early_console, buf, n);
-}
-#endif
-
 static int __add_preferred_console(char *name, int idx, char *options,
 				   char *brl_options)
 {
-- 
1.8.5.6

[PATCH 3/3] early_printk: Add simple serialization to early_vprintk()

[Peter Zijlstra]

[-- Attachment #1: peterz-early_printk-serialize.patch --]
[-- Type: text/plain, Size: 978 bytes --]

In order to avoid multiple CPUs banging on the serial port at the same
time, add simple serialization. This explicitly deals with nested
contexts (like IRQs etc.).

Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
---
 kernel/printk/printk.c |   16 +++++++++++++++-
 1 file changed, 15 insertions(+), 1 deletion(-)

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -356,14 +356,28 @@ static int __init force_early_printk_set
 }
 early_param("force_early_printk", force_early_printk_setup);
 
+static int early_printk_cpu = -1;
+
 static int early_vprintk(const char *fmt, va_list args)
 {
+	int n, cpu, old;
 	char buf[512];
-	int n;
+
+	cpu = get_cpu();
+	for (;;) {
+		old = cmpxchg(&early_printk_cpu, -1, cpu);
+		if (old == -1 || old == cpu)
+			break;
+
+		cpu_relax();
+	}
 
 	n = vscnprintf(buf, sizeof(buf), fmt, args);
 	early_console->write(early_console, buf, n);
 
+	smp_store_release(&early_printk_cpu, old);
+	put_cpu();
+
 	return n;
 }
 

Re: [PATCH 3/3] early_printk: Add simple serialization to early_vprintk()

[Steven Rostedt]

On Tue, 18 Oct 2016 19:08:33 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> In order to avoid multiple CPUs banging on the serial port at the same
> time, add simple serialization. This explicitly deals with nested
> contexts (like IRQs etc.).
> 
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> ---

hehe, I have the exact same patch for my -rt work.

-- Steve

>  kernel/printk/printk.c |   16 +++++++++++++++-
>  1 file changed, 15 insertions(+), 1 deletion(-)
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -356,14 +356,28 @@ static int __init force_early_printk_set
>  }
>  early_param("force_early_printk", force_early_printk_setup);
>  
> +static int early_printk_cpu = -1;
> +
>  static int early_vprintk(const char *fmt, va_list args)
>  {
> +	int n, cpu, old;
>  	char buf[512];
> -	int n;
> +
> +	cpu = get_cpu();
> +	for (;;) {
> +		old = cmpxchg(&early_printk_cpu, -1, cpu);
> +		if (old == -1 || old == cpu)
> +			break;
> +
> +		cpu_relax();
> +	}
>  
>  	n = vscnprintf(buf, sizeof(buf), fmt, args);
>  	early_console->write(early_console, buf, n);
>  
> +	smp_store_release(&early_printk_cpu, old);
> +	put_cpu();
> +
>  	return n;
>  }
>  
> 

Re: [PATCH 3/3] early_printk: Add simple serialization to early_vprintk()

[Peter Zijlstra]

On Tue, Oct 18, 2016 at 01:19:51PM -0400, Steven Rostedt wrote:
> 
> hehe, I have the exact same patch for my -rt work.

> > +static int early_printk_cpu = -1;
> > +
> >  static int early_vprintk(const char *fmt, va_list args)
> >  {
> > +	int n, cpu, old;
> >  	char buf[512];
> > +
> > +	cpu = get_cpu();
> > +	for (;;) {
> > +		old = cmpxchg(&early_printk_cpu, -1, cpu);
> > +		if (old == -1 || old == cpu)
> > +			break;

Looking at this again, we really should not spin using cmpxchg(), that
thrashes the cacheline.

The below is slightly better spinning... then again, this isn't
performance code.

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -376,10 +376,16 @@ static int early_vprintk(const char *fmt
 
 	cpu = get_cpu();
 	for (;;) {
-		old = cmpxchg(&early_printk_cpu, -1, cpu);
-		if (old == -1 || old == cpu)
+		old = READ_ONCE(early_printk_cpu);
+		if (old == cpu)
 			break;
 
+		if (old == -1) {
+			old = cmpxchg(&early_printk_cpu, -1, cpu);
+			if (old == -1 || old == cpu)
+				break;
+		}
+
 		cpu_relax();
 	}
 

Re: [PATCH 3/3] early_printk: Add simple serialization to early_vprintk()

[Steven Rostedt]

On Tue, 18 Oct 2016 19:30:46 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Tue, Oct 18, 2016 at 01:19:51PM -0400, Steven Rostedt wrote:

> Looking at this again, we really should not spin using cmpxchg(), that
> thrashes the cacheline.
> 
> The below is slightly better spinning... then again, this isn't
> performance code.

Yeah, this is similar to the hack I had.

May want to fold this in your previous version.

-- Steve

> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -376,10 +376,16 @@ static int early_vprintk(const char *fmt
>  
>  	cpu = get_cpu();
>  	for (;;) {
> -		old = cmpxchg(&early_printk_cpu, -1, cpu);
> -		if (old == -1 || old == cpu)
> +		old = READ_ONCE(early_printk_cpu);
> +		if (old == cpu)
>  			break;
>  
> +		if (old == -1) {
> +			old = cmpxchg(&early_printk_cpu, -1, cpu);
> +			if (old == -1 || old == cpu)
> +				break;
> +		}
> +
>  		cpu_relax();
>  	}
>  

Re: [PATCH 3/3] early_printk: Add simple serialization to early_vprintk()

[Petr Mladek]

On Tue 2016-10-18 19:08:33, Peter Zijlstra wrote:
> In order to avoid multiple CPUs banging on the serial port at the same
> time, add simple serialization. This explicitly deals with nested
> contexts (like IRQs etc.).
> 
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>

Makes sense. Just a small comment below.

Reviewd-by: Petr Mladek <pmladek@suse.com>

> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -356,14 +356,28 @@ static int __init force_early_printk_set
>  }
>  early_param("force_early_printk", force_early_printk_setup);
>  
> +static int early_printk_cpu = -1;

[...]

> +	for (;;) {
> +		old = cmpxchg(&early_printk_cpu, -1, cpu);
> +		if (old == -1 || old == cpu)
> +			break;
> +
> +		cpu_relax();
> +	}
>  
>  	n = vscnprintf(buf, sizeof(buf), fmt, args);
>  	early_console->write(early_console, buf, n);
>  
> +	smp_store_release(&early_printk_cpu, old);

checkpatch.pl complains about using a barrier without a comment.
The code is simple but it still might help to add something like:

	/* Releasing early_printk_cpu custom lock. */

Best Regards,
Petr

Re: [PATCH 0/3] make printk work again

[Jan Kara]

On Tue 18-10-16 19:08:30, Peter Zijlstra wrote:
> This basically fixes printk by evading everything it does.
> 
> There's too many problems with printk, from sleeping locks to broken console
> drivers. Stop using it.

I agree that printk is fragile and your patches are likely fine for machine
where you do kernel development. However for production servers with
hundreds of SCSI LUNs assigned I don't think it is a viable solution - I'm
pretty sure those machines would take ages to boot (if they ever boot) with
early_printk implementation. So do you intend this as "the ultimate printk
solution" or just a "kernel developers debugging aid"? :)

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [PATCH 0/3] make printk work again

[Peter Zijlstra]

On Wed, Oct 19, 2016 at 09:04:16AM +0200, Jan Kara wrote:
> On Tue 18-10-16 19:08:30, Peter Zijlstra wrote:
> > This basically fixes printk by evading everything it does.
> > 
> > There's too many problems with printk, from sleeping locks to broken console
> > drivers. Stop using it.
> 
> I agree that printk is fragile and your patches are likely fine for machine
> where you do kernel development. However for production servers with
> hundreds of SCSI LUNs assigned I don't think it is a viable solution - I'm
> pretty sure those machines would take ages to boot (if they ever boot) with
> early_printk implementation. So do you intend this as "the ultimate printk
> solution" or just a "kernel developers debugging aid"? :)

Mostly just to scratch my itch. It also completely kills dmesg, which I
can't see being popular :-) On the plus side, these 3 little patches
seems like something mergable (as opposed to my previous approach which
basically just deleted everything printk). The first also fixes a real,
and long standing, issue with kdb_printk.

But I really do not see how printk and the console drivers as exist
today can ever yield something reliable. We've been stacking band-aids
on it for a while now, and I think we're at the point where we should
say stop this madness.

Either do a complete overhaul and redesign of the entire stack, or just
give up and admit its broken crap and leave it rot.

Re: [PATCH 0/3] make printk work again

[Sergey Senozhatsky]

On (10/18/16 19:08), Peter Zijlstra wrote:
> This basically fixes printk by evading everything it does.
> 
> There's too many problems with printk, from sleeping locks to broken console
> drivers. Stop using it.
> 
> The early_console drivers are the most robust and simple, use those.

ACK

Can we also please ban that pre Because it's a bit tricky.emption thing?

	-ss

Re: [PATCH 0/3] make printk work again

[Peter Zijlstra]

On Wed, Oct 19, 2016 at 08:48:28PM +0900, Sergey Senozhatsky wrote:
> On (10/18/16 19:08), Peter Zijlstra wrote:
> > This basically fixes printk by evading everything it does.
> > 
> > There's too many problems with printk, from sleeping locks to broken console
> > drivers. Stop using it.
> > 
> > The early_console drivers are the most robust and simple, use those.
> 
> ACK
> 
> Can we also please ban that pre Because it's a bit tricky.emption thing?

Ha, so that's actually quite complicated. The 3rd patch does what is
simple and robust. Doing more gets very tricky real quick.

So actual preemption is disabled per get_cpu()/put_cpu(), and cross-cpu
interleaving is disabled by that 'lock'. But interrupt (and NMI) nesting
are still possible.

It does sporadically happen, but I've not really found it to be a
problem when reading the output.

[PATCH 0/3] printk: Add force_early_printk boot param

[Peter Zijlstra]

Most all printk() bits are terminally broken because they rely on the scheduler
and blocking locks to function, making them unsuitable for debugging the
scheduler and NMI context things.

Luckily many early_printk implementations are relatively sane and don't rely on
anything much at all; the x86 early_serial_console for example is pure
bit-banging without anything.

So provide means to always use these and avoid the whole printk mess.

[PATCH 1/3] printk: Fix kdb_trap_printk placement

[Peter Zijlstra]

[-- Attachment #1: peterz-printk-kdb.patch --]
[-- Type: text/plain, Size: 1304 bytes --]

Some people figured vprintk_emit() makes for a nice API and exported
it, bypassing the kdb trap.

This still leaves vprintk_nmi() outside of the kbd reach, should that
be fixed too?

Cc: Jason Wessel <jason.wessel@windriver.com>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
---
 kernel/printk/printk.c |   18 ++++++------------
 1 file changed, 6 insertions(+), 12 deletions(-)

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1811,6 +1811,11 @@ asmlinkage int vprintk_emit(int facility
 	int printed_len;
 	bool in_sched = false;
 
+#ifdef CONFIG_KGDB_KDB
+	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0))
+		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
+#endif
+
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
 		in_sched = true;
@@ -1903,18 +1908,7 @@ EXPORT_SYMBOL(printk_emit);
 
 int vprintk_default(const char *fmt, va_list args)
 {
-	int r;
-
-#ifdef CONFIG_KGDB_KDB
-	/* Allow to pass printk() to kdb but avoid a recursion. */
-	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0)) {
-		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
-		return r;
-	}
-#endif
-	r = vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
-
-	return r;
+	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
 }
 EXPORT_SYMBOL_GPL(vprintk_default);
 

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Steven Rostedt]

On Thu, 28 Sep 2017 14:18:24 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> Some people figured vprintk_emit() makes for a nice API and exported
> it, bypassing the kdb trap.
> 
> This still leaves vprintk_nmi() outside of the kbd reach, should that
> be fixed too?

I believe the vprintk_nmi() just buffers the prints, and doesn't send
it out. I'm guessing not then.

> 
> Cc: Jason Wessel <jason.wessel@windriver.com>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> ---
>  kernel/printk/printk.c |   18 ++++++------------
>  1 file changed, 6 insertions(+), 12 deletions(-)
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1811,6 +1811,11 @@ asmlinkage int vprintk_emit(int facility
>  	int printed_len;
>  	bool in_sched = false;
>  
> +#ifdef CONFIG_KGDB_KDB
> +	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0))
> +		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
> +#endif
> +
>  	if (level == LOGLEVEL_SCHED) {
>  		level = LOGLEVEL_DEFAULT;
>  		in_sched = true;
> @@ -1903,18 +1908,7 @@ EXPORT_SYMBOL(printk_emit);
>  
>  int vprintk_default(const char *fmt, va_list args)
>  {
> -	int r;
> -
> -#ifdef CONFIG_KGDB_KDB
> -	/* Allow to pass printk() to kdb but avoid a recursion. */
> -	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0)) {
> -		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
> -		return r;
> -	}
> -#endif
> -	r = vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
> -
> -	return r;

Hmm, what was with the return r before??

Anyway,

Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> +	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
>  }
>  EXPORT_SYMBOL_GPL(vprintk_default);
>  
> 

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Petr Mladek]

On Thu 2017-09-28 14:18:24, Peter Zijlstra wrote:
> Some people figured vprintk_emit() makes for a nice API and exported
> it, bypassing the kdb trap.
> 
> This still leaves vprintk_nmi() outside of the kbd reach, should that
> be fixed too?
> 
> Cc: Jason Wessel <jason.wessel@windriver.com>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> ---
>  kernel/printk/printk.c |   18 ++++++------------
>  1 file changed, 6 insertions(+), 12 deletions(-)
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1811,6 +1811,11 @@ asmlinkage int vprintk_emit(int facility
>  	int printed_len;
>  	bool in_sched = false;
>  
> +#ifdef CONFIG_KGDB_KDB
> +	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0))
> +		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
> +#endif

Hmm, this will get called also from scheduler and timer code
via printk_deferred(). I am afraid that it is not safe.

If I get it correctly, vkdb_printf() might call printk()
when kdb_printf_cpu are set to a real CPU number. Then
we will fall through and try to call consoles.


Fortunately, I think that we do not need this patch at all.
vkdb_printf() is called here only when kdb_trap_printk is set.
It is used the following way:

static void kdb_dumpregs(struct pt_regs *regs)
{
[...]
	kdb_trap_printk++;
	show_regs(regs);
	kdb_trap_printk--;
[...]
}

or 

static int kdb_ftdump(int argc, const char **argv)
{
[...]
	kdb_trap_printk++;
	ftrace_dump_buf(skip_lines, cpu_file);
	kdb_trap_printk--;
[...]
}

It looks like a nasty hack to reuse an existing code
that calls printk(). The aim is to get the output
of these printk's on the kdb console instead of
the log buffer and other consoles.

Note that kdb_dumpregs(), kdb_ftdump() implement
kdb commands that might be called from the kdb console.

If these commands are always called from normal context
then we do not need to care of NMI and other special printk
variants.

Or can the kdb console commands be called in NMI context?

Best Regards,
Petr

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Peter Zijlstra]

On Thu, Oct 05, 2017 at 03:38:44PM +0200, Petr Mladek wrote:
> Or can the kdb console commands be called in NMI context?

IIRC most of KDB runs from NMI context.

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Petr Mladek]

On Thu 2017-10-05 15:42:27, Peter Zijlstra wrote:
> On Thu, Oct 05, 2017 at 03:38:44PM +0200, Petr Mladek wrote:
> > Or can the kdb console commands be called in NMI context?
> 
> IIRC most of KDB runs from NMI context.

To be honest, I am not familiar with kdb. I tried the following
from Documentation/dev-tools/kgdb.rst:

$> echo ttyS0 > /sys/module/kgdboc/parameters/kgdboc
$> echo g >/proc/sysrq-trigger

Result: I was able to do kdb commands on the serial console.
Note: It seems that this stuff was _not_ running in NMI.

Then I tried to set breakpoint for a function that is
called in NMI context:

$kdb> bt show_regs

Where show_regs() is called from nmi_cpu_backtrace(). I unblocked
the system and triggered ''l'' sysrq to show stacks from all CPUs:

$kdb> go
$> echo l >/proc/sysrq-trigger

Result: The system frozen and I had to reboot using a power switch.


I wonder if the break point in NMI is supposed to work and if the
kdb commands are handled in NMI context on the serial console then.

By other words, do you need this patch for a particular use-case?
Or did you added this patch just to fix a theoretical problem?

Best Regards,
Petr

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Petr Mladek]

Hi,

I thought about this a lot from several angles. And I would prefer
sligly different placement, see the patch below.

On Thu 2017-09-28 14:18:24, Peter Zijlstra wrote:
> Some people figured vprintk_emit() makes for a nice API and exported
> it, bypassing the kdb trap.

Sigh, printk() API is pretty complicated and this export
made it much worse. Well, there are two things:

First, kdb_trap_printk name is a bit misleading. It is not a
generic trap of any printk message. Instead it seems to be
used to redirect only particular messages from some existing
functions, e.g. show_regs() called from kdb_dumpregs().

Second, it seems that the only user of the exported vprintk_emit()
is dev_vprintk_emit(). I believe that code using this wrapper
is not called in the sections where kdb_trap_printk is incremented.

As a result, I think that we do not need to handle kdb_trap_printk
in vprintk_emit().


> This still leaves vprintk_nmi() outside of the kbd reach, should that
> be fixed too?

I think that it is safe after all, see the commit message in the patch
below.


>From 0da097266f617c2d62956f3abc8e5f39f119c674 Mon Sep 17 00:00:00 2001
From: Peter Zijlstra <peterz@infradead.org>
Date: Thu, 28 Sep 2017 14:18:24 +0200
Subject: [PATCH 1/3] printk: Fix kdb_trap_printk placement

The counter kdb_trap_printk marks parts of code where we want to redirect
printk() into vkdb_printf(). It is used to reuse existing non-trivial
functions, for example, show_regs() to print some information in
the kdb console.

This patch moves the check into printk_func() where the right
printk implementation is choosen also for other special contexts.

Also it would make sense to get rid of kdb_trap_printk counter
and use printk_context instead. The only problem is that
printk_context is per-CPU. It is most likely safe. It seems
that kdb_trap_printk is incremented only in code that is called
from the kdb console and constroling CPU. But I am not 100% sure.

This change allows to redirect the messages also from NMI or
printk_safe context. It looks safe from the printk() point
of view because kdb code prints many messages directly using
kdb_printf() directly. By other words, if kdb reaches the point
when kdb_trap_printk might be incremented, we should be on
the safe side.

Cc: Jason Wessel <jason.wessel@windriver.com>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
[pmladek@suse.com: Move the check to printk_func.]
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c      | 14 +-------------
 kernel/printk/printk_safe.c | 10 ++++++++++
 2 files changed, 11 insertions(+), 13 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 512f7c2baedd..e4151b14509d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -33,7 +33,6 @@
 #include <linux/memblock.h>
 #include <linux/syscalls.h>
 #include <linux/crash_core.h>
-#include <linux/kdb.h>
 #include <linux/ratelimit.h>
 #include <linux/kmsg_dump.h>
 #include <linux/syslog.h>
@@ -1784,18 +1783,7 @@ asmlinkage int printk_emit(int facility, int level,
 
 int vprintk_default(const char *fmt, va_list args)
 {
-	int r;
-
-#ifdef CONFIG_KGDB_KDB
-	/* Allow to pass printk() to kdb but avoid a recursion. */
-	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0)) {
-		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
-		return r;
-	}
-#endif
-	r = vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
-
-	return r;
+	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
 }
 EXPORT_SYMBOL_GPL(vprintk_default);
 
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index 3cdaeaef9ce1..45136f0c8189 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -21,6 +21,7 @@
 #include <linux/smp.h>
 #include <linux/cpumask.h>
 #include <linux/irq_work.h>
+#include <linux/kdb.h>
 #include <linux/printk.h>
 
 #include "internal.h"
@@ -363,6 +364,15 @@ void __printk_safe_exit(void)
 
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 {
+#ifdef CONFIG_KGDB_KDB
+	/*
+	 * Special context where printk() messages should appear on kdb
+	 * console. Allow logging by recursion detection.
+	 */
+	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0))
+		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
+#endif
+
 	/* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
 	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
 		return vprintk_nmi(fmt, args);
-- 
1.8.5.6

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Petr Mladek]

On Thu 2017-10-12 11:45:37, Petr Mladek wrote:
> Hi,
> 
> I thought about this a lot from several angles. And I would prefer
> sligly different placement, see the patch below.
> 
> On Thu 2017-09-28 14:18:24, Peter Zijlstra wrote:
> > Some people figured vprintk_emit() makes for a nice API and exported
> > it, bypassing the kdb trap.
> 
> Sigh, printk() API is pretty complicated and this export
> made it much worse. Well, there are two things:
> 
> First, kdb_trap_printk name is a bit misleading. It is not a
> generic trap of any printk message. Instead it seems to be
> used to redirect only particular messages from some existing
> functions, e.g. show_regs() called from kdb_dumpregs().
> 
> Second, it seems that the only user of the exported vprintk_emit()
> is dev_vprintk_emit(). I believe that code using this wrapper
> is not called in the sections where kdb_trap_printk is incremented.

Well, I wonder if we should go even further and stop exporting
vprintk_emit(). IMHO, the only reason was dev_print_emit() and
the ability to pass the extra "dict" parameter.

My aim is to redirect all the exported interfaces into vprintk_func
(need another name?) where the right implementation will be chosen
by the context (NMI, printk_safe, kdb, deferred?, printk_early, normal).

In each case, I would like to have all these re-directions on a single
place to make the printk() code better readable.

IMHO, it would make sense to do this clean up first before
this patchset adds more twists. But I am afraid that we will
meet some problems and it make take longer. I am open for
opinions.

Best Regards,
Petr

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Peter Zijlstra]

On Thu, Oct 12, 2017 at 12:03:04PM +0200, Petr Mladek wrote:
> On Thu 2017-10-12 11:45:37, Petr Mladek wrote:
> > Hi,
> > 
> > I thought about this a lot from several angles. And I would prefer
> > sligly different placement, see the patch below.
> > 
> > On Thu 2017-09-28 14:18:24, Peter Zijlstra wrote:
> > > Some people figured vprintk_emit() makes for a nice API and exported
> > > it, bypassing the kdb trap.
> > 
> > Sigh, printk() API is pretty complicated and this export
> > made it much worse. Well, there are two things:
> > 
> > First, kdb_trap_printk name is a bit misleading. It is not a
> > generic trap of any printk message. Instead it seems to be
> > used to redirect only particular messages from some existing
> > functions, e.g. show_regs() called from kdb_dumpregs().
> > 
> > Second, it seems that the only user of the exported vprintk_emit()
> > is dev_vprintk_emit(). I believe that code using this wrapper
> > is not called in the sections where kdb_trap_printk is incremented.
> 
> Well, I wonder if we should go even further and stop exporting
> vprintk_emit(). IMHO, the only reason was dev_print_emit() and
> the ability to pass the extra "dict" parameter.

You have my blessing there, but the device folks might have an opinion
on that; Cc'ed Gregkh.

> My aim is to redirect all the exported interfaces into vprintk_func
> (need another name?) where the right implementation will be chosen
> by the context (NMI, printk_safe, kdb, deferred?, printk_early, normal).
> 
> In each case, I would like to have all these re-directions on a single
> place to make the printk() code better readable.
> 
> IMHO, it would make sense to do this clean up first before
> this patchset adds more twists. But I am afraid that we will
> meet some problems and it make take longer. I am open for
> opinions.
> 
> Best Regards,
> Petr

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Greg Kroah-Hartman]

On Thu, Oct 12, 2017 at 01:34:39PM +0200, Peter Zijlstra wrote:
> On Thu, Oct 12, 2017 at 12:03:04PM +0200, Petr Mladek wrote:
> > On Thu 2017-10-12 11:45:37, Petr Mladek wrote:
> > > Hi,
> > > 
> > > I thought about this a lot from several angles. And I would prefer
> > > sligly different placement, see the patch below.
> > > 
> > > On Thu 2017-09-28 14:18:24, Peter Zijlstra wrote:
> > > > Some people figured vprintk_emit() makes for a nice API and exported
> > > > it, bypassing the kdb trap.
> > > 
> > > Sigh, printk() API is pretty complicated and this export
> > > made it much worse. Well, there are two things:
> > > 
> > > First, kdb_trap_printk name is a bit misleading. It is not a
> > > generic trap of any printk message. Instead it seems to be
> > > used to redirect only particular messages from some existing
> > > functions, e.g. show_regs() called from kdb_dumpregs().
> > > 
> > > Second, it seems that the only user of the exported vprintk_emit()
> > > is dev_vprintk_emit(). I believe that code using this wrapper
> > > is not called in the sections where kdb_trap_printk is incremented.
> > 
> > Well, I wonder if we should go even further and stop exporting
> > vprintk_emit(). IMHO, the only reason was dev_print_emit() and
> > the ability to pass the extra "dict" parameter.
> 
> You have my blessing there, but the device folks might have an opinion
> on that; Cc'ed Gregkh.

Hm, we "need" that dict option, otherwise the whole dev_printk() family
of messages will not work properly, right?

Or am I missing something?  If you can figure out a way to still support
the same thing (we need a prefix at the beginning of the message that
shows the device/driver/binding/etc that emitted the message), that's
fine with me, I'm not wed to vprintk_emit() :)

thanks,

greg k-h

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Greg Kroah-Hartman]

On Thu, Oct 12, 2017 at 01:52:29PM +0200, Greg Kroah-Hartman wrote:
> On Thu, Oct 12, 2017 at 01:34:39PM +0200, Peter Zijlstra wrote:
> > On Thu, Oct 12, 2017 at 12:03:04PM +0200, Petr Mladek wrote:
> > > On Thu 2017-10-12 11:45:37, Petr Mladek wrote:
> > > > Hi,
> > > > 
> > > > I thought about this a lot from several angles. And I would prefer
> > > > sligly different placement, see the patch below.
> > > > 
> > > > On Thu 2017-09-28 14:18:24, Peter Zijlstra wrote:
> > > > > Some people figured vprintk_emit() makes for a nice API and exported
> > > > > it, bypassing the kdb trap.
> > > > 
> > > > Sigh, printk() API is pretty complicated and this export
> > > > made it much worse. Well, there are two things:
> > > > 
> > > > First, kdb_trap_printk name is a bit misleading. It is not a
> > > > generic trap of any printk message. Instead it seems to be
> > > > used to redirect only particular messages from some existing
> > > > functions, e.g. show_regs() called from kdb_dumpregs().
> > > > 
> > > > Second, it seems that the only user of the exported vprintk_emit()
> > > > is dev_vprintk_emit(). I believe that code using this wrapper
> > > > is not called in the sections where kdb_trap_printk is incremented.
> > > 
> > > Well, I wonder if we should go even further and stop exporting
> > > vprintk_emit(). IMHO, the only reason was dev_print_emit() and
> > > the ability to pass the extra "dict" parameter.
> > 
> > You have my blessing there, but the device folks might have an opinion
> > on that; Cc'ed Gregkh.
> 
> Hm, we "need" that dict option, otherwise the whole dev_printk() family
> of messages will not work properly, right?
> 
> Or am I missing something?  If you can figure out a way to still support
> the same thing (we need a prefix at the beginning of the message that
> shows the device/driver/binding/etc that emitted the message), that's
> fine with me, I'm not wed to vprintk_emit() :)

Nope, this doesn't seem to deal with the prefix, except in some odd way
that is tied to the dynamic debugging logic.  I really don't know what
this does anymore.  Joe wrote it in 2012 as part of the dynamic debug
code.

Joe, any thoughts?

thanks,

greg k-h

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Joe Perches]

On Thu, 2017-10-12 at 14:08 +0200, Greg Kroah-Hartman wrote:
> On Thu, Oct 12, 2017 at 01:52:29PM +0200, Greg Kroah-Hartman wrote:
> > On Thu, Oct 12, 2017 at 01:34:39PM +0200, Peter Zijlstra wrote:
> > > On Thu, Oct 12, 2017 at 12:03:04PM +0200, Petr Mladek wrote:
> > > > On Thu 2017-10-12 11:45:37, Petr Mladek wrote:
> > > > > Hi,
> > > > > 
> > > > > I thought about this a lot from several angles. And I would prefer
> > > > > sligly different placement, see the patch below.
> > > > > 
> > > > > On Thu 2017-09-28 14:18:24, Peter Zijlstra wrote:
> > > > > > Some people figured vprintk_emit() makes for a nice API and exported
> > > > > > it, bypassing the kdb trap.
> > > > > 
> > > > > Sigh, printk() API is pretty complicated and this export
> > > > > made it much worse. Well, there are two things:
> > > > > 
> > > > > First, kdb_trap_printk name is a bit misleading. It is not a
> > > > > generic trap of any printk message. Instead it seems to be
> > > > > used to redirect only particular messages from some existing
> > > > > functions, e.g. show_regs() called from kdb_dumpregs().
> > > > > 
> > > > > Second, it seems that the only user of the exported vprintk_emit()
> > > > > is dev_vprintk_emit(). I believe that code using this wrapper
> > > > > is not called in the sections where kdb_trap_printk is incremented.
> > > > 
> > > > Well, I wonder if we should go even further and stop exporting
> > > > vprintk_emit(). IMHO, the only reason was dev_print_emit() and
> > > > the ability to pass the extra "dict" parameter.
> > > 
> > > You have my blessing there, but the device folks might have an opinion
> > > on that; Cc'ed Gregkh.
> > 
> > Hm, we "need" that dict option, otherwise the whole dev_printk() family
> > of messages will not work properly, right?
> > 
> > Or am I missing something?  If you can figure out a way to still support
> > the same thing (we need a prefix at the beginning of the message that
> > shows the device/driver/binding/etc that emitted the message), that's
> > fine with me, I'm not wed to vprintk_emit() :)
> 
> Nope, this doesn't seem to deal with the prefix, except in some odd way
> that is tied to the dynamic debugging logic.  I really don't know what
> this does anymore.  Joe wrote it in 2012 as part of the dynamic debug
> code.
> 
> Joe, any thoughts?

Man I hate rabbit-holes.  I need a few days as I'm
otherwise busy.

This stuff has been broken for half a decade now.
Perhaps it doesn't need fixing?

In any case, printk needs a thorough breaking up
and refactoring.

Pushing around at its edges just makes it worse.

vprintk_emit came from Kay Sievers.

commit 7ff9554bb578ba02166071d2d487b7fc7d860d62
Author: Kay Sievers <kay@vrfy.org>
Date:   Thu May 3 02:29:13 2012 +0200

    printk: convert byte-buffer to variable-length record buffer

It seems printk_emit is also exported and unused.

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Petr Mladek]

On Thu 2017-10-12 11:11:00, Joe Perches wrote:
> On Thu, 2017-10-12 at 14:08 +0200, Greg Kroah-Hartman wrote:
> > On Thu, Oct 12, 2017 at 01:52:29PM +0200, Greg Kroah-Hartman wrote:
> > > On Thu, Oct 12, 2017 at 01:34:39PM +0200, Peter Zijlstra wrote:
> > > > On Thu, Oct 12, 2017 at 12:03:04PM +0200, Petr Mladek wrote:
> > > > > On Thu 2017-10-12 11:45:37, Petr Mladek wrote:
> > > > > Well, I wonder if we should go even further and stop exporting
> > > > > vprintk_emit(). IMHO, the only reason was dev_print_emit() and
> > > > > the ability to pass the extra "dict" parameter.
> > > > 
> > > > You have my blessing there, but the device folks might have an opinion
> > > > on that; Cc'ed Gregkh.
> > > 
> > > Hm, we "need" that dict option, otherwise the whole dev_printk() family
> > > of messages will not work properly, right?
> > > 
> > > Or am I missing something?  If you can figure out a way to still support
> > > the same thing (we need a prefix at the beginning of the message that
> > > shows the device/driver/binding/etc that emitted the message), that's
> > > fine with me, I'm not wed to vprintk_emit() :)
> > 
> > Nope, this doesn't seem to deal with the prefix, except in some odd way
> > that is tied to the dynamic debugging logic.  I really don't know what
> > this does anymore.  Joe wrote it in 2012 as part of the dynamic debug
> > code.
> > 
> > Joe, any thoughts?
>
> Man I hate rabbit-holes.  I need a few days as I'm
> otherwise busy.

Joe, you were added in the middle of the thread and probably
do not have the right context. IMHO, Greg did not want any code.
He just wanted to know if the code is still needed at all.

dev_vprintk_emit() is the only external user of vprintk_emit().
Also it is the only user that sets the "dict" parameter.

If I get it correctly, it is not about message prefix but
about some extra info, see create_syslog_header().
It displayed only on /dev/kmsg and consoles with
CON_EXTENDED flag, see msg_print_ext_header().

One question is if people use it and if it is worth
the complexity.


> This stuff has been broken for half a decade now.
> Perhaps it doesn't need fixing?

This is more about cleaning the interfaces. vprintk_emit() is
a low level API and it would help a lot it is not called
directly outside printk code.

But I already have some idea how to solve this.

> In any case, printk needs a thorough breaking up
> and refactoring.
>
> Pushing around at its edges just makes it worse.

In this case, the edge blocks the refactoring.


> vprintk_emit came from Kay Sievers.
> 
> commit 7ff9554bb578ba02166071d2d487b7fc7d860d62
> Author: Kay Sievers <kay@vrfy.org>
> Date:   Thu May 3 02:29:13 2012 +0200
> 
>     printk: convert byte-buffer to variable-length record buffer
> 
> It seems printk_emit is also exported and unused.

Yes, this was the infamous commit that complicated printk
code a lot.

Best Regards,
Petr

Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement

[Peter Zijlstra]

On Thu, Oct 12, 2017 at 11:45:37AM +0200, Petr Mladek wrote:
> I think that it is safe after all, see the commit message in the patch
> below.

Its all up to Jason I suppose.