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

Groups > linux.kernel > #1470439 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-25 23:30 +0200
    Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-26 04:00 +0200
      Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-26 10:30 +0200
      Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-30 11:30 +0200
        Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-31 04:40 +0200
          Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-31 11:40 +0200
            Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-08-31 15:00 +0200
              Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-09-01 11:00 +0200
                Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-09-02 10:00 +0200
                  Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-09-02 17:20 +0200
                    Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-09-06 09:20 +0200

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

On Mon 2016-08-22 13:15:20, Sergey Senozhatsky wrote:
> Hello,
> 
> On (08/20/16 14:24), Sergey Senozhatsky wrote:
> > On (08/19/16 21:00), Jan Kara wrote:
> > > > > depending on .config BUG() may never return back -- passing control
> > > > > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > > > > probably need to have a per-cpu variable that would indicate that
> > > > > we are in deferred_bug. hm... but do we really need deferred BUG()
> > > > > in the first place?
> > > > 
> since we are basically interested in wake_up_process() only from
> printk() POV. not sure how acceptable 2 * preempt_count and 2 * per-CPU
> writes for every try_to_wake_up().
> 
> 
> the other thing I just thought of is doing something as follows
> !!!not tested, will not compile, just an idea!!!
> 
> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 6e260a0..bb8d719 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1789,6 +1789,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>         printk_delay();
>  
>         local_irq_save(flags);
> +       printk_nmi_enter();
>         this_cpu = smp_processor_id();
>  
>         /*
> @@ -1804,6 +1805,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>                  */
>                 if (!oops_in_progress && !lockdep_recursing(current)) {
>                         recursion_bug = true;
> +                       printk_nmi_exit();
>                         local_irq_restore(flags);
>                         return 0;
>                 }
> @@ -1920,6 +1922,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>         logbuf_cpu = UINT_MAX;
>         raw_spin_unlock(&logbuf_lock);
>         lockdep_on();
> +       printk_nmi_exit();
>         local_irq_restore(flags);
>  
>         /* If called from the scheduler, we can not call up(). */

I was so taken by the idea of temporary forcing a lockless and
"trivial" printk implementation that I missed one thing.

Your patch use the alternative printk() variant around logbuf_lock.
But this is not the problem with wake_up_process(). printk_deferred()
takes logbuf_lock without problems.

Our problem is with calling wake_up_process() recursively. The
deadlock is in the scheduler locks.

But the patch still inspired me. What about blocking the problematic
wake_up_process() call by a per-cpu variable. I mean something like
this completely untested code:

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ca9733b802ce..93915eb1fd0d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1708,6 +1708,8 @@ static size_t cont_print_text(char *text, size_t size)
        return textlen;
 }
 
+DEFINE_PER_CPU(bool, printk_wakeup);
+
 asmlinkage int vprintk_emit(int facility, int level,
                            const char *dict, size_t dictlen,
                            const char *fmt, va_list args)
@@ -1902,8 +1904,17 @@ asmlinkage int vprintk_emit(int facility, int level,
        lockdep_off();
 
        if  (printk_kthread && !in_panic) {
+               bool __percpu *printk_wakeup_ptr;
+
                /* Offload printing to a schedulable context. */
-               wake_up_process(printk_kthread);
+               local_irq_save(flags);
+               printk_wake_up_ptr = this_cpu_ptr(&printk_wake_up);
+               if (!*printk_wakeup_ptr) {
+                       *printk_wake_up_ptr = true;
+                       wake_up_process(printk_kthread);
+                       *printk_wake_up_ptr = false;
+               }
+               local_irq_restore(flags);
                goto out_lockdep;
        } else {
                /*


We might eventually hide this into a wake_up_process_safe() or so.

Also we might need to use it also in console_unlock() to avoid similar
recursion there as well.

Best Regards,
Petr

[toc] | [next] | [standalone]

#1470507

On (08/25/16 23:10), Petr Mladek wrote:
[..]
> I was so taken by the idea of temporary forcing a lockless and
> "trivial" printk implementation that I missed one thing.
> 
> Your patch use the alternative printk() variant around logbuf_lock.
> But this is not the problem with wake_up_process(). printk_deferred()
> takes logbuf_lock without problems.

you didn't miss anything, I think I wasn't too descriptive and that caused
some confusion. this patch is not a replacement of wake_up_process() patch
posted earlier in the loop, but an addition to it. not only every WARN/BUG
issued from wake_up_process() will do no good, but every lock we take is
potentially dangerous as well. In the simplest case because of $LOCK-debug.c
files in kernel/locking (spin_lock in our case); in the worst case --
because of WARNs issued by log_store() and friends (there may be custom
modifications) or by violations of spinlock atomicity requirements.

For example,

	vprintk_emit()
		local_irq_save()
		raw_spin_lock()
		text_len = vscnprintf(text, sizeof(textbuf), fmt, args)
		{
			vsnprintf()
			{
				if (WARN_ON_ONCE(size > INT_MAX))
					return 0;
			}
		}
		...

this is a rather unlikely event, sure, there must be some sort of
memory corruption or something else, but the thing is -- if it will
happen, printk() will not be willing to help.

wake_up_process() change, posted earlier, is using a deferred version of
WARN macro, but we definitely can (and we better do) switch to lockless
alternative printk() in both cases and don't bother with new macros.
replacing all of the existing ones with 'safe' deferred versions is
a difficult task, but keeping track of a newly introduced ones is even
harder (if possible at all).

> +DEFINE_PER_CPU(bool, printk_wakeup);
> +
>  asmlinkage int vprintk_emit(int facility, int level,
>                             const char *dict, size_t dictlen,
>                             const char *fmt, va_list args)
> @@ -1902,8 +1904,17 @@ asmlinkage int vprintk_emit(int facility, int level,
>         lockdep_off();
>  
>         if  (printk_kthread && !in_panic) {
> +               bool __percpu *printk_wakeup_ptr;
> +
>                 /* Offload printing to a schedulable context. */
> -               wake_up_process(printk_kthread);
> +               local_irq_save(flags);
> +               printk_wake_up_ptr = this_cpu_ptr(&printk_wake_up);
> +               if (!*printk_wakeup_ptr) {
> +                       *printk_wake_up_ptr = true;
> +                       wake_up_process(printk_kthread);
> +                       *printk_wake_up_ptr = false;
> +               }
> +               local_irq_restore(flags);
>                 goto out_lockdep;
>         } else {

this can do, thanks.
I would probably prefer, for the time being, to have a single mechanism
that we will use in both cases. something like this:

vprintk_emit()
{
	alt_printk_enter();
	...
	log_store();
	...
	alt_printk_exit();

	wakep_up_process() /* direct from async printk,
			      or indirect from console_unlock()->up() */
		alt_printk_enter();
		... enqueue task
		alt_printk_exit();
}

and we need to have some sort of rollback to default printk() if
BUG() goes to panic() (both on HAVE_ARCH_BUG and !HAVE_ARCH_BUG
platforms):

static void oops_end(...)
{
...
	if (in_interrupt())
		panic("Fatal exception in interrupt");
	if (panic_on_oops)
		panic("Fatal exception");
	if (signr)
		do_exit(signr);
}

not so sure about do_exit(). we are specifically talking here about
wake_up_process()->try_to_wake_up(), which does all of its job under
raw_spin_lock_irqsave(&p->pi_lock), so IF there is a BUG() that does
do_exit() /* hard to imagine that */, then nothing will help us out,
I think.

	-ss

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

#1470594

On (08/26/16 10:56), Sergey Senozhatsky wrote:


> but every lock we take is potentially dangerous as well.
...
> vprintk_emit()
> {
> 	alt_printk_enter();
> 	...
> 	log_store();
> 	...
> 	alt_printk_exit();
> 
> 	wakep_up_process() /* direct from async printk,
> 			      or indirect from console_unlock()->up() */
> 		alt_printk_enter();
> 		... enqueue task
> 		alt_printk_exit();
> }


OTOH, after a very quick thought, up() also takes a spin lock, which
may spindump. so I'll probably prefer to keep the entire alt-printk
thing entirely in printk(). something like this

vprintk_emit()
{
	alt_printk_enter()
	log_store()
	alt_printk_exit()

	if (async_printk)
	{
		alt_printk_enter()
		wake_up_process()
		alt_printk_exit()
	} else {
		if (console_trylock()) {
			console_unlock()
			{
				....
				alt_printk_enter()
				up()
				alt_printk_exit()
			}
		}
	}
}

this leaves console_trylock() `unprotected'. so I guess I'll do
something like this:

	} else {
		int ret;

		alt_printk_enter()
		ret = console_trylock();
		alt_printk_exit()

		if (ret)
			console_unlock();
	}

a bit ugly, but well, it is what it is. will think more about it.

	-ss

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

#1472352

On Fri 2016-08-26 10:56:41, Sergey Senozhatsky wrote:
> On (08/25/16 23:10), Petr Mladek wrote:
> [..]
> > I was so taken by the idea of temporary forcing a lockless and
> > "trivial" printk implementation that I missed one thing.
> > 
> > Your patch use the alternative printk() variant around logbuf_lock.
> > But this is not the problem with wake_up_process(). printk_deferred()
> > takes logbuf_lock without problems.
> 
> you didn't miss anything, I think I wasn't too descriptive and that caused
> some confusion. this patch is not a replacement of wake_up_process() patch
> posted earlier in the loop, but an addition to it. not only every WARN/BUG
> issued from wake_up_process() will do no good, but every lock we take is
> potentially dangerous as well. In the simplest case because of $LOCK-debug.c
> files in kernel/locking (spin_lock in our case); in the worst case --
> because of WARNs issued by log_store() and friends (there may be custom
> modifications) or by violations of spinlock atomicity requirements.
> 
> For example,
> 
> 	vprintk_emit()
> 		local_irq_save()
> 		raw_spin_lock()
> 		text_len = vscnprintf(text, sizeof(textbuf), fmt, args)
> 		{
> 			vsnprintf()
> 			{
> 				if (WARN_ON_ONCE(size > INT_MAX))
> 					return 0;
> 			}
> 		}
> 		...
> 
> this is a rather unlikely event, sure, there must be some sort of
> memory corruption or something else, but the thing is -- if it will
> happen, printk() will not be willing to help.
> 
> wake_up_process() change, posted earlier, is using a deferred version of
> WARN macro, but we definitely can (and we better do) switch to lockless
> alternative printk() in both cases and don't bother with new macros.
> replacing all of the existing ones with 'safe' deferred versions is
> a difficult task, but keeping track of a newly introduced ones is even
> harder (if possible at all).

I see. It makes some sense. I would like to be on the safe side. I am
just afraid that adding yet another per-CPU buffer is too complex.
It adds quite some complexity to the code. And it even more scatters
the messages so that it will be harder to get them from the
crash dump or flush them to the console when the system goes down.

It took few years to get in the solution for NMIs even when
it fixed real life deadlocks for many people and customers.
I am afraid that it is not realistic to get in similar complex
code to fix rather theoretical problems.

Sigh, I waited few days with this comment. I do not want to sound
like a broken record. I have hoped that anyone else could say
an opinion.

Best Regards,
Petr

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

#1472986

On (08/30/16 11:29), Petr Mladek wrote:
> > you didn't miss anything, I think I wasn't too descriptive and that caused
> > some confusion. this patch is not a replacement of wake_up_process() patch
> > posted earlier in the loop, but an addition to it. not only every WARN/BUG
> > issued from wake_up_process() will do no good, but every lock we take is
> > potentially dangerous as well. In the simplest case because of $LOCK-debug.c
> > files in kernel/locking (spin_lock in our case); in the worst case --
> > because of WARNs issued by log_store() and friends (there may be custom
> > modifications) or by violations of spinlock atomicity requirements.
> > 
> > For example,
> > 
> > 	vprintk_emit()
> > 		local_irq_save()
> > 		raw_spin_lock()
> > 		text_len = vscnprintf(text, sizeof(textbuf), fmt, args)
> > 		{
> > 			vsnprintf()
> > 			{
> > 				if (WARN_ON_ONCE(size > INT_MAX))
> > 					return 0;
> > 			}
> > 		}
> > 		...
> > 
> > this is a rather unlikely event, sure, there must be some sort of
> > memory corruption or something else, but the thing is -- if it will
> > happen, printk() will not be willing to help.
> > 
> > wake_up_process() change, posted earlier, is using a deferred version of
> > WARN macro, but we definitely can (and we better do) switch to lockless
> > alternative printk() in both cases and don't bother with new macros.
> > replacing all of the existing ones with 'safe' deferred versions is
> > a difficult task, but keeping track of a newly introduced ones is even
> > harder (if possible at all).
> 
> I see. It makes some sense. I would like to be on the safe side. I am
> just afraid that adding yet another per-CPU buffer is too complex.
> It adds quite some complexity to the code. And it even more scatters
> the messages so that it will be harder to get them from the
> crash dump or flush them to the console when the system goes down.
> 
> It took few years to get in the solution for NMIs even when
> it fixed real life deadlocks for many people and customers.
> I am afraid that it is not realistic to get in similar complex
> code to fix rather theoretical problems.

well, I still can try it in my spare time. we can't fix printk() without
ever touching it, can we? so far we basically only acknowledge the
existing printk() problems. we can do better than that, I think.

> Sigh, I waited few days with this comment. I do not want to sound
> like a broken record.

no worries

	-ss

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

#1473226

On Wed 2016-08-31 11:31:35, Sergey Senozhatsky wrote:
> On (08/30/16 11:29), Petr Mladek wrote:
> > > you didn't miss anything, I think I wasn't too descriptive and that caused
> > > some confusion. this patch is not a replacement of wake_up_process() patch
> > > posted earlier in the loop, but an addition to it. not only every WARN/BUG
> > > issued from wake_up_process() will do no good, but every lock we take is
> > > potentially dangerous as well. In the simplest case because of $LOCK-debug.c
> > > files in kernel/locking (spin_lock in our case); in the worst case --
> > > because of WARNs issued by log_store() and friends (there may be custom
> > > modifications) or by violations of spinlock atomicity requirements.
> > > 
> > > For example,
> > > 
> > > 	vprintk_emit()
> > > 		local_irq_save()
> > > 		raw_spin_lock()
> > > 		text_len = vscnprintf(text, sizeof(textbuf), fmt, args)
> > > 		{
> > > 			vsnprintf()
> > > 			{
> > > 				if (WARN_ON_ONCE(size > INT_MAX))
> > > 					return 0;
> > > 			}
> > > 		}
> > > 		...
> > > 
> > > this is a rather unlikely event, sure, there must be some sort of
> > > memory corruption or something else, but the thing is -- if it will
> > > happen, printk() will not be willing to help.
> > > 
> > > wake_up_process() change, posted earlier, is using a deferred version of
> > > WARN macro, but we definitely can (and we better do) switch to lockless
> > > alternative printk() in both cases and don't bother with new macros.
> > > replacing all of the existing ones with 'safe' deferred versions is
> > > a difficult task, but keeping track of a newly introduced ones is even
> > > harder (if possible at all).
> > 
> > I see. It makes some sense. I would like to be on the safe side. I am
> > just afraid that adding yet another per-CPU buffer is too complex.
> > It adds quite some complexity to the code. And it even more scatters
> > the messages so that it will be harder to get them from the
> > crash dump or flush them to the console when the system goes down.
> > 
> > It took few years to get in the solution for NMIs even when
> > it fixed real life deadlocks for many people and customers.
> > I am afraid that it is not realistic to get in similar complex
> > code to fix rather theoretical problems.
> 
> well, I still can try it in my spare time. we can't fix printk() without
> ever touching it, can we? so far we basically only acknowledge the
> existing printk() problems. we can do better than that, I think.

Ah, I do not want to discourage you from finding a solution for these
problems. 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). But I might be wrong.

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.

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

  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.

  4. Messed output with continuous lines.


They are related but only partly. IMHO, it is not realistic to
fix all the problems in a single patchset. I wonder how to move
forward.

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.

      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.
      There seems to be similar deadlock:

      console_unlock()
	up_console_sem()
	  up()
	    __up()
	      raw_spin_lock_irqsave(&sem->lock, flags);
	      wake_up_process()
		WARN()
		  printk()
		    vprintk_emit()
		      console_trylock()
			down_trylock_console_sem()
			  __down_trylock_console_sem)()
			    down_trylock()
			      raw_spin_lock_irqsave(&sem->lock, flags);

      DEADLOCK: because sem->lock is already taken by __up()

      We hit the deadlock quickly when the printk kthread used SCHED_FIFO.
      But it must be almost impossible to hit it (hit a WARN() with
      the normal scheduler. Otherwise, people would hit it also by
      console_unlock().

      => 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.


Ad 3. The clean up of the console code might change some things. But it
      it is a huge task with unclear output. Anyway, we want to push
      messages to the console from printk(), so it will not help
      to avoid the async printk. It is a completely separate problem
      from my point of view.


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

      It is because a partially flushed cont buffer is blocked
      until the rest of the line is flushed. This happens
      more likely when the messages are flushed by a separate
      process. I have proposed a fix that read the end of the
      partially printed line from the main ring buffer. It
      made the code easier and might be a low risk change.

      In each case, I would not mix it with a perfect solution
      of the continuous lines. IMHO, it would be too complex
      and it is not worth it.

Did I miss anything?

I wonder how to separate the problems and make them more manageable.

Best Regards,
Petr

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

#1473437

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

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

#1474183

On Wed 2016-08-31 21:52:24, Sergey Senozhatsky wrote:
> On (08/31/16 11:38), Petr Mladek wrote:
> >   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.

Yup and BTW: Peter Zijlstra wants to avoid zapping locks whenever
possible because it corrupts the state. It might solve the actual
state but it might cause deadlock by the double unlock.

> 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

Great catch! From the already mentioned solutions, I would prefer
using deferred variants of WARN()/BUG()/printk() on these locations.
Together with using lockdep to find these locations.

Also there is the Peter Zijlstra's idea of using a lockless
"early" console to debug the situations where it happens.
It might make sense to make such a console easy to use.

I am unable to find any other generic solution that would prevent this
from the printk() side at the moment.

>     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.

That might be very hard to solve in general as well. Again the PeterZ's
idea with the lockless console might help here.

> > 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.

We must separate historical possible lockups and new regressions.
Only regressions should block the async printk series. Old
bugs should be fixed separately to keep the series manageable.

Anyway, I think that the async printk will make sense even
when we solve all the other issues. If async printk does not
cause regressions, why not make it in.


> a console_unlock() doing
> wake_up_process(printk_kthread) would make it better.

I am not sure what you mean by this.

Thanks for working on it.

Best Regards,
Petr

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

#1474929

On (09/01/16 10:58), Petr Mladek wrote:
> On Wed 2016-08-31 21:52:24, Sergey Senozhatsky wrote:
> > On (08/31/16 11:38), Petr Mladek wrote:
> > >   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.
> 
> Yup and BTW: Peter Zijlstra wants to avoid zapping locks whenever
> possible because it corrupts the state. It might solve the actual
> state but it might cause deadlock by the double unlock.

yes, don't really want to zap_locks() either.

[..]
> Great catch! From the already mentioned solutions, I would prefer
> using deferred variants of WARN()/BUG()/printk() on these locations.
> Together with using lockdep to find these locations.

hmm... need to think more. one of the problems is that we would have to
periodically "scan" for new WARNs/BUGs/etc doing all the types of random
.configs

> Also there is the Peter Zijlstra's idea of using a lockless
> "early" console to debug the situations where it happens.
> It might make sense to make such a console easy to use.

aha, not really familiar with early console.

> I am unable to find any other generic solution that would prevent this
> from the printk() side at the moment.
> 
> >     5. not 100% guaranteed printing on panic
[..]
> That might be very hard to solve in general as well. Again the PeterZ's
> idea with the lockless console might help here.

"need to google it".

> > > 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.
> 
> We must separate historical possible lockups and new regressions.
> Only regressions should block the async printk series. Old
> bugs should be fixed separately to keep the series manageable.

agree.

> Anyway, I think that the async printk will make sense even
> when we solve all the other issues. If async printk does not
> cause regressions, why not make it in.

sure.

> > a console_unlock() doing
> > wake_up_process(printk_kthread) would make it better.
> 
> I am not sure what you mean by this.

I meant that this thing

	local_irq_save() // or preempt_disable()
	...
	if (console_trylock())
		console_unlock();
	...
	local_irq_restore() // or preempt_enable()


can easily lockup the system if console_trylock() was successful and there
are enough messages to print. printk_kthread can't help, because here we
basically enforce the `old' behavior. we have async printk, but not async
console output. tweaking console_unlock() to offload the actual printing loop
to printk_kthread would make the entire console output async:

	static void console_sync_flush_and_unlock(void)
	{
		for (;;) {
		...
			call_console_drivers();
		...
		}
	}

	void console_unlock(void)
	{
		if (!MOTORMOUTH && can_printk_async()) {
			up();
			wake_up_process(printk_kthread);
			return;
		}
		console_sync_flush_and_unlock();
	}

	-ss

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

#1475237

On Fri 2016-09-02 16:58:08, Sergey Senozhatsky wrote:
> On (09/01/16 10:58), Petr Mladek wrote:
> > On Wed 2016-08-31 21:52:24, Sergey Senozhatsky wrote:
> > > a console_unlock() doing
> > > wake_up_process(printk_kthread) would make it better.
> > 
> > I am not sure what you mean by this.
> 
> I meant that this thing
> 
> 	local_irq_save() // or preempt_disable()
> 	...
> 	if (console_trylock())
> 		console_unlock();
> 	...
> 	local_irq_restore() // or preempt_enable()

I see.

> can easily lockup the system if console_trylock() was successful and there
> are enough messages to print. printk_kthread can't help, because here we
> basically enforce the `old' behavior. we have async printk, but not async
> console output. tweaking console_unlock() to offload the actual printing loop
> to printk_kthread would make the entire console output async:
> 
> 	static void console_sync_flush_and_unlock(void)
> 	{
> 		for (;;) {
> 		...
> 			call_console_drivers();
> 		...
> 		}
> 	}
> 
> 	void console_unlock(void)
> 	{
> 		if (!MOTORMOUTH && can_printk_async()) {
> 			up();
> 			wake_up_process(printk_kthread);
> 			return;
> 		}
> 		console_sync_flush_and_unlock();
> 	}

Something like this would make sense. But I would do it in a separate
patch(set). We need to go through all console_unlock() callers and
make sure that they are fine with the potential async behavior.
I would not complicate the async printk patchset by this.

Best Regards,
Petr

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

#1477109

Hello,

On (09/02/16 17:15), Petr Mladek wrote:
[..]
> > I meant that this thing
> > 
> > 	local_irq_save() // or preempt_disable()
> > 	...
> > 	if (console_trylock())
> > 		console_unlock();
> > 	...
> > 	local_irq_restore() // or preempt_enable()
> 
> I see.
> 
> > can easily lockup the system if console_trylock() was successful and there
> > are enough messages to print. printk_kthread can't help, because here we
> > basically enforce the `old' behavior. we have async printk, but not async
> > console output. tweaking console_unlock() to offload the actual printing loop
> > to printk_kthread would make the entire console output async:
> > 
> > 	static void console_sync_flush_and_unlock(void)
> > 	{
> > 		for (;;) {
> > 		...
> > 			call_console_drivers();
> > 		...
> > 		}
> > 	}
> > 
> > 	void console_unlock(void)
> > 	{
> > 		if (!MOTORMOUTH && can_printk_async()) {
> > 			up();
> > 			wake_up_process(printk_kthread);
> > 			return;
> > 		}
> > 		console_sync_flush_and_unlock();
> > 	}
> 
> Something like this would make sense. But I would do it in a separate
> patch(set). We need to go through all console_unlock() callers and
> make sure that they are fine with the potential async behavior.
> I would not complicate the async printk patchset by this.

sure. just added one more item to the list.

	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web