Re: [RFC][PATCH v9 1/2] printk: Make printk() completely async
On (04/01/16 17:00), Petr Mladek wrote: > You need to move this assigment right above the > console_lock()/console_unlock() > calls. Otherwise, there is a race: > > CPU0: CPU1 > > printk_kthread_func() > > console_unlock() > > printk() > > printk_kthread_need_flush_console = true; > wake_up_process(printk_kthread); > > printk_kthread_need_flush_console = false; > > set_current_state(TASK_INTERRUPTIBLE); > if (!printk_kthread_need_flush_console) > schedule(); thanks. yeah, this can add latency to some messages. -ss
Re: [RFC][PATCH v9 1/2] printk: Make printk() completely async
On (04/01/16 17:00), Petr Mladek wrote: > You need to move this assigment right above the > console_lock()/console_unlock() > calls. Otherwise, there is a race: > > CPU0: CPU1 > > printk_kthread_func() > > console_unlock() > > printk() > > printk_kthread_need_flush_console = true; > wake_up_process(printk_kthread); > > printk_kthread_need_flush_console = false; > > set_current_state(TASK_INTERRUPTIBLE); > if (!printk_kthread_need_flush_console) > schedule(); thanks. yeah, this can add latency to some messages. -ss
Re: [RFC][PATCH v9 1/2] printk: Make printk() completely async
Hello, On (04/01/16 22:33), kbuild test robot wrote: > Hi Jan, > > > >> kernel/printk/printk.c:1938:28: warning: 'printk_kthread' defined but not > >> used [-Wunused-variable] > static struct task_struct *printk_kthread; >^ yeah. thanks. please find the updated patch below. also updated to address Petr's comments. ===8<===8<===8< >From 45698fcaa85fcabbb246dcf2e73c4935b58690c2 Mon Sep 17 00:00:00 2001 From: Jan KaraDate: Fri, 1 Apr 2016 22:09:59 +0900 Subject: [PATCH] printk: Make printk() completely async Currently, printk() sometimes waits for message to be printed to console and sometimes it does not (when console_sem is held by some other process). In case printk() grabs console_sem and starts printing to console, it prints messages from kernel printk buffer until the buffer is empty. When serial console is attached, printing is slow and thus other CPUs in the system have plenty of time to append new messages to the buffer while one CPU is printing. Thus the CPU can spend unbounded amount of time doing printing in console_unlock(). This is especially serious problem if the printk() calling console_unlock() was called with interrupts disabled. In practice users have observed a CPU can spend tens of seconds printing in console_unlock() (usually during boot when hundreds of SCSI devices are discovered) resulting in RCU stalls (CPU doing printing doesn't reach quiescent state for a long time), softlockup reports (IPIs for the printing CPU don't get served and thus other CPUs are spinning waiting for the printing CPU to process IPIs), and eventually a machine death (as messages from stalls and lockups append to printk buffer faster than we are able to print). So these machines are unable to boot with serial console attached. Another observed issue is that due to slow printk, hardware discovery is slow and udev times out before kernel manages to discover all the attached HW. Also during artificial stress testing SATA disk disappears from the system because its interrupts aren't served for too long. This patch makes printk() completely asynchronous (similar to what printk_deferred() did until now). It appends message to the kernel printk buffer and wake_up()s a special dedicated kthread to do the printing to console. This has the advantage that printing always happens from a schedulable contex and thus we don't lockup any particular CPU or even interrupts. Also it has the advantage that printk() is fast and thus kernel booting is not slowed down by slow serial console. Disadvantage of this method is that in case of crash there is higher chance that important messages won't appear in console output (we may need working scheduling to print message to console). We somewhat mitigate this risk by switching printk to the original method of immediate printing to console if oops is in progress. Also for debugging purposes we provide printk.synchronous kernel parameter which resorts to the original printk behavior. printk() is expected to work under different conditions and in different scenarios, including corner cases of OOM when all of the workers are busy (e.g. allocating memory), thus printk() uses its own dedicated printing kthread, rather than relying on workqueue (even with WQ_MEM_RECLAIM bit set we potentially can receive delays in printing until workqueue declares a ->mayday, as noted by Tetsuo Handa). Signed-off-by: Jan Kara Signed-off-by: Sergey Senozhatsky Reviewed-by: Petr Mladek --- Documentation/kernel-parameters.txt | 10 kernel/printk/printk.c | 93 ++--- 2 files changed, 96 insertions(+), 7 deletions(-) diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt index da9ee46..9317de6 100644 --- a/Documentation/kernel-parameters.txt +++ b/Documentation/kernel-parameters.txt @@ -3114,6 +3114,16 @@ bytes respectively. Such letter suffixes can also be entirely omitted. printk.time=Show timing data prefixed to each printk message line Format: (1/Y/y=enable, 0/N/n=disable) + printk.synchronous= + By default kernel messages are printed to console + asynchronously (except during early boot or when oops + is happening). That avoids kernel stalling behind slow + serial console and thus avoids softlockups, interrupt + timeouts, or userspace timing out during heavy printing. + However for debugging problems, printing messages to + console immediately may be desirable. This option + enables such behavior. + processor.max_cstate= [HW,ACPI] Limit processor to maximum C-state max_cstate=9 overrides any DMI blacklist limit.
Re: [RFC][PATCH v9 1/2] printk: Make printk() completely async
Hello, On (04/01/16 22:33), kbuild test robot wrote: > Hi Jan, > > > >> kernel/printk/printk.c:1938:28: warning: 'printk_kthread' defined but not > >> used [-Wunused-variable] > static struct task_struct *printk_kthread; >^ yeah. thanks. please find the updated patch below. also updated to address Petr's comments. ===8<===8<===8< >From 45698fcaa85fcabbb246dcf2e73c4935b58690c2 Mon Sep 17 00:00:00 2001 From: Jan Kara Date: Fri, 1 Apr 2016 22:09:59 +0900 Subject: [PATCH] printk: Make printk() completely async Currently, printk() sometimes waits for message to be printed to console and sometimes it does not (when console_sem is held by some other process). In case printk() grabs console_sem and starts printing to console, it prints messages from kernel printk buffer until the buffer is empty. When serial console is attached, printing is slow and thus other CPUs in the system have plenty of time to append new messages to the buffer while one CPU is printing. Thus the CPU can spend unbounded amount of time doing printing in console_unlock(). This is especially serious problem if the printk() calling console_unlock() was called with interrupts disabled. In practice users have observed a CPU can spend tens of seconds printing in console_unlock() (usually during boot when hundreds of SCSI devices are discovered) resulting in RCU stalls (CPU doing printing doesn't reach quiescent state for a long time), softlockup reports (IPIs for the printing CPU don't get served and thus other CPUs are spinning waiting for the printing CPU to process IPIs), and eventually a machine death (as messages from stalls and lockups append to printk buffer faster than we are able to print). So these machines are unable to boot with serial console attached. Another observed issue is that due to slow printk, hardware discovery is slow and udev times out before kernel manages to discover all the attached HW. Also during artificial stress testing SATA disk disappears from the system because its interrupts aren't served for too long. This patch makes printk() completely asynchronous (similar to what printk_deferred() did until now). It appends message to the kernel printk buffer and wake_up()s a special dedicated kthread to do the printing to console. This has the advantage that printing always happens from a schedulable contex and thus we don't lockup any particular CPU or even interrupts. Also it has the advantage that printk() is fast and thus kernel booting is not slowed down by slow serial console. Disadvantage of this method is that in case of crash there is higher chance that important messages won't appear in console output (we may need working scheduling to print message to console). We somewhat mitigate this risk by switching printk to the original method of immediate printing to console if oops is in progress. Also for debugging purposes we provide printk.synchronous kernel parameter which resorts to the original printk behavior. printk() is expected to work under different conditions and in different scenarios, including corner cases of OOM when all of the workers are busy (e.g. allocating memory), thus printk() uses its own dedicated printing kthread, rather than relying on workqueue (even with WQ_MEM_RECLAIM bit set we potentially can receive delays in printing until workqueue declares a ->mayday, as noted by Tetsuo Handa). Signed-off-by: Jan Kara Signed-off-by: Sergey Senozhatsky Reviewed-by: Petr Mladek --- Documentation/kernel-parameters.txt | 10 kernel/printk/printk.c | 93 ++--- 2 files changed, 96 insertions(+), 7 deletions(-) diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt index da9ee46..9317de6 100644 --- a/Documentation/kernel-parameters.txt +++ b/Documentation/kernel-parameters.txt @@ -3114,6 +3114,16 @@ bytes respectively. Such letter suffixes can also be entirely omitted. printk.time=Show timing data prefixed to each printk message line Format: (1/Y/y=enable, 0/N/n=disable) + printk.synchronous= + By default kernel messages are printed to console + asynchronously (except during early boot or when oops + is happening). That avoids kernel stalling behind slow + serial console and thus avoids softlockups, interrupt + timeouts, or userspace timing out during heavy printing. + However for debugging problems, printing messages to + console immediately may be desirable. This option + enables such behavior. + processor.max_cstate= [HW,ACPI] Limit processor to maximum C-state max_cstate=9 overrides any DMI blacklist limit. diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index
Re: [RFC][PATCH v9 1/2] printk: Make printk() completely async
On Fri 2016-04-01 23:10:04, Sergey Senozhatsky wrote: > This patch makes printk() completely asynchronous (similar to what > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index bfbf284..2e50c48 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -2722,6 +2761,47 @@ static int __init printk_late_init(void) > late_initcall(printk_late_init); > > #if defined CONFIG_PRINTK > +static int printk_kthread_func(void *data) > +{ > + while (1) { > + set_current_state(TASK_INTERRUPTIBLE); > + if (!printk_kthread_need_flush_console) > + schedule(); > + > + __set_current_state(TASK_RUNNING); > + > + console_lock(); > + console_unlock(); > + /* > + * Avoid an infinite loop when console_unlock() cannot > + * access consoles, e.g. because console_suspended is > + * true. schedule(), someone else will print the messages > + * from resume_console(). > + */ > + printk_kthread_need_flush_console = false; You need to move this assigment right above the console_lock()/console_unlock() calls. Otherwise, there is a race: CPU0: CPU1 printk_kthread_func() console_unlock() printk() printk_kthread_need_flush_console = true; wake_up_process(printk_kthread); printk_kthread_need_flush_console = false; set_current_state(TASK_INTERRUPTIBLE); if (!printk_kthread_need_flush_console) schedule(); => sleeping without processing the last message. You could safely set it false before calling console_lock()/console_unlock() because you are calling the commands that are requested by the flag. With the above described change: Reviewed-by: Petr MladekBest Regards, Petr
Re: [RFC][PATCH v9 1/2] printk: Make printk() completely async
On Fri 2016-04-01 23:10:04, Sergey Senozhatsky wrote: > This patch makes printk() completely asynchronous (similar to what > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index bfbf284..2e50c48 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -2722,6 +2761,47 @@ static int __init printk_late_init(void) > late_initcall(printk_late_init); > > #if defined CONFIG_PRINTK > +static int printk_kthread_func(void *data) > +{ > + while (1) { > + set_current_state(TASK_INTERRUPTIBLE); > + if (!printk_kthread_need_flush_console) > + schedule(); > + > + __set_current_state(TASK_RUNNING); > + > + console_lock(); > + console_unlock(); > + /* > + * Avoid an infinite loop when console_unlock() cannot > + * access consoles, e.g. because console_suspended is > + * true. schedule(), someone else will print the messages > + * from resume_console(). > + */ > + printk_kthread_need_flush_console = false; You need to move this assigment right above the console_lock()/console_unlock() calls. Otherwise, there is a race: CPU0: CPU1 printk_kthread_func() console_unlock() printk() printk_kthread_need_flush_console = true; wake_up_process(printk_kthread); printk_kthread_need_flush_console = false; set_current_state(TASK_INTERRUPTIBLE); if (!printk_kthread_need_flush_console) schedule(); => sleeping without processing the last message. You could safely set it false before calling console_lock()/console_unlock() because you are calling the commands that are requested by the flag. With the above described change: Reviewed-by: Petr Mladek Best Regards, Petr