Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1503235 > unrolled thread

[PATCH 0/3] make printk work again

Back to article view | Back to linux.kernel

Contents

  [PATCH 0/3] make printk work again Peter Zijlstra <peterz@infradead.org> - 2016-10-18 19:20 +0200
    [PATCH 1/3] printk: Fix kdb_trap_printk placement Peter Zijlstra <peterz@infradead.org> - 2016-10-18 19:20 +0200
      Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement Petr Mladek <pmladek@suse.com> - 2016-10-19 16:50 +0200
        Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement Peter Zijlstra <peterz@infradead.org> - 2016-10-19 17:20 +0200
      Re: [PATCH 1/3] printk: Fix kdb_trap_printk placement Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-10-20 15:10 +0200
    [PATCH 3/3] early_printk: Add simple serialization to early_vprintk() Peter Zijlstra <peterz@infradead.org> - 2016-10-18 19:20 +0200
      Re: [PATCH 3/3] early_printk: Add simple serialization to  early_vprintk() Steven Rostedt <rostedt@goodmis.org> - 2016-10-18 19:30 +0200
        Re: [PATCH 3/3] early_printk: Add simple serialization to  early_vprintk() Peter Zijlstra <peterz@infradead.org> - 2016-10-18 19:40 +0200
          Re: [PATCH 3/3] early_printk: Add simple serialization to  early_vprintk() Steven Rostedt <rostedt@goodmis.org> - 2016-10-18 20:00 +0200
    [PATCH 2/3] early_printk: Add force_early_printk kernel parameter Peter Zijlstra <peterz@infradead.org> - 2016-10-18 19:20 +0200
    Re: [PATCH 0/3] make printk work again Peter Zijlstra <peterz@infradead.org> - 2016-10-19 16:30 +0200
    Re: [PATCH 0/3] make printk work again Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-10-19 16:30 +0200
    Re: [PATCH 0/3] make printk work again Jan Kara <jack@suse.cz> - 2016-10-19 17:00 +0200
      Re: [PATCH 0/3] make printk work again Peter Zijlstra <peterz@infradead.org> - 2016-10-19 18:20 +0200

#1503235 — [PATCH 0/3] make printk work again

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.

[toc] | [next] | [standalone]

#1503239 — [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>
---
 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);
 

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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.

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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;
 }
 

[toc] | [prev] | [next] | [standalone]

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

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;
>  }
>  
> 

[toc] | [prev] | [next] | [standalone]

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

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();
 	}
 

[toc] | [prev] | [next] | [standalone]

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

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();
>  	}
>  

[toc] | [prev] | [next] | [standalone]

#1503245 — [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>
---
 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)
 {

[toc] | [prev] | [next] | [standalone]

#1503655

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.

[toc] | [prev] | [next] | [standalone]

#1503669

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

[toc] | [prev] | [next] | [standalone]

#1503786

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

[toc] | [prev] | [next] | [standalone]

#1504050

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.

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web