Re: [PATCH v10 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

On (08/31/16 11:38), Petr Mladek wrote:
[..]
> Ah, I do not want to discourage you from finding a solution for these
> problems.

oh, Petr, I didn't mean it. that was a poor/incorrect wording on my side.

> I just wanted to point out problems with this particular
> path of thinking (more per-CPU buffers, shuffling data between
> them and the main buffer and console).

sure, and I do appreciate your input.

that's a good summary.

> Sigh, there are many problems with printk(). I think the we recently
> discussed the following problems:
> 
>   1. Hung task or blocked irq handler when preemption/irqs
>      are disabled and there are too many messages pushed to
>      the console.

    1.1. deferred printing, for instance due to sched throttling

    1.2. unlucky printk() from IRQ handler, that succeeded in grabbing the
console semaphore via console_trylock().

once there is a moderate printk() flood and some of console_unlock()
calls can be executed with preemption disabled, chances of sched
throttling do increase. I've seen this many times in the past.


>   2. Potential deadlocks when calling wake_up_process() by
>      async printk and console_unlock().

    * there are many reasons to those recursive printk() calls -- some
can be addressed, some cannot. for instance, it doesn't matter how many
per-CPU buffers we use for alternative printk() once the logbuf_lock is
corrupted.

another `deadlock' example would be:

SyS_ioctl
 do_vfs_ioctl
  tty_ioctl
   n_tty_ioctl
    tty_mode_ioctl
     set_termios
      tty_set_termios
       uart_set_termios
        uart_change_speed
         FOO_serial_set_termios
          spin_lock_irqsave(&port->lock)     // lock the output port
          ....
          !! WARN() or pr_err() or printk()
              vprintk_emit()
               /* console_trylock() */
               console_unlock()
                call_console_drivers()
                 FOO_write()
                  spin_lock_irqsave(&port->lock)     // already locked


>   3. Clean up the console handling to split manipulation with
>      consoles setting and pushing the messages. By other words,
>      allow to push the console messages only when wanted.

yes, that's a hard one. not only console_unlock() may force a completely
random task to do the printing loop, but console_lock() will force that task
to stay in TASK_UNINTERRUPTIBLE as long as the semaphore is busy. if that
task ends up being a user space process that must reply to systemd watchdog
(user space) signals then things can get confusing. apart from the fact that
that user space process can spend XX seconds printing kernel's messages from
console_unlock().

even a single unfortunate console_trylock() and console_unlock() can lockup
the system, etc. basically because they void the printk_kthread.

so there are several outcomes from reworking console locking, but
the results may vary. depending on particular setups.


>   4. Messed output with continuous lines.

    5. not 100% guaranteed printing on panic
    not entirely related to printk(), but to console output mechanism in
general. we have console_flush_on_panic() which ignores console semaphore
state, to increase our chances of seeing the backtrace. however, there are
more that just one lock involved: logbuf_lock, serial driver locks. so we may
start zap_locks() in console_flush_on_panic() to re-init the logbuf_lock,
but underlying serial driver's locks are still in unclear state. most of
the drivers (if not all of them) take the port->lock under disabled IRQs,
so if panic-CPU is not the one that holds the port->lock then the port->lock
owner CPU will probably unlock the spin_lock before processing its STOP_IPI.
if it's the port->lock CPU that panic() the system (nmi_panic() or BUG())
then things can be bad.


> Our primary target was to solve the 1st problem with the async printk.
> It has stalled because we hit the other areas. Let's look at them
> from this point of view.
>
> Ad 2. The potential deadlock with wake_up_process(). It pooped up
>       with using async printk during the suspend.

right... and no per-CPU buffer could have helped here.

>       But it is not new! up() called by console_unlock() has the
>       same problem. I thought that it was different because
>       console_trylock() would prevent recursion but I was wrong.

correct. Byungchul hit that problem awhile ago https://lkml.org/lkml/2016/2/17/102

>       => If we use normal scheduler for the printk() thread, we should
>       be on the safe side. The deadlock should get fixed but it
>       will be enough to fix it later separately.

agree.

> Ad 4. The problems with messaged continues lines got a bit more
>       visible with the async printk.

yep. I also agree that it might be not so serious to fix it now (if ever).

> Did I miss anything?
> 
> I wonder how to separate the problems and make them more manageable.

so I was thinking for a moment about doing the recursion detection rework
before the async_printk. just because better recursion detection is a nice
thing to have in the first place and it probably may help us catching some
of the surprises that async_printk might have. but it probably will be more
problematic than I thought.

then async_printk. I have a refreshed series on my hands, addressing
Viresh's reports. it certainly makes things better, but it doesn't
eliminate all of the lockups/etc sources. a console_unlock() doing
wake_up_process(printk_kthread) would make it better.

	-ss