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

[Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>]

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