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

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

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

[Peter Zijlstra]

[-- Attachment #1: peterz-force_early_printk.patch --]
[-- Type: text/plain, Size: 2569 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 |   68 +++++++++++++++++++++++++++++++++----------------
 1 file changed, 47 insertions(+), 21 deletions(-)

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -365,6 +365,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
@@ -1816,6 +1852,11 @@ asmlinkage int vprintk_emit(int facility
 		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;
@@ -1939,7 +1980,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;
@@ -1975,26 +2021,6 @@ static size_t msg_print_text(const struc
 static bool suppress_message_printing(int level) { return false; }
 #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)
 {

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

[Peter Zijlstra]

[-- Attachment #1: peterz-early_printk-serialize.patch --]
[-- Type: text/plain, Size: 1422 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 |   35 ++++++++++++++++++++++++++++++++++-
 1 file changed, 34 insertions(+), 1 deletion(-)

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -378,14 +378,47 @@ 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();
+	/*
+	 * Test-and-Set inter-cpu spinlock with recursion.
+	 */
+	for (;;) {
+		/*
+		 * c-cas to avoid the exclusive bouncing on spin.
+		 * Depends on the memory barrier implied by cmpxchg
+		 * for ACQUIRE semantics.
+		 */
+		old = READ_ONCE(early_printk_cpu);
+		if (old == -1) {
+			old = cmpxchg(&early_printk_cpu, -1, cpu);
+			if (old == -1)
+				break;
+		}
+		/*
+		 * Allow recursion for interrupts and the like.
+		 */
+		if (old == cpu)
+			break;
+
+		cpu_relax();
+	}
 
 	n = vscnprintf(buf, sizeof(buf), fmt, args);
 	early_console->write(early_console, buf, n);
 
+	/*
+	 * Unlock -- in case @old == @cpu, this is a no-op.
+	 */
+	smp_store_release(&early_printk_cpu, old);
+	put_cpu();
+
 	return n;
 }
 

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

[Randy Dunlap]

On 09/28/17 05:18, Peter Zijlstra wrote:

<attachment not shown>

Hi Peter,

Please add that kernel parameter to Documentation/admin-guide/kernel-parameters.txt.

thanks,
-- 
~Randy

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

[Sergey Senozhatsky]

On (09/28/17 14:18), Peter Zijlstra wrote:
> 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.

hold on... wait a second... the scheduler is not lockless yet? darn...

ok, I think having something like that in printk.c wouldn't hurt. Petr
was going to take a look, IIRC.

but what's up with that scheduler thing I keep hearing about, must be
something new, can I disable it in kconfig? it seems to be conflicting
with CONFIG_PRINTK.

	-ss

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

[Peter Zijlstra]

On Thu, Sep 28, 2017 at 08:41:37AM -0700, Randy Dunlap wrote:

> Please add that kernel parameter to Documentation/admin-guide/kernel-parameters.txt.

Something like so?

--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -1165,6 +1165,11 @@
 			parameter will force ia64_sal_cache_flush to call
 			ia64_pal_cache_flush instead of SAL_CACHE_FLUSH.
 
+	force_early_printk
+			Forcefully uses early_console (as per earlyprintk=)
+			usage for regular printk, bypassing everything,
+			including the syslog (dmesg will be empty).
+
 	forcepae [X86-32]
 			Forcefully enable Physical Address Extension (PAE).
 			Many Pentium M systems disable PAE but may have a

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

[Peter Zijlstra]

On Fri, Sep 29, 2017 at 01:02:30AM +0900, Sergey Senozhatsky wrote:
> but what's up with that scheduler thing I keep hearing about, must be
> something new, can I disable it in kconfig? it seems to be conflicting
> with CONFIG_PRINTK.

Its not new, its been there for a very long time :-)

The problem is that the scheduler has WARN()s in, those tend to tickle
printk(). Printk() on its own has this console semaphore that tends to
want to schedule. Console drivers have things like wakeups, which tend
to not work when you're already holding scheduler locks etc..

Its one big giant mess.. Since you removed that lockdep_off() from
printk() lockdep now sees and complains, which again hits printk(),
recursion FTW!

Similarly, since there's a metric ton of locks all over printk() and
console driver code, printk() doesn't work well from NMI context. And
the taken approach to buffering and then printing later has issues if
there is no later.

Both problems are solved by using early_printk which has lockless
drivers (x86 early_serial_console is the one I use) and avoids all
problems that way.

Its bullet proof console output. Always works. Its been very good to me.

(it of course doesn't help that I work on the scheduler and perf, the
latter of which does lots of cruft in NMI context. So I tend to run into
the very worst possible situations more than most other people)

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

[Randy Dunlap]

On 09/28/17 09:07, Peter Zijlstra wrote:
> On Thu, Sep 28, 2017 at 08:41:37AM -0700, Randy Dunlap wrote:
> 
>> Please add that kernel parameter to Documentation/admin-guide/kernel-parameters.txt.
> 
> Something like so?

Yes, thanks. Ack.

> --- a/Documentation/admin-guide/kernel-parameters.txt
> +++ b/Documentation/admin-guide/kernel-parameters.txt
> @@ -1165,6 +1165,11 @@
>  			parameter will force ia64_sal_cache_flush to call
>  			ia64_pal_cache_flush instead of SAL_CACHE_FLUSH.
>  
> +	force_early_printk
> +			Forcefully uses early_console (as per earlyprintk=)
> +			usage for regular printk, bypassing everything,
> +			including the syslog (dmesg will be empty).
> +
>  	forcepae [X86-32]
>  			Forcefully enable Physical Address Extension (PAE).
>  			Many Pentium M systems disable PAE but may have a
> 


-- 
~Randy

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 2/3] early_printk: Add force_early_printk kernel parameter

[Steven Rostedt]

On Thu, 28 Sep 2017 14:18:25 +0200
Peter Zijlstra <peterz@infradead.org> 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.

Probably break this up into two patches. One for creation of
early_vprintk(), and the other to add the force_early_printk parameter.

-- Steve

> 
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> ---
>  kernel/printk/printk.c |   68 +++++++++++++++++++++++++++++++++----------------
>  1 file changed, 47 insertions(+), 21 deletions(-)
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -365,6 +365,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
> @@ -1816,6 +1852,11 @@ asmlinkage int vprintk_emit(int facility
>  		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;
> @@ -1939,7 +1980,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;
> @@ -1975,26 +2021,6 @@ static size_t msg_print_text(const struc
>  static bool suppress_message_printing(int level) { return false; }
>  #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 3/3] early_printk: Add simple serialization to early_vprintk()

[Steven Rostedt]

On Thu, 28 Sep 2017 14:18:26 +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>
> ---
>  kernel/printk/printk.c |   35 ++++++++++++++++++++++++++++++++++-
>  1 file changed, 34 insertions(+), 1 deletion(-)
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -378,14 +378,47 @@ 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();
> +	/*
> +	 * Test-and-Set inter-cpu spinlock with recursion.
> +	 */
> +	for (;;) {
> +		/*
> +		 * c-cas to avoid the exclusive bouncing on spin.
> +		 * Depends on the memory barrier implied by cmpxchg
> +		 * for ACQUIRE semantics.
> +		 */
> +		old = READ_ONCE(early_printk_cpu);
> +		if (old == -1) {

If old != -1 and old != cpu, is it possible that the CPU could have
fetched an old value, and never try to fetch it again?

The cmpxchg memory barrier only happens when old == -1.

-- Steve

> +			old = cmpxchg(&early_printk_cpu, -1, cpu);
> +			if (old == -1)
> +				break;
> +		}
> +		/*
> +		 * Allow recursion for interrupts and the like.
> +		 */
> +		if (old == cpu)
> +			break;
> +
> +		cpu_relax();
> +	}
>  
>  	n = vscnprintf(buf, sizeof(buf), fmt, args);
>  	early_console->write(early_console, buf, n);
>  
> +	/*
> +	 * Unlock -- in case @old == @cpu, this is a no-op.
> +	 */
> +	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 03, 2017 at 06:24:22PM -0400, Steven Rostedt wrote:
> On Thu, 28 Sep 2017 14:18:26 +0200
> Peter Zijlstra <peterz@infradead.org> wrote:
> >  static int early_vprintk(const char *fmt, va_list args)
> >  {
> > +	int n, cpu, old;
> >  	char buf[512];
> > +
> > +	cpu = get_cpu();
> > +	/*
> > +	 * Test-and-Set inter-cpu spinlock with recursion.
> > +	 */
> > +	for (;;) {
> > +		/*
> > +		 * c-cas to avoid the exclusive bouncing on spin.
> > +		 * Depends on the memory barrier implied by cmpxchg
> > +		 * for ACQUIRE semantics.
> > +		 */
> > +		old = READ_ONCE(early_printk_cpu);
> > +		if (old == -1) {
> 
> If old != -1 and old != cpu, is it possible that the CPU could have
> fetched an old value, and never try to fetch it again?

What? If old != -1 and old != cpu, we'll hit the cpu_relax() and do the
READ_ONCE() again. The READ_ONCE() guarantees we'll do the load again,
as does the barrier() implied by cpu_relax().

> The cmpxchg memory barrier only happens when old == -1.

Yeah, so?

> > +			old = cmpxchg(&early_printk_cpu, -1, cpu);
> > +			if (old == -1)
> > +				break;
> > +		}
> > +		/*
> > +		 * Allow recursion for interrupts and the like.
> > +		 */
> > +		if (old == cpu)
> > +			break;
> > +
> > +		cpu_relax();
> > +	}
> >  
> >  	n = vscnprintf(buf, sizeof(buf), fmt, args);
> >  	early_console->write(early_console, buf, n);
> >  
> > +	/*
> > +	 * Unlock -- in case @old == @cpu, this is a no-op.
> > +	 */
> > +	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 Wed, 4 Oct 2017 11:08:30 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Tue, Oct 03, 2017 at 06:24:22PM -0400, Steven Rostedt wrote:
> > On Thu, 28 Sep 2017 14:18:26 +0200
> > Peter Zijlstra <peterz@infradead.org> wrote:  
> > >  static int early_vprintk(const char *fmt, va_list args)
> > >  {
> > > +	int n, cpu, old;
> > >  	char buf[512];
> > > +
> > > +	cpu = get_cpu();
> > > +	/*
> > > +	 * Test-and-Set inter-cpu spinlock with recursion.
> > > +	 */
> > > +	for (;;) {
> > > +		/*
> > > +		 * c-cas to avoid the exclusive bouncing on spin.
> > > +		 * Depends on the memory barrier implied by cmpxchg
> > > +		 * for ACQUIRE semantics.
> > > +		 */
> > > +		old = READ_ONCE(early_printk_cpu);
> > > +		if (old == -1) {  
> > 
> > If old != -1 and old != cpu, is it possible that the CPU could have
> > fetched an old value, and never try to fetch it again?  
> 
> What? If old != -1 and old != cpu, we'll hit the cpu_relax() and do the
> READ_ONCE() again. The READ_ONCE() guarantees we'll do the load again,
> as does the barrier() implied by cpu_relax().

I'm more worried about other architectures that don't have as strong of
a cache coherency.

[ Added Paul as he knows a lot about odd architectures ]

Is there any architecture that we support that can have the following:

	CPU0			CPU1
	----			----
			    early_printk_cpu = 1
 for (;;)
   old = READ_ONCE(early_printk_cpu);
   [ old = 1 ]

			    early_printk_cpu = -1

   [...]
   cpu_relax();
   old = READ_ONCE(early_printk_cpu);

   [ but the CPU uses the cache and not the memory? ]

   old = 1;

-- Steve


> 
> > The cmpxchg memory barrier only happens when old == -1.  
> 
> Yeah, so?
> 
> > > +			old = cmpxchg(&early_printk_cpu, -1, cpu);
> > > +			if (old == -1)
> > > +				break;
> > > +		}
> > > +		/*
> > > +		 * Allow recursion for interrupts and the like.
> > > +		 */
> > > +		if (old == cpu)
> > > +			break;
> > > +
> > > +		cpu_relax();
> > > +	}
> > >  
> > >  	n = vscnprintf(buf, sizeof(buf), fmt, args);
> > >  	early_console->write(early_console, buf, n);
> > >  
> > > +	/*
> > > +	 * Unlock -- in case @old == @cpu, this is a no-op.
> > > +	 */
> > > +	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 Wed, Oct 04, 2017 at 09:04:01AM -0400, Steven Rostedt wrote:

> > > If old != -1 and old != cpu, is it possible that the CPU could have
> > > fetched an old value, and never try to fetch it again?  
> > 
> > What? If old != -1 and old != cpu, we'll hit the cpu_relax() and do the
> > READ_ONCE() again. The READ_ONCE() guarantees we'll do the load again,
> > as does the barrier() implied by cpu_relax().
> 
> I'm more worried about other architectures that don't have as strong of
> a cache coherency.

Linux mandates cache-coherency, there's no weak or strong there. Memory
ordering can be weak or strong, but coherency not.

If this patch is broken, lots of code would be broken.

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

[Paul E. McKenney]

On Wed, Oct 04, 2017 at 09:04:01AM -0400, Steven Rostedt wrote:
> On Wed, 4 Oct 2017 11:08:30 +0200
> Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > On Tue, Oct 03, 2017 at 06:24:22PM -0400, Steven Rostedt wrote:
> > > On Thu, 28 Sep 2017 14:18:26 +0200
> > > Peter Zijlstra <peterz@infradead.org> wrote:  
> > > >  static int early_vprintk(const char *fmt, va_list args)
> > > >  {
> > > > +	int n, cpu, old;
> > > >  	char buf[512];
> > > > +
> > > > +	cpu = get_cpu();
> > > > +	/*
> > > > +	 * Test-and-Set inter-cpu spinlock with recursion.
> > > > +	 */
> > > > +	for (;;) {
> > > > +		/*
> > > > +		 * c-cas to avoid the exclusive bouncing on spin.
> > > > +		 * Depends on the memory barrier implied by cmpxchg
> > > > +		 * for ACQUIRE semantics.
> > > > +		 */
> > > > +		old = READ_ONCE(early_printk_cpu);
> > > > +		if (old == -1) {  
> > > 
> > > If old != -1 and old != cpu, is it possible that the CPU could have
> > > fetched an old value, and never try to fetch it again?  
> > 
> > What? If old != -1 and old != cpu, we'll hit the cpu_relax() and do the
> > READ_ONCE() again. The READ_ONCE() guarantees we'll do the load again,
> > as does the barrier() implied by cpu_relax().
> 
> I'm more worried about other architectures that don't have as strong of
> a cache coherency.
> 
> [ Added Paul as he knows a lot about odd architectures ]
> 
> Is there any architecture that we support that can have the following:
> 
> 	CPU0			CPU1
> 	----			----
> 			    early_printk_cpu = 1
>  for (;;)
>    old = READ_ONCE(early_printk_cpu);
>    [ old = 1 ]
> 
> 			    early_printk_cpu = -1
> 
>    [...]
>    cpu_relax();
>    old = READ_ONCE(early_printk_cpu);
> 
>    [ but the CPU uses the cache and not the memory? ]
> 
>    old = 1;

If you use READ_ONCE(), then all architectures I know of enforce
full ordering for accesses to a single variable.  (If you don't use
READ_ONCE(), then in theory Itanium can reorder reads.)  Me, I would
argue for WRITE_ONCE() as well to prevent store tearing.

It is only when you have at least two variables and at least two threads
than things start getting really "interesting".  ;-)

							Thanx, Paul

> -- Steve
> 
> 
> > 
> > > The cmpxchg memory barrier only happens when old == -1.  
> > 
> > Yeah, so?
> > 
> > > > +			old = cmpxchg(&early_printk_cpu, -1, cpu);
> > > > +			if (old == -1)
> > > > +				break;
> > > > +		}
> > > > +		/*
> > > > +		 * Allow recursion for interrupts and the like.
> > > > +		 */
> > > > +		if (old == cpu)
> > > > +			break;
> > > > +
> > > > +		cpu_relax();
> > > > +	}
> > > >  
> > > >  	n = vscnprintf(buf, sizeof(buf), fmt, args);
> > > >  	early_console->write(early_console, buf, n);
> > > >  
> > > > +	/*
> > > > +	 * Unlock -- in case @old == @cpu, this is a no-op.
> > > > +	 */
> > > > +	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 Wed, 4 Oct 2017 07:17:45 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:

> > I'm more worried about other architectures that don't have as strong of
> > a cache coherency.
> > 
> > [ Added Paul as he knows a lot about odd architectures ]
> > 
> > Is there any architecture that we support that can have the following:
> > 
> > 	CPU0			CPU1
> > 	----			----
> > 			    early_printk_cpu = 1
> >  for (;;)
> >    old = READ_ONCE(early_printk_cpu);
> >    [ old = 1 ]
> > 
> > 			    early_printk_cpu = -1
> > 
> >    [...]
> >    cpu_relax();
> >    old = READ_ONCE(early_printk_cpu);
> > 
> >    [ but the CPU uses the cache and not the memory? ]
> > 
> >    old = 1;  
> 
> If you use READ_ONCE(), then all architectures I know of enforce
> full ordering for accesses to a single variable.  (If you don't use
> READ_ONCE(), then in theory Itanium can reorder reads.)  Me, I would
> argue for WRITE_ONCE() as well to prevent store tearing.
> 
> It is only when you have at least two variables and at least two threads
> than things start getting really "interesting".  ;-)
> 

My question is not about ordering, but about coherency. Can you have
one CPU read a variable that goes into cache, and keep using the cached
variable every time the program asks to read it, instead of going out
to memory.

Also, on the other CPU, if a variable is written, and the cache is not
write-through, could that variable be sitting in cache and not go out
to memory until a flush happens?

Do we support architectures that don't have strong coherency to know
that one CPU is asking for a memory location for something that was
changed in the cache of another CPU. Or a CPU will return old cache data
even though the memory was updated?

I guess my concern is that READ_ONCE() and cpu_relax(), don't actually
do a memory barrier. They are mostly compiler barriers. Do we support
poorly coherent architectures that require some kind of flush to make
sure the communication exists between the two CPUs?

Note, at TimeSys, I had to port Linux to a poorly coherent SMP board
that would trip over this all the time. I don't know if that board is
sufficient to run Linux, as we had to slap in memory barriers all over
the place. But this was a 2.4 kernel at the time.

-- Steve

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

[Peter Zijlstra]

On Wed, Oct 04, 2017 at 10:43:54AM -0400, Steven Rostedt wrote:
> 
> My question is not about ordering, but about coherency. Can you have
> one CPU read a variable that goes into cache, and keep using the cached
> variable every time the program asks to read it, instead of going out
> to memory.

No, not on a coherent system.

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

[Steven Rostedt]

On Wed, 4 Oct 2017 16:52:47 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Wed, Oct 04, 2017 at 10:43:54AM -0400, Steven Rostedt wrote:
> > 
> > My question is not about ordering, but about coherency. Can you have
> > one CPU read a variable that goes into cache, and keep using the cached
> > variable every time the program asks to read it, instead of going out
> > to memory.  
> 
> No, not on a coherent system.

In this case.

Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

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

[Paul E. McKenney]

On Wed, Oct 04, 2017 at 04:52:47PM +0200, Peter Zijlstra wrote:
> On Wed, Oct 04, 2017 at 10:43:54AM -0400, Steven Rostedt wrote:
> > 
> > My question is not about ordering, but about coherency. Can you have
> > one CPU read a variable that goes into cache, and keep using the cached
> > variable every time the program asks to read it, instead of going out
> > to memory.
> 
> No, not on a coherent system.

What Peter said.  And if you use READ_ONCE() for the reads, than as
far as I know, all the systems that the Linux kernel supports are
coherent systems.

							Thanx, Paul

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

[Peter Zijlstra]

On Wed, Oct 04, 2017 at 07:17:45AM -0700, Paul E. McKenney wrote:
> If you use READ_ONCE(), then all architectures I know of enforce
> full ordering for accesses to a single variable.  (If you don't use
> READ_ONCE(), then in theory Itanium can reorder reads.)  Me, I would
> argue for WRITE_ONCE() as well to prevent store tearing.

Note that the stores are either cmpxchg() or smp_store_release() both of
which imply a WRITE_ONCE().

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

[Paul E. McKenney]

On Wed, Oct 04, 2017 at 05:24:23PM +0200, Peter Zijlstra wrote:
> On Wed, Oct 04, 2017 at 07:17:45AM -0700, Paul E. McKenney wrote:
> > If you use READ_ONCE(), then all architectures I know of enforce
> > full ordering for accesses to a single variable.  (If you don't use
> > READ_ONCE(), then in theory Itanium can reorder reads.)  Me, I would
> > argue for WRITE_ONCE() as well to prevent store tearing.
> 
> Note that the stores are either cmpxchg() or smp_store_release() both of
> which imply a WRITE_ONCE().

That works for me!  ;-)

							Thanx, Paul

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 2/3] early_printk: Add force_early_printk kernel parameter

[Petr Mladek]

On Thu 2017-09-28 14:18:25, 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.
> 
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> ---
>  kernel/printk/printk.c |   68 +++++++++++++++++++++++++++++++++----------------
>  1 file changed, 47 insertions(+), 21 deletions(-)
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -365,6 +365,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);

The parameter is currently used only when CONFIG_PRINTK is enabled.
But CONFIG_EARLY_PRINTK is independent. What would be your preferred
behavior when CONFIG_PRINTK is disabled, please?


> @@ -1816,6 +1852,11 @@ asmlinkage int vprintk_emit(int facility
>  		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;
> @@ -1939,7 +1980,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);

There is rather theoretical race. We skip vprintk_func() because
we believe that vprintk_default()/vprintk_emit() would choose
handle this by early_printk().

A solution would be the clean up of the exported printk() interfaces
that I suggested in the other mail. Then we could choose the right
implementation on a single place: printk_func().

PeterZ, I guess that you do not want to spend much time on this.
But if you basically agree with my proposal, I could start
working on it and rebase this patchset on top of it.

Best Regards,
Petr

PS: I am sorry that I am complicating this rather simple patchset.
I only want to be careful. You know that the current printk code
is a mess and I would like to improve it.

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.

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 2/3] early_printk: Add force_early_printk kernel parameter

[Peter Zijlstra]

On Thu, Oct 12, 2017 at 12:24:19PM +0200, Petr Mladek wrote:
> On Thu 2017-09-28 14:18:25, Peter Zijlstra wrote:

> > +#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);
> 
> The parameter is currently used only when CONFIG_PRINTK is enabled.
> But CONFIG_EARLY_PRINTK is independent. What would be your preferred
> behavior when CONFIG_PRINTK is disabled, please?

Can we even have !PRINTK && EARLY_PRINTK? If so it seems to me continued
usage of early_printk() is what makes most sense.

> > @@ -1816,6 +1852,11 @@ asmlinkage int vprintk_emit(int facility
> >  		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;
> > @@ -1939,7 +1980,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);
> 
> There is rather theoretical race. We skip vprintk_func() because
> we believe that vprintk_default()/vprintk_emit() would choose
> handle this by early_printk().

Do you mean if someone were to toggle force_early_printk at runtime?

The reason I did it like this and not use that function pointer thing is
that I didn't want to risk anybody hijacking my output ever.

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 2/3] early_printk: Add force_early_printk kernel parameter

[Petr Mladek]

On Thu 2017-10-12 13:39:49, Peter Zijlstra wrote:
> On Thu, Oct 12, 2017 at 12:24:19PM +0200, Petr Mladek wrote:
> > On Thu 2017-09-28 14:18:25, Peter Zijlstra wrote:
> 
> > > +#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);
> > 
> > The parameter is currently used only when CONFIG_PRINTK is enabled.
> > But CONFIG_EARLY_PRINTK is independent. What would be your preferred
> > behavior when CONFIG_PRINTK is disabled, please?
> 
> Can we even have !PRINTK && EARLY_PRINTK? If so it seems to me continued
> usage of early_printk() is what makes most sense.

Yes, !PRINTK && EARLY_PRINTK is possible at the moment. It makes some
sense because EARLY_PRINTK needs only consoles and they are needed
also for !PRINTK stuff.

We either should define force_early_printk only when
PRINTK is enabled.

Or we should call early_printk() from printk() also when
PRINTK is disabled. The current implemetation is in
include/linux/printk.h, see

static inline __printf(1, 2) __cold
int printk(const char *s, ...)
{
	return 0;
}

> > > @@ -1816,6 +1852,11 @@ asmlinkage int vprintk_emit(int facility
> > >  		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;
> > > @@ -1939,7 +1980,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);
> > 
> > There is rather theoretical race. We skip vprintk_func() because
> > we believe that vprintk_default()/vprintk_emit() would choose
> > handle this by early_printk().
> 
> Do you mean if someone were to toggle force_early_printk at runtime?

Or that someone unregisters the early console.


> The reason I did it like this and not use that function pointer thing is
> that I didn't want to risk anybody hijacking my output ever.

I understand. I think about refactoring the code so that all
*printk*() variants call printk_func(). This function
could then call the right printk implementation according
to the context or global setting.

This way we could have all the logic on a single place and
avoid the race.

Note that printk_func() is not longer a pointer. It is
a function since the commit 099f1c84c0052ec1b2
("printk: introduce per-cpu safe_print seq buffer").

Best Regards,
Petr

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

[Peter Zijlstra]

On Fri, Oct 13, 2017 at 03:06:09PM +0200, Petr Mladek wrote:

> Or we should call early_printk() from printk() also when
> PRINTK is disabled.

This.

> > Do you mean if someone were to toggle force_early_printk at runtime?
> 
> Or that someone unregisters the early console.

That's broken anyway, nor do I think anybody does that, early_printk is
a set once never touch kinda thing.

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

[Steven Rostedt]

On Fri, 13 Oct 2017 15:06:09 +0200
Petr Mladek <pmladek@suse.com> wrote:
> > 
> > Can we even have !PRINTK && EARLY_PRINTK? If so it seems to me continued
> > usage of early_printk() is what makes most sense.  
> 
> Yes, !PRINTK && EARLY_PRINTK is possible at the moment. It makes some
> sense because EARLY_PRINTK needs only consoles and they are needed
> also for !PRINTK stuff.
> 
> We either should define force_early_printk only when
> PRINTK is enabled.

I think it makes sense to have force_early_printk depend on PRINTK and
EARLY_PRINTK.

 
> > The reason I did it like this and not use that function pointer thing is
> > that I didn't want to risk anybody hijacking my output ever.  
> 
> I understand. I think about refactoring the code so that all
> *printk*() variants call printk_func(). This function
> could then call the right printk implementation according
> to the context or global setting.
> 
> This way we could have all the logic on a single place and
> avoid the race.
> 
> Note that printk_func() is not longer a pointer. It is
> a function since the commit 099f1c84c0052ec1b2
> ("printk: introduce per-cpu safe_print seq buffer").

Yes, I agree with Petr here. Slapping the force printk into
printk_func() should have the same effect, as everything is hard coded
now:

asmlinkage __visible int printk(const char *fmt, ...)
{
	va_list args;
	int r;

	va_start(args, fmt);
	r = vprintk_func(fmt, args);
	va_end(args);

	return r;
}


__printf(1, 0) int vprintk_func(const char *fmt, va_list args)
{
	/* 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);

	/* Use extra buffer to prevent a recursion deadlock in safe mode. */
	if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK)
		return vprintk_safe(fmt, args);

	/*
	 * Use the main logbuf when logbuf_lock is available in NMI.
	 * But avoid calling console drivers that might have their own locks.
	 */
	if (this_cpu_read(printk_context) & PRINTK_NMI_DEFERRED_CONTEXT_MASK)
		return vprintk_deferred(fmt, args);

	/* No obstacles. */
	return vprintk_default(fmt, args);
}

Thus putting in the call to early_printk() at the very beginning of
vprintk_func() would have the result that Peter would like.

-- Steve

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

[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

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

[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

[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

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