[PATCH] printk: Correctly handle preemption in console_unlock()

[PATCH] printk: Correctly handle preemption in console_unlock()

[Petr Mladek]

Some console drivers code calls console_conditional_schedule()
that looks at @console_may_schedule. The value must be cleared
when the drivers are called from console_unlock() with
interrupts disabled. But rescheduling is fine when the same
code is called, for example, from tty operations where the
console semaphore is taken via console_lock().

This is why @console_may_schedule is cleared before calling console
drivers. The original value is stored to decide if we could sleep
between lines.

Now, @console_may_schedule is not cleared when we call
console_trylock() and jump back to the "again" goto label.
This has become a problem, since the commit 6b97a20d3a7909daa066
("printk: set may_schedule for some of console_trylock() callers").
@console_may_schedule might get enabled now.

There is also the opposite problem. console_lock() can be called
only from preemptive context. It can always enable scheduling in
the console code. But console_trylock() is not able to detect it
when CONFIG_PREEMPT_COUNT is disabled. Therefore we should use the
original @console_may_schedule value after re-acquiring
the console semaphore in console_unlock().

This patch solves both problems by clearing and restoring the very
original @may_schedule setting only around call_console_drivers().

Reported-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
This is related to the thread
https://lkml.kernel.org/r/201612261954.FJE69201.OFLVtFJSQFOHMO@I-love.SAKURA.ne.jp

 kernel/printk/printk.c | 25 ++++++++++++-------------
 1 file changed, 12 insertions(+), 13 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7180088cbb23..2ac54291230d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2150,7 +2150,7 @@ void console_unlock(void)
 	static u64 seen_seq;
 	unsigned long flags;
 	bool wake_klogd = false;
-	bool do_cond_resched, retry;
+	bool may_schedule_orig, retry;
 
 	if (console_suspended) {
 		up_console_sem();
@@ -2158,17 +2158,15 @@ void console_unlock(void)
 	}
 
 	/*
-	 * Console drivers are called under logbuf_lock, so
-	 * @console_may_schedule should be cleared before; however, we may
-	 * end up dumping a lot of lines, for example, if called from
-	 * console registration path, and should invoke cond_resched()
-	 * between lines if allowable.  Not doing so can cause a very long
-	 * scheduling stall on a slow console leading to RCU stall and
-	 * softlockup warnings which exacerbate the issue with more
-	 * messages practically incapacitating the system.
+	 * Console drivers are called with interrupts disabled, so
+	 * @console_may_schedule must be cleared before. The original
+	 * value must be restored so that we could schedule between lines.
+	 *
+	 * console_trylock() is not able to detect the preemptive context when
+	 * CONFIG_PREEMPT_COUNT is disabled. Therefore the value must be
+	 * stored before the "again" goto label.
 	 */
-	do_cond_resched = console_may_schedule;
-	console_may_schedule = 0;
+	may_schedule_orig = console_may_schedule;
 
 again:
 	/*
@@ -2235,12 +2233,13 @@ void console_unlock(void)
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
+		console_may_schedule = 0;
 		call_console_drivers(ext_text, ext_len, text, len);
+		console_may_schedule = may_schedule_orig;
 		start_critical_timings();
 		printk_safe_exit_irqrestore(flags);
 
-		if (do_cond_resched)
-			cond_resched();
+		console_conditional_schedule();
 	}
 	console_locked = 0;
 
-- 
1.8.5.6

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Steven Rostedt]

On Fri, 13 Jan 2017 14:15:21 +0100
Petr Mladek <pmladek@suse.com> wrote:

> ---
> This is related to the thread
> https://lkml.kernel.org/r/201612261954.FJE69201.OFLVtFJSQFOHMO@I-love.SAKURA.ne.jp
> 
>  kernel/printk/printk.c | 25 ++++++++++++-------------
>  1 file changed, 12 insertions(+), 13 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 7180088cbb23..2ac54291230d 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2150,7 +2150,7 @@ void console_unlock(void)
>  	static u64 seen_seq;
>  	unsigned long flags;
>  	bool wake_klogd = false;
> -	bool do_cond_resched, retry;
> +	bool may_schedule_orig, retry;

<bike-shedding>
 Hmm, I just hate the name of that variable.
 console_may_schedule_orig, keep the full name?
</bike-shedding>

>  
>  	if (console_suspended) {
>  		up_console_sem();
> @@ -2158,17 +2158,15 @@ void console_unlock(void)
>  	}
>  
>  	/*
> -	 * Console drivers are called under logbuf_lock, so
> -	 * @console_may_schedule should be cleared before; however, we may
> -	 * end up dumping a lot of lines, for example, if called from
> -	 * console registration path, and should invoke cond_resched()
> -	 * between lines if allowable.  Not doing so can cause a very long
> -	 * scheduling stall on a slow console leading to RCU stall and
> -	 * softlockup warnings which exacerbate the issue with more
> -	 * messages practically incapacitating the system.
> +	 * Console drivers are called with interrupts disabled, so
> +	 * @console_may_schedule must be cleared before. The original
> +	 * value must be restored so that we could schedule between lines.
> +	 *
> +	 * console_trylock() is not able to detect the preemptive context when
> +	 * CONFIG_PREEMPT_COUNT is disabled. Therefore the value must be
> +	 * stored before the "again" goto label.
>  	 */
> -	do_cond_resched = console_may_schedule;
> -	console_may_schedule = 0;
> +	may_schedule_orig = console_may_schedule;
>  
>  again:
>  	/*
> @@ -2235,12 +2233,13 @@ void console_unlock(void)
>  		raw_spin_unlock(&logbuf_lock);
>  
>  		stop_critical_timings();	/* don't trace print latency */
> +		console_may_schedule = 0;
>  		call_console_drivers(ext_text, ext_len, text, len);
> +		console_may_schedule = may_schedule_orig;
>  		start_critical_timings();
>  		printk_safe_exit_irqrestore(flags);
>  
> -		if (do_cond_resched)
> -			cond_resched();
> +		console_conditional_schedule();

Makes perfect sense to me. The only thing that worries me is that it
does change the logic slightly, and I'm not sure if this will have any
ramifications with it. That is, console_unlock() use to always leave
with console_may_schedule equal to zero, where console_unlock() clears
it. With this change, console_unlock() no longer clears that variable.
Will that have any side effects that we are unaware of?

-- Steve

>  	}
>  	console_locked = 0;
>  

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Petr Mladek]

On Fri 2017-01-13 11:05:42, Steven Rostedt wrote:
> On Fri, 13 Jan 2017 14:15:21 +0100
> Petr Mladek <pmladek@suse.com> wrote:
> 
> > ---
> > This is related to the thread
> > https://lkml.kernel.org/r/201612261954.FJE69201.OFLVtFJSQFOHMO@I-love.SAKURA.ne.jp
> > 
> >  kernel/printk/printk.c | 25 ++++++++++++-------------
> >  1 file changed, 12 insertions(+), 13 deletions(-)
> > 
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 7180088cbb23..2ac54291230d 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2150,7 +2150,7 @@ void console_unlock(void)
> >  	static u64 seen_seq;
> >  	unsigned long flags;
> >  	bool wake_klogd = false;
> > -	bool do_cond_resched, retry;
> > +	bool may_schedule_orig, retry;
> 
> <bike-shedding>
>  Hmm, I just hate the name of that variable.
>  console_may_schedule_orig, keep the full name?
> </bike-shedding>

No problem. I will use the full name in the next iteration
if there will be one.

> >  
> >  	if (console_suspended) {
> >  		up_console_sem();
> > @@ -2158,17 +2158,15 @@ void console_unlock(void)
> >  	}
> >  
> >  	/*
> > -	 * Console drivers are called under logbuf_lock, so
> > -	 * @console_may_schedule should be cleared before; however, we may
> > -	 * end up dumping a lot of lines, for example, if called from
> > -	 * console registration path, and should invoke cond_resched()
> > -	 * between lines if allowable.  Not doing so can cause a very long
> > -	 * scheduling stall on a slow console leading to RCU stall and
> > -	 * softlockup warnings which exacerbate the issue with more
> > -	 * messages practically incapacitating the system.
> > +	 * Console drivers are called with interrupts disabled, so
> > +	 * @console_may_schedule must be cleared before. The original
> > +	 * value must be restored so that we could schedule between lines.
> > +	 *
> > +	 * console_trylock() is not able to detect the preemptive context when
> > +	 * CONFIG_PREEMPT_COUNT is disabled. Therefore the value must be
> > +	 * stored before the "again" goto label.
> >  	 */
> > -	do_cond_resched = console_may_schedule;
> > -	console_may_schedule = 0;
> > +	may_schedule_orig = console_may_schedule;
> >  
> >  again:
> >  	/*
> > @@ -2235,12 +2233,13 @@ void console_unlock(void)
> >  		raw_spin_unlock(&logbuf_lock);
> >  
> >  		stop_critical_timings();	/* don't trace print latency */
> > +		console_may_schedule = 0;
> >  		call_console_drivers(ext_text, ext_len, text, len);
> > +		console_may_schedule = may_schedule_orig;
> >  		start_critical_timings();
> >  		printk_safe_exit_irqrestore(flags);
> >  
> > -		if (do_cond_resched)
> > -			cond_resched();
> > +		console_conditional_schedule();
> 
> Makes perfect sense to me. The only thing that worries me is that it
> does change the logic slightly, and I'm not sure if this will have any
> ramifications with it. That is, console_unlock() use to always leave
> with console_may_schedule equal to zero, where console_unlock() clears
> it. With this change, console_unlock() no longer clears that variable.
> Will that have any side effects that we are unaware of?

Good question!

If I get it correctly, the variable should never be used without the
console semaphore. IMHO, if it was used without the semaphore or if
it was not set correctly when the semaphore was taken, it would be a
bug. It means that leaving the variable set might actually help
to find a buggy usage if there is any.

My findings:

  + console_may_lock is set only by functions that get the console
    semaphore.

  + The function that takes the semaphore and does not set the
    variable is resume_console(). IMHO, it is a bug.

    We are on the safe side because the function is called from
    the same context as suspend_console() and it allows rescheduling.


  + I am not aware of any use of the variable without the
    semaphore. But it is not easy to prove just be reading
    the code.


Best Regards,
Petr

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/16/17 12:00), Petr Mladek wrote:
[..]
> > Makes perfect sense to me. The only thing that worries me is that it
> > does change the logic slightly, and I'm not sure if this will have any
> > ramifications with it. That is, console_unlock() use to always leave
> > with console_may_schedule equal to zero, where console_unlock() clears
> > it. With this change, console_unlock() no longer clears that variable.
> > Will that have any side effects that we are unaware of?
> 
> Good question!

it does look a bit worrisome.

> If I get it correctly, the variable should never be used without the
> console semaphore. IMHO, if it was used without the semaphore or if
> it was not set correctly when the semaphore was taken, it would be a
> bug. It means that leaving the variable set might actually help
> to find a buggy usage if there is any.
> 
> My findings:
> 
>   + console_may_lock is set only by functions that get the console
>     semaphore.
> 
>   + The function that takes the semaphore and does not set the
>     variable is resume_console(). IMHO, it is a bug.
> 
>     We are on the safe side because the function is called from
>     the same context as suspend_console() and it allows rescheduling.
> 
> 
>   + I am not aware of any use of the variable without the
>     semaphore. But it is not easy to prove just be reading
>     the code.

there is a function that clears @console_may_schedule out of
console_sem scope - console_flush_on_panic().
so I *may be* can think about a worst case scenario of race
condition between
	console_flush_on_panic()->console_may_schedule = 0 on panic CPU
and
	console_unlock()->console_may_schedule = 1 from CPU that panic CPU
failed to stop (smp_send_stop() can return with secondary CPUs still being
online).

thoughts?

	-ss

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/18/17 14:45), Sergey Senozhatsky wrote:
[..]
> 
> there is a function that clears @console_may_schedule out of
> console_sem scope - console_flush_on_panic().
> so I *may be* can think about a worst case scenario of race
> condition between
> 	console_flush_on_panic()->console_may_schedule = 0 on panic CPU
> and
> 	console_unlock()->console_may_schedule = 1 from CPU that panic CPU
> failed to stop (smp_send_stop() can return with secondary CPUs still being
> online).

what I mean, is that we can have, let's say, 2 CPUs spinning in
console_unlock(), both with @console_may_schedule == 1 (because secondary
CPU restores global @console_may_schedule value). now, suppose, we have
misbehaving scheduler (well, we are in panic after all). secondary CPU
will cond_resched() and may be lockup somewhere in the scheduler. which is
fine, we don't care about that secondary CPU anyway. but the same can happen
to panic CPU as well.

what do you think?

	-ss

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Petr Mladek]

On Wed 2017-01-18 16:21:41, Sergey Senozhatsky wrote:
> On (01/18/17 14:45), Sergey Senozhatsky wrote:
> [..]
> > 
> > there is a function that clears @console_may_schedule out of
> > console_sem scope - console_flush_on_panic().
> > so I *may be* can think about a worst case scenario of race
> > condition between
> > 	console_flush_on_panic()->console_may_schedule = 0 on panic CPU
> > and
> > 	console_unlock()->console_may_schedule = 1 from CPU that panic CPU
> > failed to stop (smp_send_stop() can return with secondary CPUs still being
> > online).
> 
> what I mean, is that we can have, let's say, 2 CPUs spinning in
> console_unlock(), both with @console_may_schedule == 1 (because secondary
> CPU restores global @console_may_schedule value). now, suppose, we have
> misbehaving scheduler (well, we are in panic after all). secondary CPU
> will cond_resched() and may be lockup somewhere in the scheduler. which is
> fine, we don't care about that secondary CPU anyway. but the same can happen
> to panic CPU as well.
> 
> what do you think?

Great catch!

console_flush_on_panic() is called after smp_send_stop();
so only one CPU should be running. But it is not guaranteed.

Better be on the safe side. I am going to use a conservative
solution that will only move the "again" goto label.


Just some thoughts for a future work:

The dependencies between console_sem, console_may_schedule,
console_locked, and console_suspended are complex like hell.
There are several surprises.

For example, console_trylock() and console_lock() behave differently
when console_suspended is set. console_trylock() completely fails.
console_lock() succeeds but it does not modify console_locked
and console_may_schedule.

This is the reason why we do not need to check console_suspended
after the "again" goto target.


IMHO, the key to make it more straightforward is to split
console flushing functionality from console_unlock().

It is a bit problematic. console_unlock() guarantees that all
messages are flushed when the semaphore is finally released.
IMHO, it might get more relaxed with some deferred techniques.
The deferred handling is perfectly fine most of the time.
In emergency situations, the console_sem is either available
or we rely on console_flush_on_panic() anyway.

Best Regards,
Petr

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/13/17 14:15), Petr Mladek wrote:
> Some console drivers code calls console_conditional_schedule()
> that looks at @console_may_schedule. The value must be cleared
> when the drivers are called from console_unlock() with
> interrupts disabled. But rescheduling is fine when the same
> code is called, for example, from tty operations where the
> console semaphore is taken via console_lock().
> 
> This is why @console_may_schedule is cleared before calling console
> drivers. The original value is stored to decide if we could sleep
> between lines.
> 
> Now, @console_may_schedule is not cleared when we call
> console_trylock() and jump back to the "again" goto label.
> This has become a problem, since the commit 6b97a20d3a7909daa066
> ("printk: set may_schedule for some of console_trylock() callers").

so I think I'd prefer to revert that commit.

the reason I added the commit in question was to reduce the number of
printk() soft lockups that I observed back then. however, it obviously
didn't solve all of the printk() problems. now printk() is moving in a
completely different direction in term of lockups and deadlocks. there
will be no console_trylock() call in vprintk_emit() at all. we will
either do console_lock() from scheduleable printk_kthread or
console_trylock() from IRQ work. so 6b97a20d3a7909daa066 didn't buy us
a lot, and it still doesn't (+ it introduced a bug).


apart from that, Tetsuo wasn't really happy with the patch
http://www.spinics.net/lists/linux-mm/msg103099.html


so let's just return the old behavior back.

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7180088cbb23..ddfbd47398f8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2078,20 +2078,7 @@ int console_trylock(void)
                return 0;
        }
        console_locked = 1;
-       /*
-        * When PREEMPT_COUNT disabled we can't reliably detect if it's
-        * safe to schedule (e.g. calling printk while holding a spin_lock),
-        * because preempt_disable()/preempt_enable() are just barriers there
-        * and preempt_count() is always 0.
-        *
-        * RCU read sections have a separate preemption counter when
-        * PREEMPT_RCU enabled thus we must take extra care and check
-        * rcu_preempt_depth(), otherwise RCU read sections modify
-        * preempt_count().
-        */
-       console_may_schedule = !oops_in_progress &&
-                       preemptible() &&
-                       !rcu_preempt_depth();
+       console_may_schedule = 0;
        return 1;
 }
 EXPORT_SYMBOL(console_trylock);

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Petr Mladek]

On Sat 2017-01-14 15:28:25, Sergey Senozhatsky wrote:
> On (01/13/17 14:15), Petr Mladek wrote:
> > Some console drivers code calls console_conditional_schedule()
> > that looks at @console_may_schedule. The value must be cleared
> > when the drivers are called from console_unlock() with
> > interrupts disabled. But rescheduling is fine when the same
> > code is called, for example, from tty operations where the
> > console semaphore is taken via console_lock().
> > 
> > This is why @console_may_schedule is cleared before calling console
> > drivers. The original value is stored to decide if we could sleep
> > between lines.
> > 
> > Now, @console_may_schedule is not cleared when we call
> > console_trylock() and jump back to the "again" goto label.
> > This has become a problem, since the commit 6b97a20d3a7909daa066
> > ("printk: set may_schedule for some of console_trylock() callers").
> 
> so I think I'd prefer to revert that commit.
> 
> the reason I added the commit in question was to reduce the number of
> printk() soft lockups that I observed back then. however, it obviously
> didn't solve all of the printk() problems.

Interesting idea!

> now printk() is moving in a
> completely different direction in term of lockups and deadlocks. there
> will be no console_trylock() call in vprintk_emit() at all. we will
> either do console_lock() from scheduleable printk_kthread or
> console_trylock() from IRQ work. so 6b97a20d3a7909daa066 didn't buy us
> a lot, and it still doesn't (+ it introduced a bug).

Well, console_trylock() still will be there for the sync mode.
Or do I miss anything?


> apart from that, Tetsuo wasn't really happy with the patch
> http://www.spinics.net/lists/linux-mm/msg103099.html

The complain is questionable. If a code is sensitive for preemption,
it should disable preemption.

Another question is if people expect that printk() would call
cond_resched() or preempt.


> so let's just return the old behavior back.
> 
> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 7180088cbb23..ddfbd47398f8 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2078,20 +2078,7 @@ int console_trylock(void)
>                 return 0;
>         }
>         console_locked = 1;
> -       /*
> -        * When PREEMPT_COUNT disabled we can't reliably detect if it's
> -        * safe to schedule (e.g. calling printk while holding a spin_lock),
> -        * because preempt_disable()/preempt_enable() are just barriers there
> -        * and preempt_count() is always 0.
> -        *
> -        * RCU read sections have a separate preemption counter when
> -        * PREEMPT_RCU enabled thus we must take extra care and check
> -        * rcu_preempt_depth(), otherwise RCU read sections modify
> -        * preempt_count().
> -        */
> -       console_may_schedule = !oops_in_progress &&
> -                       preemptible() &&
> -                       !rcu_preempt_depth();
> +       console_may_schedule = 0;
>         return 1;
>  }
>  EXPORT_SYMBOL(console_trylock);

This would revert the change only for non-preemptive kernel.

The commit 6b97a20d3a7909daa06625 ("printk: set may_schedule for some
of console_trylock() callers" also enabled preemption which still
affects preemtible kernel.

Do we want to behave differently in preemptive and non-preemtive
kernel?

Best Regards,
Petr

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/16/17 12:38), Petr Mladek wrote:
[..]
> > > Now, @console_may_schedule is not cleared when we call
> > > console_trylock() and jump back to the "again" goto label.
> > > This has become a problem, since the commit 6b97a20d3a7909daa066
> > > ("printk: set may_schedule for some of console_trylock() callers").
> > 
> > so I think I'd prefer to revert that commit.
> > 
> > the reason I added the commit in question was to reduce the number of
> > printk() soft lockups that I observed back then. however, it obviously
> > didn't solve all of the printk() problems.
> 
> Interesting idea!
> 
> > now printk() is moving in a
> > completely different direction in term of lockups and deadlocks. there
> > will be no console_trylock() call in vprintk_emit() at all. we will
> > either do console_lock() from scheduleable printk_kthread or
> > console_trylock() from IRQ work. so 6b97a20d3a7909daa066 didn't buy us
> > a lot, and it still doesn't (+ it introduced a bug).
> 
> Well, console_trylock() still will be there for the sync mode.
> Or do I miss anything?

you mean in console_unlock()? there we inherit may_schedule from the
original console_sem lock path, which sould be console_lock() in async
printk case (IOW, preemptible).

other then that - from printk POV, I don't think we will care that much.
anything that directly calls console_lock()/console_trylock will be doing
console_unlock(). those paths are not addressed by async printk anyway.
I have some plans on addressing it, as you know, but that's a later work.

so let's return good ol' bhaviour:
-- console_trylock is always "no resched"
-- console_lock is always "enable resched" (regardless of
   console_trylock calls from console_unlock()).


> > apart from that, Tetsuo wasn't really happy with the patch
> > http://www.spinics.net/lists/linux-mm/msg103099.html
> 
> The complain is questionable. If a code is sensitive for preemption,
> it should disable preemption.
>
> Another question is if people expect that printk() would call
> cond_resched() or preempt.

my assumption would be that probably people expect printk to work
asap.


[..]
> This would revert the change only for non-preemptive kernel.
> 
> The commit 6b97a20d3a7909daa06625 ("printk: set may_schedule for some
> of console_trylock() callers" also enabled preemption which still
> affects preemtible kernel.
> 
> Do we want to behave differently in preemptive and non-preemtive
> kernel?

not sure I'm following here. in non-preemptible kernels console_trylock()
always sets console_may_schedule to 0, just like it did before. in
preemptible kernels we now will also set console_may_schedule to 0.
just like before.


in any case, we return back the old behavior. there should be no issues (tm)

	-ss

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Petr Mladek]

On Mon 2017-01-16 20:58:44, Sergey Senozhatsky wrote:
> On (01/16/17 12:38), Petr Mladek wrote:
> [..]
> > > > Now, @console_may_schedule is not cleared when we call
> > > > console_trylock() and jump back to the "again" goto label.
> > > > This has become a problem, since the commit 6b97a20d3a7909daa066
> > > > ("printk: set may_schedule for some of console_trylock() callers").
> > > 
> > > so I think I'd prefer to revert that commit.
> > > 
> > > the reason I added the commit in question was to reduce the number of
> > > printk() soft lockups that I observed back then. however, it obviously
> > > didn't solve all of the printk() problems.
> > 
> > Interesting idea!
> > 
> > > now printk() is moving in a
> > > completely different direction in term of lockups and deadlocks. there
> > > will be no console_trylock() call in vprintk_emit() at all. we will
> > > either do console_lock() from scheduleable printk_kthread or
> > > console_trylock() from IRQ work. so 6b97a20d3a7909daa066 didn't buy us
> > > a lot, and it still doesn't (+ it introduced a bug).
> > 
> > Well, console_trylock() still will be there for the sync mode.
> > Or do I miss anything?
> 
> you mean in console_unlock()? there we inherit may_schedule from the
> original console_sem lock path, which sould be console_lock() in async
> printk case (IOW, preemptible).

The async printk code looks like this:

vprintk_emit(...)
{


		if (can_printk_async()) {
			/* Offload printing to a schedulable context. */
			printk_kthread_need_flush_console = true;
			wake_up_process(printk_kthread);
		} else {
			/*
			 * Try to acquire and then immediately release the
			 * console semaphore.  The release will print out
			 * buffers and wake up /dev/kmsg and syslog() users.
			 */
			if (console_trylock())
				console_unlock();
		}

So, there is still the console_trylock() for the sync mode. Or do I
see an outdated variant?


> other then that - from printk POV, I don't think we will care that much.
> anything that directly calls console_lock()/console_trylock will be doing
> console_unlock(). those paths are not addressed by async printk anyway.
> I have some plans on addressing it, as you know, but that's a later work.
> 
> so let's return good ol' bhaviour:
> -- console_trylock is always "no resched"

Then you would need to revert the entire commit 6b97a20d3a7909daa06625
("printk: set may_schedule for some of console_trylock() callers")
to disable preemption also in preemptive kernel.



> -- console_lock is always "enable resched" (regardless of
>    console_trylock calls from console_unlock()).

This was always broken. If we want to fix this, we need
some variant of my patch.


> > > apart from that, Tetsuo wasn't really happy with the patch
> > > http://www.spinics.net/lists/linux-mm/msg103099.html
> > 
> > The complain is questionable. If a code is sensitive for preemption,
> > it should disable preemption.
> >
> > Another question is if people expect that printk() would call
> > cond_resched() or preempt.
> 
> my assumption would be that probably people expect printk to work
> asap.

Sure. But this will be solved by the async mode. If people force
sync mode there always will be a risk that printk() might take long.

IMHO, if a code takes a long time and it is called in preemtible
context it should get preempted. => We should keep that cond_resched()
and allow to call it for the synchronous mode.


> [..]
> > This would revert the change only for non-preemptive kernel.
> > 
> > The commit 6b97a20d3a7909daa06625 ("printk: set may_schedule for some
> > of console_trylock() callers" also enabled preemption which still
> > affects preemtible kernel.
> > 
> > Do we want to behave differently in preemptive and non-preemtive
> > kernel?
> 
> not sure I'm following here. in non-preemptible kernels console_trylock()
> always sets console_may_schedule to 0, just like it did before.

No, if CONFIG_PREEMPT_COUNT is enabled then we are able to detect
preemtible context even on non-preemtible kernel. Then

	console_may_schedule = !oops_in_progress &&
			preemptible() &&
			!rcu_preempt_depth();

might eventually allow scheduling.


> preemptible kernels we now will also set console_may_schedule to 0.
> just like before.

Only, the following part of the commit 6b97a20d3a7909d was important for
preemtible kernel:

@@ -1758,20 +1758,12 @@ asmlinkage int vprintk_emit(int facility, int level,
        if (!in_sched) {
                lockdep_off();
                /*
-                * Disable preemption to avoid being preempted while holding
-                * console_sem which would prevent anyone from printing to
-                * console
-                */
-               preempt_disable();
-
-               /*
                 * Try to acquire and then immediately release the console
                 * semaphore.  The release will print out buffers and wake up
                 * /dev/kmsg and syslog() users.
                 */
                if (console_trylock())
                        console_unlock();
-               preempt_enable();
                lockdep_on();
        }


Note that cond_resched() is a non-op in preemtible kernel. See the
following code is in current Linus' tree in include/linux/sched.h:

#ifndef CONFIG_PREEMPT
extern int _cond_resched(void);
#else
static inline int _cond_resched(void) { return 0; }
#endif

It makes perfect sense. The following code is needed for
non-preemtible kernel:

	local_irq_restore(flags);
	cond_resched()

but the following code does the same job in preemtible kernel:

	local_irq_restore(flags);

If there is a pending interrupt/timer that would cause preemption
in preemtible kernel, it will happen immediately when interrupts
are enabled. We do not need to call cond_resched() for this.
Also if the interrupt/timers is not pending, it does not make
sense to call cond_resched() because the time for the task
has not elapsed yet.


My proposal:

1. Keep the commit 6b97a20d3a7909d as is. As I wrote above. If
   a function takes a long and it is called in preemtible context,
   it should preempt.

   The fact that printk() might take long is bad. But this will
   get solved by async mode. The cond_resched still makes sense in
   sync mode.


2. Fix clearing/storing console_might_schedule in console_unlock().
   It makes sense for keeping the setting from console_lock() even
   if console_trylock() always set 0.


Best Regards,
Petr

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/16/17 13:48), Petr Mladek wrote:
[..]
> The async printk code looks like this:
> 
> vprintk_emit(...)
> {
> 
> 
> 		if (can_printk_async()) {
> 			/* Offload printing to a schedulable context. */
> 			printk_kthread_need_flush_console = true;
> 			wake_up_process(printk_kthread);
> 		} else {
> 			/*
> 			 * Try to acquire and then immediately release the
> 			 * console semaphore.  The release will print out
> 			 * buffers and wake up /dev/kmsg and syslog() users.
> 			 */
> 			if (console_trylock())
> 				console_unlock();
> 		}
> 
> So, there is still the console_trylock() for the sync mode. Or do I
> see an outdated variant?

no, it doesn't.

ASYNC printk looks like a wake_up of printk_kthread from deferred
printk handler. and printk_kthread does a while-loop, calling
console_lock() and doing console_unlock().

SYNC printk mode is also handled in deferred printk callback and
does console_trylock()/console_unlock().


> > other then that - from printk POV, I don't think we will care that much.
> > anything that directly calls console_lock()/console_trylock will be doing
> > console_unlock(). those paths are not addressed by async printk anyway.
> > I have some plans on addressing it, as you know, but that's a later work.
> > 
> > so let's return good ol' bhaviour:
> > -- console_trylock is always "no resched"
> 
> Then you would need to revert the entire commit 6b97a20d3a7909daa06625
> ("printk: set may_schedule for some of console_trylock() callers")
> to disable preemption also in preemptive kernel.

we check can_use_console() in console_unlock(), with console_sem acquired.
it's not like the CPU will suddenly go offline from under us.

> > -- console_lock is always "enable resched" (regardless of
> >    console_trylock calls from console_unlock()).
> 
> This was always broken. If we want to fix this, we need
> some variant of my patch.

you mean the "console_trylock calls from console_unlock()" part.
well, may be. it sort of works for me. we safe may_schedule from
the original context and then don't care about console_trylock().

it's a bit fragile, though. took me 1 year to find out that I
accidentally broke it.


[..]
> > not sure I'm following here. in non-preemptible kernels console_trylock()
> > always sets console_may_schedule to 0, just like it did before.
> 
> No, if CONFIG_PREEMPT_COUNT is enabled then we are able to detect
> preemtible context even on non-preemtible kernel. Then
> 
> 	console_may_schedule = !oops_in_progress &&
> 			preemptible() &&
> 			!rcu_preempt_depth();
> 
> might eventually allow scheduling.

yes. well, that was the idea behind those lines. the question is - do we
really need it after all? given that there won't be console_trylock() in
printk path any more. my call -- we probably don't need it. thus I'm
proposing to return back console_trylock() we used to have.

> My proposal:
> 
> 1. Keep the commit 6b97a20d3a7909d as is. As I wrote above. If
>    a function takes a long and it is called in preemtible context,
>    it should preempt.
> 
>    The fact that printk() might take long is bad. But this will
>    get solved by async mode. The cond_resched still makes sense in
>    sync mode.
>
> 
> 2. Fix clearing/storing console_might_schedule in console_unlock().
>    It makes sense for keeping the setting from console_lock() even
>    if console_trylock() always set 0.

well, we can add that *_orig/etc, but is it really worth it?
console_trylock() won't be used that often. not in printk at
least.

	-ss

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/16/17 22:26), Sergey Senozhatsky wrote:
> On (01/16/17 13:48), Petr Mladek wrote:
> [..]
> > The async printk code looks like this:
> > 
> > vprintk_emit(...)
> > {
> > 
> > 
> > 		if (can_printk_async()) {
> > 			/* Offload printing to a schedulable context. */
> > 			printk_kthread_need_flush_console = true;
> > 			wake_up_process(printk_kthread);
> > 		} else {
> > 			/*
> > 			 * Try to acquire and then immediately release the
> > 			 * console semaphore.  The release will print out
> > 			 * buffers and wake up /dev/kmsg and syslog() users.
> > 			 */
> > 			if (console_trylock())
> > 				console_unlock();
> > 		}
> > 
> > So, there is still the console_trylock() for the sync mode. Or do I
> > see an outdated variant?
> 
> no, it doesn't.

I meant that none of this is happening in vprintk_emit(). there is no
console_sem in vprintk_emit() at all. eveything is done in deferred printk.

	-ss

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Petr Mladek]

On Mon 2017-01-16 22:26:33, Sergey Senozhatsky wrote:
> On (01/16/17 13:48), Petr Mladek wrote:
> [..]
> > The async printk code looks like this:
> > 
> > vprintk_emit(...)
> > {
> > 
> > 
> > 		if (can_printk_async()) {
> > 			/* Offload printing to a schedulable context. */
> > 			printk_kthread_need_flush_console = true;
> > 			wake_up_process(printk_kthread);
> > 		} else {
> > 			/*
> > 			 * Try to acquire and then immediately release the
> > 			 * console semaphore.  The release will print out
> > 			 * buffers and wake up /dev/kmsg and syslog() users.
> > 			 */
> > 			if (console_trylock())
> > 				console_unlock();
> > 		}
> > 
> > So, there is still the console_trylock() for the sync mode. Or do I
> > see an outdated variant?
> 
> no, it doesn't.
> 
> ASYNC printk looks like a wake_up of printk_kthread from deferred
> printk handler. and printk_kthread does a while-loop, calling
> console_lock() and doing console_unlock().

Yup.

> SYNC printk mode is also handled in deferred printk callback and
> does console_trylock()/console_unlock().

I am confused by the sentence.

If it is a synchronous mode then console_trylock()/console_unlock() must
be called directly from printk()/vprintk_emit().

If you move this to a deferred callback, it is not longer synchronous.


> > > other then that - from printk POV, I don't think we will care that much.
> > > anything that directly calls console_lock()/console_trylock will be doing
> > > console_unlock(). those paths are not addressed by async printk anyway.
> > > I have some plans on addressing it, as you know, but that's a later work.
> > > 
> > > so let's return good ol' bhaviour:
> > > -- console_trylock is always "no resched"
> > 
> > Then you would need to revert the entire commit 6b97a20d3a7909daa06625
> > ("printk: set may_schedule for some of console_trylock() callers")
> > to disable preemption also in preemptive kernel.
> 
> we check can_use_console() in console_unlock(), with console_sem acquired.
> it's not like the CPU will suddenly go offline from under us.

I am not sure how this is related to the above. It talked about
the "no resched" behavior.

If you want to avoid preemtion in preemtible kernel, you need to
disable preemtion.

If you want to avoid preemtion in non-preemtible kernel, it is
enough to do _not_ call cond_resched()/schedule().

Your mail
https://lkml.kernel.org/r/20170114062825.GB699@tigerII.localdomain
suggested to avoid calling cond_resched(). This reverted the
original behavior only for non-preemtible kernel.

If we wanted to restore the original behavior also for preemtible
kernel, we would need to disable preemtion around console_trylock/
console_unlock() calls again.


> > > -- console_lock is always "enable resched" (regardless of
> > >    console_trylock calls from console_unlock()).
> > 
> > This was always broken. If we want to fix this, we need
> > some variant of my patch.
> 
> you mean the "console_trylock calls from console_unlock()" part.
> well, may be. it sort of works for me. we safe may_schedule from
> the original context and then don't care about console_trylock().
> 
> it's a bit fragile, though. took me 1 year to find out that I
> accidentally broke it.

That only means that the problem is a corner case. Note that Tetsuo
found it by some stress test that puts the machine beyond usability.

I personally think that the enabled preemtion and automatic detection
of the context makes perfect sense.

[...]

> > My proposal:
> > 
> > 1. Keep the commit 6b97a20d3a7909d as is. As I wrote above. If
> >    a function takes a long and it is called in preemtible context,
> >    it should preempt.
> > 
> >    The fact that printk() might take long is bad. But this will
> >    get solved by async mode. The cond_resched still makes sense in
> >    sync mode.
> >
> > 
> > 2. Fix clearing/storing console_might_schedule in console_unlock().
> >    It makes sense for keeping the setting from console_lock() even
> >    if console_trylock() always set 0.
> 
> well, we can add that *_orig/etc, but is it really worth it?
> console_trylock() won't be used that often. not in printk at
> least.

IMHO, it is worth it because both patches go into the right direction.

Your commit allows to preemt a potentially long call in preemtible
context. It makes perfect sense. And it will be usable in the sync mode.

My patch is needed if we keep your commit and I vote for it.
Also it might safe someone a time in the future if he wanted
to solve the prepemtion again. Note how much effort it took
us to understand the side effects and the
console_trylock()/goto-again influence.

Best Regards,
Petr

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/16/17 15:14), Petr Mladek wrote:
[..]
> > SYNC printk mode is also handled in deferred printk callback and
> > does console_trylock()/console_unlock().
> 
> I am confused by the sentence.
> 
> If it is a synchronous mode then console_trylock()/console_unlock() must
> be called directly from printk()/vprintk_emit().
> 
> If you move this to a deferred callback, it is not longer synchronous.

yes, everything is about to move to the deferred printk() handler.
it has been discussed during the LPC/KS session. Linus proposed it,
to be exact. and I was quite sure that everyone in the room,
including you, agreed. we either do everything asking scheduled for
help (wake_up()), which is async printk. or do the print out from
deferred printk() handler /** 1) in case of panic() there is a
console_flush_on_panic() call. 2) once the system stores at least
one EMERG loglevel message, we don't wake_up() printk_kthread from
deferred printk handler.  **/

but, well, probably this is not related to this thread.


> it is not longer synchronous.

well, a silly and boring note is that there is nothing that guarantees
or provides 'synchronous' printk(). console_sem simply can be locked
and printk() will just log_store(), while the actual printing will
happen sometime later (if ever) from whatever context that held the
console_sem. can be IRQ or anything else.

*may be* we need a new 'terminology' here. 'sync printk' does
not reflect the actual behavior and can give false expectations.
just a note.

> > > Then you would need to revert the entire commit 6b97a20d3a7909daa06625
> > > ("printk: set may_schedule for some of console_trylock() callers")
> > > to disable preemption also in preemptive kernel.
> > 
> > we check can_use_console() in console_unlock(), with console_sem acquired.
> > it's not like the CPU will suddenly go offline from under us.
> 
> I am not sure how this is related to the above. It talked about
> the "no resched" behavior.
> 
> If you want to avoid preemtion in preemtible kernel, you need to
> disable preemtion.
>
> If you want to avoid preemtion in non-preemtible kernel, it is
> enough to do _not_ call cond_resched()/schedule().
[..]
> Your mail
> https://lkml.kernel.org/r/20170114062825.GB699@tigerII.localdomain
> suggested to avoid calling cond_resched(). This reverted the
> original behavior only for non-preemtible kernel.
> If we wanted to restore the original behavior also for preemtible
> kernel, we would need to disable preemtion around console_trylock/
> console_unlock() calls again.

ah, ok. the code there is not even a patch. so yes, could be
incomplete/wrong "revert".

[..]
> > well, we can add that *_orig/etc, but is it really worth it?
> > console_trylock() won't be used that often. not in printk at
> > least.
> 
> IMHO, it is worth it because both patches go into the right direction.

well, ok. if you insist :)

	-ss

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Sergey Senozhatsky]

On (01/17/17 00:19), Sergey Senozhatsky wrote:
[..]
> > I am confused by the sentence.
> > 
> > If it is a synchronous mode then console_trylock()/console_unlock() must
> > be called directly from printk()/vprintk_emit().
> > 
> > If you move this to a deferred callback, it is not longer synchronous.
> 
> yes, everything is about to move to the deferred printk() handler.
> it has been discussed during the LPC/KS session. Linus proposed it,
> to be exact. and I was quite sure that everyone in the room,
> including you, agreed. we either do everything asking scheduled for
> help (wake_up()), which is async printk. or do the print out from
> deferred printk() handler /** 1) in case of panic() there is a
> console_flush_on_panic() call. 2) once the system stores at least
> one EMERG loglevel message, we don't wake_up() printk_kthread from
> deferred printk handler.  **/

gosh.. sorry. I need some rest. badly. the above is not completely
accurate. "make printk always behave like printk deferred" was in
my presentation and proposal. the difference was in EMERG loglevel
handling. Linus suggested to handle it in deferred printk handler
as well, while I initially wanted to handle EMERG messages in
vprintk_emit() as a special case/exception. but I like the idea of
doing everything in printk deferred handler better. printk is moving
there anyway. otherwise there is no way of resolving printk deadlocks
on "external" locks.

	-ss

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Petr Mladek]

On Tue 2017-01-17 00:43:43, Sergey Senozhatsky wrote:
> On (01/17/17 00:19), Sergey Senozhatsky wrote:
> [..]
> > > I am confused by the sentence.
> > > 
> > > If it is a synchronous mode then console_trylock()/console_unlock() must
> > > be called directly from printk()/vprintk_emit().
> > > 
> > > If you move this to a deferred callback, it is not longer synchronous.
> > 
> > yes, everything is about to move to the deferred printk() handler.
> > it has been discussed during the LPC/KS session. Linus proposed it,
> > to be exact. and I was quite sure that everyone in the room,
> > including you, agreed. we either do everything asking scheduled for
> > help (wake_up()), which is async printk. or do the print out from
> > deferred printk() handler /** 1) in case of panic() there is a
> > console_flush_on_panic() call. 2) once the system stores at least
> > one EMERG loglevel message, we don't wake_up() printk_kthread from
> > deferred printk handler.  **/
> 
> gosh.. sorry. I need some rest. badly. the above is not completely
> accurate. "make printk always behave like printk deferred" was in
> my presentation and proposal. the difference was in EMERG loglevel
> handling. Linus suggested to handle it in deferred printk handler
> as well, while I initially wanted to handle EMERG messages in
> vprintk_emit() as a special case/exception. but I like the idea of
> doing everything in printk deferred handler better. printk is moving
> there anyway. otherwise there is no way of resolving printk deadlocks
> on "external" locks.

Yes, this is the direction. But I can not imagine to do all this in one
big step. It is even possible that it will simply not work. Just remember
the problems with suspend, sysrq, kexec.

There are more paths where we need to make sure that the messages
are flushed. And we must not rely only on deferred solutions (IRQ,
kthread) because they simply need not happen.

My expectation is that we will keep the sync mode as it is now for
some (long time). And we will do more and more deferring in the
async mode step by step. If the async mode proves to be perfectly
usable and people do not need the sync mode any longer, we could
remove the sync mode but only then.

By other words, I expect that we would first push a solution similar
to v12. It was tested for years in SUSE. Any bigger changes
would just cause another huge delay.

I am sorry but I am not a crazy jumper. The async printk idea was
blocked for years. We should not go into the other extreme now.

Best Regards,
Petr

Re: [PATCH] printk: Correctly handle preemption in console_unlock()

[Tetsuo Handa]

Sergey Senozhatsky wrote:
> On (01/16/17 12:38), Petr Mladek wrote:
> > > apart from that, Tetsuo wasn't really happy with the patch
> > > http://www.spinics.net/lists/linux-mm/msg103099.html
> > 
> > The complain is questionable. If a code is sensitive for preemption,
> > it should disable preemption.
> >
> > Another question is if people expect that printk() would call
> > cond_resched() or preempt.
> 
> my assumption would be that probably people expect printk to work
> asap.

The code executed with oom_lock held is sensitive for preemption. I tried
to disable preemption, but it was not accepted. What is so sorry is that
this is not really a problem of printk() because sleeping for minutes
(presumably forever) with oom_lock held is triggerable without printk().
It is a problem of memory page allocator which consumes a lot of CPU time
for pointless direct reclaim rather than giving CPU time to a thread which
held the oom_lock. I tried to wait for oom_lock in order to give CPU time
to the thread holding the oom_lock, but it was not accepted neither.