[RFC][PATCH] printk: do not call console drivers from printk_safe context

[RFC][PATCH] printk: do not call console drivers from printk_safe context

[Sergey Senozhatsky]

Calling console drivers from printk_safe() context does not really
make call_console_drivers() any safer, because printk_safe() has
nothing to do with console drivers or the underlying code. At the
same time printk()-s from console drivers are fine, they don't
deadlock the system. We need printk_safe() because of the way
vprintk_emit() works -- we protect logbuf lock, console_owner_lock
and console_sem spin_lock with printk_safe, -- not because of the
console drivers (which don't deal with logbuf, console_owner_lock
or console_sem locks). Hence we can call console drivers outside
of printk_safe() context.

Another thing to notice is that,
printk_safe() introduces unneeded complexity, since any printk()
message from console drivers has to be stored in per-CPU printk_safe()
buffer first, then be flushed via IRQ work:
	call_console_drivers()
	 printk()
	  printk_safe_log_store()
	   IRQ_work()
	    printk_safe_flush_buffer()
	     printk_deferred()
	      log_store()
	       irq_work_queue()               *
	        wake_up_klogd_work_func()     *

Note that this also costs us extra IRQ work [along with the IRQ work
that flushes printk_safe() buffer] - we flush per-CPU printk_safe()
buffers via printk_deferred().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/internal.h | 7 ++++++-
 kernel/printk/printk.c   | 2 ++
 2 files changed, 8 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 2a7d04049af4..f3ba1bf08590 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -55,8 +55,13 @@ void __printk_safe_exit(void);
 	} while (0)
 
 #else
+static void __printk_safe_enter(void) {}
+static void __printk_safe_exit(void) {}
 
-__printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
+static __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
+{
+	return 0;
+}
 
 /*
  * In !PRINTK builds we still export logbuf_lock spin_lock, console_sem
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2f4af216bd6e..9acb25ce6081 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2391,9 +2391,11 @@ void console_unlock(void)
 		 */
 		console_lock_spinning_enable();
 
+		__printk_safe_exit();
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(ext_text, ext_len, text, len);
 		start_critical_timings();
+		__printk_safe_enter();
 
 		if (console_lock_spinning_disable_and_check()) {
 			printk_safe_exit_irqrestore(flags);
-- 
2.17.0

Re: [RFC][PATCH] printk: do not call console drivers from printk_safe context

[Steven Rostedt]

On Tue, 24 Apr 2018 11:28:02 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> Calling console drivers from printk_safe() context does not really
> make call_console_drivers() any safer, because printk_safe() has
> nothing to do with console drivers or the underlying code. At the
> same time printk()-s from console drivers are fine, they don't
> deadlock the system. We need printk_safe() because of the way
> vprintk_emit() works -- we protect logbuf lock, console_owner_lock
> and console_sem spin_lock with printk_safe, -- not because of the
> console drivers (which don't deal with logbuf, console_owner_lock
> or console_sem locks). Hence we can call console drivers outside
> of printk_safe() context.
> 
> Another thing to notice is that,
> printk_safe() introduces unneeded complexity, since any printk()
> message from console drivers has to be stored in per-CPU printk_safe()
> buffer first, then be flushed via IRQ work:
> 	call_console_drivers()
> 	 printk()
> 	  printk_safe_log_store()
> 	   IRQ_work()
> 	    printk_safe_flush_buffer()
> 	     printk_deferred()
> 	      log_store()
> 	       irq_work_queue()               *
> 	        wake_up_klogd_work_func()     *
> 
> Note that this also costs us extra IRQ work [along with the IRQ work
> that flushes printk_safe() buffer] - we flush per-CPU printk_safe()
> buffers via printk_deferred().
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/internal.h | 7 ++++++-
>  kernel/printk/printk.c   | 2 ++
>  2 files changed, 8 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
> index 2a7d04049af4..f3ba1bf08590 100644
> --- a/kernel/printk/internal.h
> +++ b/kernel/printk/internal.h
> @@ -55,8 +55,13 @@ void __printk_safe_exit(void);
>  	} while (0)
>  
>  #else
> +static void __printk_safe_enter(void) {}
> +static void __printk_safe_exit(void) {}
>  
> -__printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
> +static __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
> +{
> +	return 0;
> +}
>  
>  /*
>   * In !PRINTK builds we still export logbuf_lock spin_lock, console_sem
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 2f4af216bd6e..9acb25ce6081 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2391,9 +2391,11 @@ void console_unlock(void)
>  		 */
>  		console_lock_spinning_enable();
>  
> +		__printk_safe_exit();
>  		stop_critical_timings();	/* don't trace print latency */
>  		call_console_drivers(ext_text, ext_len, text, len);
>  		start_critical_timings();
> +		__printk_safe_enter();
>  

OK, I'm still confused (It's been that kind of week)

So, if we do this, and the consoles do a printk(), doesn't that fill
the logbuf? And then the loop this is in will just continue to perform
that loop? That is, we have:

  for (;;) {
	if (console_seq == log_next_seq)
		break;
	console_seq++;
	call_console_drives() {
		printk() {
			log_next_seq++;
		}
	}
  }

That looks like an infinite loop to me. Whereas the printk_safe keeps
from adding to the logbuf?

-- Steve


>  		if (console_lock_spinning_disable_and_check()) {
>  			printk_safe_exit_irqrestore(flags);

Re: [RFC][PATCH] printk: do not call console drivers from printk_safe context

[Sergey Senozhatsky]

On (04/24/18 10:51), Steven Rostedt wrote:
[..]
> >  		console_lock_spinning_enable();
> >  
> > +		__printk_safe_exit();
> >  		stop_critical_timings();	/* don't trace print latency */
> >  		call_console_drivers(ext_text, ext_len, text, len);
> >  		start_critical_timings();
> > +		__printk_safe_enter();
> >  
> 
> OK, I'm still confused (It's been that kind of week)

No worries, I'm here to help.
The email is, once again, a bit long, but hey at least I'm using
capitals now ;)

> So, if we do this, and the consoles do a printk(), doesn't that fill
> the logbuf?

Yes. It's been this way for many years, and, in fact, even with
printk_safe() we still add concole_drivers->printk() messages to
the logbuf ASAP, which mostly happens while the printing CPU is
still in console_unlock() loop [see #flushing below].

> And then the loop this is in will just continue to perform that loop?

Yes. And it's the same even with printk_safe(). Except that
printk_safe() costs us 2 extra IRQ works on that CPU.

In short, what printk_safe() does:

a) protects us from deadlocking on logbuf spin_lock

E.g.
       vprintk_emit()
       {
         raw_spin_lock(&logbuf_lock);
           vscnprintf(text, sizeof(textbuf), fmt, args)
:            WARN_ONCE(1, "Unsupported flags modifier....)
:             printk()
:              vprintk_emit()
:               raw_spin_lock(&logbuf_lock);                 <<<<<<<
         raw_spin_unlock(&logbuf_lock);
       }

b) protects us from deadlocking on console_sem (for example, console_sem
   ->lock spin_lock)

E.g.
     console_unlock()
     {
       for (;;) {
        if (console_seq == log_next_seq)
         break;
       }

       up()
:       raw_spin_lock_irqsave(&sem->lock, flags);
:        printk()
:         vprintk_emit()
:          if (console_trylock_spinning())
:           console_trylock()
:            down_trylock()
:             raw_spin_lock_irqsave(&sem->lock, flags);     <<<<<<<
     }


c) protects us from deadlocking on console_sem_owner spin_lock
  Basically, the same as (a) - deadlock on spin_lock, but at the moment
  I'd say a rather theoretical case.

d) protects us from deadlocking on _some_ external locks. For example,
   scheduler ->pi_lock lock


> That is, we have:
> 
>   for (;;) {
> 	if (console_seq == log_next_seq)
> 		break;
> 	console_seq++;
> 	call_console_drives() {
> 		printk() {
> 			log_next_seq++;
> 		}
> 	}
>   }
> 
> That looks like an infinite loop to me.

Correct, this is how it works. And I think we need to preserve that
"console drivers can add messages to the logbuf" and to avoid any
interference [and by interference I mean a deliberate message loss]
with the messages. I have provided some links [in another email] to
support that claim, let me know.


I'd love to see real backtraces/logs when we actually have that
infinite loop.

> Whereas the printk_safe keeps from adding to the logbuf?

#flushing

printk_safe() does not keep console drivers from adding new messages
to the logbuf. We flush [move messages to the logbuf] printk_safe()
per-CPU buffer the moment we enable local IRQ on that CPU: which is,
basically, right after call_console_drivers():

for (;;) {
	printk_safe_enter_irqsave(flags);
	raw_spin_lock(&logbuf_lock);

	if (console_seq == log_next_seq)
		break;
	console_seq++;
	raw_spin_unlock(&logbuf_lock);

	call_console_drives() {
		printk()
		 printk_safe_log_store()      ::
		  irq_work_queue()            ::
	}

	printk_safe_exit_irqrestore(flags);   ::

	 << IRQ >>
	   printk_safe_flush_buffer()
	    printk_deferred()
	     log_store()                        << log_next_seq++
	      irq_work_queue()
}

In it's current form printk_safe() is redundant here.

	-ss

Re: [RFC][PATCH] printk: do not call console drivers from printk_safe context

[Petr Mladek]

On Tue 2018-04-24 10:51:04, Steven Rostedt wrote:
> On Tue, 24 Apr 2018 11:28:02 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > Calling console drivers from printk_safe() context does not really
> > make call_console_drivers() any safer, because printk_safe() has
> > nothing to do with console drivers or the underlying code. At the
> > same time printk()-s from console drivers are fine, they don't
> > deadlock the system. We need printk_safe() because of the way
> > vprintk_emit() works -- we protect logbuf lock, console_owner_lock
> > and console_sem spin_lock with printk_safe, -- not because of the
> > console drivers (which don't deal with logbuf, console_owner_lock
> > or console_sem locks). Hence we can call console drivers outside
> > of printk_safe() context.

The above paragraph is not easy to understand. I wonder if the
following might be more clear:

"Calling console drivers from printk_safe() context does not really
make call_console_drivers() any safer. They are never called
recursively thanks to console_trylock() in vprintk_emit()."


> > Another thing to notice is that,
> > printk_safe() introduces unneeded complexity, since any printk()
> > message from console drivers has to be stored in per-CPU printk_safe()
> > buffer first, then be flushed via IRQ work:
> > 	call_console_drivers()
> > 	 printk()
> > 	  printk_safe_log_store()
> > 	   IRQ_work()
> > 	    printk_safe_flush_buffer()
> > 	     printk_deferred()
> > 	      log_store()
> > 	       irq_work_queue()               *
> > 	        wake_up_klogd_work_func()     *
> > 
> > Note that this also costs us extra IRQ work [along with the IRQ work
> > that flushes printk_safe() buffer] - we flush per-CPU printk_safe()
> > buffers via printk_deferred().
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> > ---
> >  kernel/printk/internal.h | 7 ++++++-
> >  kernel/printk/printk.c   | 2 ++
> >  2 files changed, 8 insertions(+), 1 deletion(-)
> > 
> > diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
> > index 2a7d04049af4..f3ba1bf08590 100644
> > --- a/kernel/printk/internal.h
> > +++ b/kernel/printk/internal.h
> > @@ -55,8 +55,13 @@ void __printk_safe_exit(void);
> >  	} while (0)
> >  
> >  #else
> > +static void __printk_safe_enter(void) {}
> > +static void __printk_safe_exit(void) {}
> >  
> > -__printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
> > +static __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
> > +{
> > +	return 0;
> > +}
> >  
> >  /*
> >   * In !PRINTK builds we still export logbuf_lock spin_lock, console_sem
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 2f4af216bd6e..9acb25ce6081 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2391,9 +2391,11 @@ void console_unlock(void)
> >  		 */
> >  		console_lock_spinning_enable();
> >  
> > +		__printk_safe_exit();
> >  		stop_critical_timings();	/* don't trace print latency */
> >  		call_console_drivers(ext_text, ext_len, text, len);
> >  		start_critical_timings();
> > +		__printk_safe_enter();
> >  
> 
> OK, I'm still confused (It's been that kind of week)
> 
> So, if we do this, and the consoles do a printk(), doesn't that fill
> the logbuf? And then the loop this is in will just continue to perform
> that loop? That is, we have:
> 
>   for (;;) {
> 	if (console_seq == log_next_seq)
> 		break;
> 	console_seq++;
> 	call_console_drives() {
> 		printk() {
> 			log_next_seq++;
> 		}
> 	}
>   }
> 
> That looks like an infinite loop to me. Whereas the printk_safe keeps
> from adding to the logbuf?

Unfortunately printk_safe context helps only when console_unlock() is
called with IRQs disabled. Otherwise, the per-CPU buffer is flushed
in every for(;;) cycle, see:

console_unlock()
{

	for (;;) {
		printk_safe_enter_irqsave(flags);

		call_console_drivers(ext_text, ext_len, text, len);

		printk_safe_exit_irqrestore(flags);   <--- IRQs enabled...

		if (do_cond_resched)
			cond_resched();
       }
}

Also it helps only when returning from console_unlock() allows to
calm down the console drivers. Otherwise, flushing the printk_safe
buffers would just trigger another loop...

So I agree that printk_safe context does not help much. And I fine
with this patch.

Best Regards,
Petr

Re: [RFC][PATCH] printk: do not call console drivers from printk_safe context

[Sergey Senozhatsky]

On (04/25/18 16:48), Petr Mladek wrote:
[..]
> 
> The above paragraph is not easy to understand. I wonder if the
> following might be more clear:
> 
> "Calling console drivers from printk_safe() context does not really
> make call_console_drivers() any safer. They are never called
> recursively thanks to console_trylock() in vprintk_emit()."

Yes, looks good.

[..]
> Unfortunately printk_safe context helps only when console_unlock() is
> called with IRQs disabled. Otherwise, the per-CPU buffer is flushed
> in every for(;;) cycle.

Right. I thought about it. If console_unlock() is called with IRQs
disabled then we postpone flush until we return from console_unlock()
and enable local IRQs. But then we have printk_safe() flush, which
uses printk_deferred() -> queue irq_work -> irq work -> console_unlock(),
so quite likely we still print out printk_safe() buffer from atomic
context (from irq in this case).

> So I agree that printk_safe context does not help much. And I fine
> with this patch.

Thanks.

	-ss

Re: [RFC][PATCH] printk: do not call console drivers from printk_safe context

[Sergey Senozhatsky]

On (04/25/18 16:48), Petr Mladek wrote:
> 
> So I agree that printk_safe context does not help much. And I fine
> with this patch.
> 

Petr, do you want me to resend the patch with the updated commit message?

	-ss

Re: [RFC][PATCH] printk: do not call console drivers from printk_safe context

[Petr Mladek]

On Mon 2018-06-18 15:39:16, Sergey Senozhatsky wrote:
> On (04/25/18 16:48), Petr Mladek wrote:
> > 
> > So I agree that printk_safe context does not help much. And I fine
> > with this patch.
> > 
> 
> Petr, do you want me to resend the patch with the updated commit message?

I am sorry for abandoning this patch. Hmm, I am a bit unsure about it now.

The printk_safe context partly prevents recursion problems when
console drivers print messages. I expected that this patch
would have been pushed together with a better solution for
the recursion. But we still do not have any.

Would you mind to keep it on hold for now? I know that it might
help in some situations. But it also makes the code more complicated
and there is some risk of a regression. I would prefer when it
is pushed in a situation when it is a clear win.

Best Regards,
Petr

Re: [RFC][PATCH] printk: do not call console drivers from printk_safe context

[Sergey Senozhatsky]

On (06/18/18 11:59), Petr Mladek wrote:
> 
> Would you mind to keep it on hold for now?

OK.

	-ss