* Re: + printk-do-cond_resched-between-lines-while-outputting-to-consoles.patch added to -mm tree
[not found] <565f855a./bN6NB3bZKjpF4Wa%akpm@linux-foundation.org>
@ 2015-12-03 1:11 ` Sergey Senozhatsky
2015-12-03 2:39 ` Sergey Senozhatsky
0 siblings, 1 reply; 4+ messages in thread
From: Sergey Senozhatsky @ 2015-12-03 1:11 UTC (permalink / raw)
To: tj; +Cc: akpm, calvinowens, davej, jack, kyle, stable, mm-commits, linux-kernel
Hello,
On (12/02/15 15:57), akpm@linux-foundation.org wrote:
[..]
> @console_may_schedule tracks whether console_sem was acquired through lock
> or trylock. If the former, we're inside a sleepable context and
> console_conditional_schedule() performs cond_resched(). This allows
> console drivers which use console_lock for synchronization to yield while
> performing time-consuming operations such as scrolling.
>
> However, the actual console outputting is performed while holding irq-safe
> logbuf_lock, so console_unlock() clears @console_may_schedule before
> starting outputting lines. Also, only a few drivers call
> console_conditional_schedule() to begin with. This means that when a lot
> of lines need to be output by console_unlock(), for example on a console
> registration, the task doing console_unlock() may not yield for a long
> time on a non-preemptible kernel.
>
> If this happens with a slow console devices, for example a serial console,
> the outputting task may occupy the cpu for a very long time. Long enough
> to trigger softlockup and/or RCU stall warnings, which in turn pile more
> messages, sometimes enough to trigger the next cycle of warnings
> incapacitating the system.
>
> Fix it by making console_unlock() insert cond_resched() between lines if
> @console_may_schedule.
CPU2 still can cause lots of troubles. consider
CPU0 CPU1 CPU2
printk
... printk_deferred
printk wake_up_klogd
wake_up_klogd_work_func
console_trylock
console_unlock
printk_deferred() may be issued by scheduler, for example.
-ss
> Signed-off-by: Tejun Heo <tj@kernel.org>
> Reported-by: Calvin Owens <calvinowens@fb.com>
> Acked-by: Jan Kara <jack@suse.com>
> Cc: Dave Jones <davej@codemonkey.org.uk>
> Cc: Kyle McMartin <kyle@kernel.org>
> Cc: <stable@vger.kernel.org>
> Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
> ---
>
> kernel/printk/printk.c | 16 +++++++++++++++-
> 1 file changed, 15 insertions(+), 1 deletion(-)
>
> diff -puN kernel/printk/printk.c~printk-do-cond_resched-between-lines-while-outputting-to-consoles kernel/printk/printk.c
> --- a/kernel/printk/printk.c~printk-do-cond_resched-between-lines-while-outputting-to-consoles
> +++ a/kernel/printk/printk.c
> @@ -2234,13 +2234,24 @@ void console_unlock(void)
> static u64 seen_seq;
> unsigned long flags;
> bool wake_klogd = false;
> - bool retry;
> + bool do_cond_resched, retry;
>
> if (console_suspended) {
> up_console_sem();
> return;
> }
>
> + /*
> + * 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.
> + */
> + do_cond_resched = console_may_schedule;
> console_may_schedule = 0;
>
> /* flush buffered message fragment immediately to console */
> @@ -2312,6 +2323,9 @@ skip:
> call_console_drivers(level, ext_text, ext_len, text, len);
> start_critical_timings();
> local_irq_restore(flags);
> +
> + if (do_cond_resched)
> + cond_resched();
> }
> console_locked = 0;
>
> _
>
> Patches currently in -mm which might be from tj@kernel.org are
>
> printk-do-cond_resched-between-lines-while-outputting-to-consoles.patch
>
> --
> To unsubscribe from this list: send the line "unsubscribe mm-commits" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: + printk-do-cond_resched-between-lines-while-outputting-to-consoles.patch added to -mm tree
2015-12-03 1:11 ` + printk-do-cond_resched-between-lines-while-outputting-to-consoles.patch added to -mm tree Sergey Senozhatsky
@ 2015-12-03 2:39 ` Sergey Senozhatsky
2015-12-03 9:57 ` Jan Kara
0 siblings, 1 reply; 4+ messages in thread
From: Sergey Senozhatsky @ 2015-12-03 2:39 UTC (permalink / raw)
To: sergey.senozhatsky.work
Cc: tj, akpm, calvinowens, davej, jack, kyle, stable, mm-commits,
linux-kernel
On (12/03/15 10:11), Sergey Senozhatsky wrote:
> On (12/02/15 15:57), akpm@linux-foundation.org wrote:
> [..]
> > @console_may_schedule tracks whether console_sem was acquired through lock
> > or trylock. If the former, we're inside a sleepable context and
> > console_conditional_schedule() performs cond_resched(). This allows
> > console drivers which use console_lock for synchronization to yield while
> > performing time-consuming operations such as scrolling.
> >
> > However, the actual console outputting is performed while holding irq-safe
> > logbuf_lock, so console_unlock() clears @console_may_schedule before
> > starting outputting lines. Also, only a few drivers call
> > console_conditional_schedule() to begin with. This means that when a lot
> > of lines need to be output by console_unlock(), for example on a console
> > registration, the task doing console_unlock() may not yield for a long
> > time on a non-preemptible kernel.
> >
> > If this happens with a slow console devices, for example a serial console,
> > the outputting task may occupy the cpu for a very long time. Long enough
> > to trigger softlockup and/or RCU stall warnings, which in turn pile more
> > messages, sometimes enough to trigger the next cycle of warnings
> > incapacitating the system.
> >
> > Fix it by making console_unlock() insert cond_resched() between lines if
> > @console_may_schedule.
>
> CPU2 still can cause lots of troubles. consider
>
> CPU0 CPU1 CPU2
> printk
> ... printk_deferred
> printk wake_up_klogd
> wake_up_klogd_work_func
> console_trylock
> console_unlock
>
> printk_deferred() may be issued by scheduler, for example.
IOW, may be we can start limiting the number of bytes printed in console_unlock()
from irq contexts. Which is quite ugly, yes. We basically don't know how much time
we spend in call_console_drivers(); some of the consoles can do 'internal' spin_lock
loops in ->write() handlers, etc. So something like this (below) probably will not
really help, but still it's not always OK to do `while (1)' loop in console_unlock()
for irqs.
-ss
(not even compile tested)
---
kernel/printk/printk.c | 6 +++++-
1 file changed, 5 insertions(+), 1 deletion(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9da39e7..221a230 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2235,6 +2235,7 @@ void console_unlock(void)
unsigned long flags;
bool wake_klogd = false;
bool do_cond_resched, retry;
+ int printed, irq_count = irq_count();
if (console_suspended) {
up_console_sem();
@@ -2257,6 +2258,7 @@ void console_unlock(void)
/* flush buffered message fragment immediately to console */
console_cont_flush(text, sizeof(text));
again:
+ printed = 0;
for (;;) {
struct printk_log *msg;
size_t ext_len = 0;
@@ -2326,6 +2328,8 @@ skip:
if (do_cond_resched)
cond_resched();
+ if (irq_count && printed > LOG_LINE_MAX)
+ break;
}
console_locked = 0;
@@ -2344,7 +2348,7 @@ skip:
* flush, no worries.
*/
raw_spin_lock(&logbuf_lock);
- retry = console_seq != log_next_seq;
+ retry = (console_seq != log_next_seq) && !!irq_count;
raw_spin_unlock_irqrestore(&logbuf_lock, flags);
if (retry && console_trylock())
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: + printk-do-cond_resched-between-lines-while-outputting-to-consoles.patch added to -mm tree
2015-12-03 2:39 ` Sergey Senozhatsky
@ 2015-12-03 9:57 ` Jan Kara
2015-12-04 0:29 ` Sergey Senozhatsky
0 siblings, 1 reply; 4+ messages in thread
From: Jan Kara @ 2015-12-03 9:57 UTC (permalink / raw)
To: Sergey Senozhatsky
Cc: tj, akpm, calvinowens, davej, jack, kyle, stable, mm-commits,
linux-kernel
On Thu 03-12-15 11:39:33, Sergey Senozhatsky wrote:
> On (12/03/15 10:11), Sergey Senozhatsky wrote:
> > On (12/02/15 15:57), akpm@linux-foundation.org wrote:
> > [..]
> > > @console_may_schedule tracks whether console_sem was acquired through lock
> > > or trylock. If the former, we're inside a sleepable context and
> > > console_conditional_schedule() performs cond_resched(). This allows
> > > console drivers which use console_lock for synchronization to yield while
> > > performing time-consuming operations such as scrolling.
> > >
> > > However, the actual console outputting is performed while holding irq-safe
> > > logbuf_lock, so console_unlock() clears @console_may_schedule before
> > > starting outputting lines. Also, only a few drivers call
> > > console_conditional_schedule() to begin with. This means that when a lot
> > > of lines need to be output by console_unlock(), for example on a console
> > > registration, the task doing console_unlock() may not yield for a long
> > > time on a non-preemptible kernel.
> > >
> > > If this happens with a slow console devices, for example a serial console,
> > > the outputting task may occupy the cpu for a very long time. Long enough
> > > to trigger softlockup and/or RCU stall warnings, which in turn pile more
> > > messages, sometimes enough to trigger the next cycle of warnings
> > > incapacitating the system.
> > >
> > > Fix it by making console_unlock() insert cond_resched() between lines if
> > > @console_may_schedule.
> >
> > CPU2 still can cause lots of troubles. consider
> >
> > CPU0 CPU1 CPU2
> > printk
> > ... printk_deferred
> > printk wake_up_klogd
> > wake_up_klogd_work_func
> > console_trylock
> > console_unlock
> >
> > printk_deferred() may be issued by scheduler, for example.
>
> IOW, may be we can start limiting the number of bytes printed in console_unlock()
> from irq contexts. Which is quite ugly, yes. We basically don't know how much time
> we spend in call_console_drivers(); some of the consoles can do 'internal' spin_lock
> loops in ->write() handlers, etc. So something like this (below) probably will not
> really help, but still it's not always OK to do `while (1)' loop in console_unlock()
> for irqs.
What we really want is pushing the printing into async context (unless
forced by debug option or oops in progress). Because what you do here fixes
only a small fraction of the problem space. I have patches which fix more
of it (https://lkml.org/lkml/2015/10/26/16) but they are still not enough
because on large machines e.g. udev times out because printing messages
about inserted hardware over serial console just takes too long.
Honza
>
> ---
>
> kernel/printk/printk.c | 6 +++++-
> 1 file changed, 5 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 9da39e7..221a230 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2235,6 +2235,7 @@ void console_unlock(void)
> unsigned long flags;
> bool wake_klogd = false;
> bool do_cond_resched, retry;
> + int printed, irq_count = irq_count();
>
> if (console_suspended) {
> up_console_sem();
> @@ -2257,6 +2258,7 @@ void console_unlock(void)
> /* flush buffered message fragment immediately to console */
> console_cont_flush(text, sizeof(text));
> again:
> + printed = 0;
> for (;;) {
> struct printk_log *msg;
> size_t ext_len = 0;
> @@ -2326,6 +2328,8 @@ skip:
>
> if (do_cond_resched)
> cond_resched();
> + if (irq_count && printed > LOG_LINE_MAX)
> + break;
> }
> console_locked = 0;
>
> @@ -2344,7 +2348,7 @@ skip:
> * flush, no worries.
> */
> raw_spin_lock(&logbuf_lock);
> - retry = console_seq != log_next_seq;
> + retry = (console_seq != log_next_seq) && !!irq_count;
> raw_spin_unlock_irqrestore(&logbuf_lock, flags);
>
> if (retry && console_trylock())
>
>
--
Jan Kara <jack@suse.com>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: + printk-do-cond_resched-between-lines-while-outputting-to-consoles.patch added to -mm tree
2015-12-03 9:57 ` Jan Kara
@ 2015-12-04 0:29 ` Sergey Senozhatsky
0 siblings, 0 replies; 4+ messages in thread
From: Sergey Senozhatsky @ 2015-12-04 0:29 UTC (permalink / raw)
To: Jan Kara
Cc: Sergey Senozhatsky, tj, akpm, calvinowens, davej, jack, kyle,
stable, mm-commits, linux-kernel
On (12/03/15 10:57), Jan Kara wrote:
[..]
> > > CPU2 still can cause lots of troubles. consider
> > >
> > > CPU0 CPU1 CPU2
> > > printk
> > > ... printk_deferred
> > > printk wake_up_klogd
> > > wake_up_klogd_work_func
> > > console_trylock
> > > console_unlock
> > >
> > > printk_deferred() may be issued by scheduler, for example.
> >
> > IOW, may be we can start limiting the number of bytes printed in console_unlock()
> > from irq contexts. Which is quite ugly, yes. We basically don't know how much time
> > we spend in call_console_drivers(); some of the consoles can do 'internal' spin_lock
> > loops in ->write() handlers, etc. So something like this (below) probably will not
> > really help, but still it's not always OK to do `while (1)' loop in console_unlock()
> > for irqs.
>
> What we really want is pushing the printing into async context (unless
> forced by debug option or oops in progress). Because what you do here fixes
> only a small fraction of the problem space. I have patches which fix more
> of it (https://lkml.org/lkml/2015/10/26/16) but they are still not enough
> because on large machines e.g. udev times out because printing messages
> about inserted hardware over serial console just takes too long.
absolutely agree. thanks for the link!
-ss
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2015-12-04 0:28 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <565f855a./bN6NB3bZKjpF4Wa%akpm@linux-foundation.org>
2015-12-03 1:11 ` + printk-do-cond_resched-between-lines-while-outputting-to-consoles.patch added to -mm tree Sergey Senozhatsky
2015-12-03 2:39 ` Sergey Senozhatsky
2015-12-03 9:57 ` Jan Kara
2015-12-04 0:29 ` Sergey Senozhatsky
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).