lkml.org 
[lkml]   [2016]   [Apr]   [7]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    From
    Subject[PATCH v11 1/3] printk: Make printk() completely async
    Date
    From: Jan Kara <jack@suse.cz>

    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.

    Async printk, for the time being, is considered to be less reliable
    than the synchronous one, so by default we keep printk operating in
    synchronous mode. There is a printk.synchronous kernel parameter which
    permits to select sync/async mode as a boot parameter or later on
    from user space via sysfs knob.

    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 <jack@suse.cz>
    Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
    ---
    Documentation/kernel-parameters.txt | 12 +++++
    kernel/printk/printk.c | 99 ++++++++++++++++++++++++++++++++++---
    2 files changed, 104 insertions(+), 7 deletions(-)

    diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
    index 6152ee4..17b9cb3 100644
    --- a/Documentation/kernel-parameters.txt
    +++ b/Documentation/kernel-parameters.txt
    @@ -3125,6 +3125,18 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
    printk.time= Show timing data prefixed to each printk message line
    Format: <bool> (1/Y/y=enable, 0/N/n=disable)

    + printk.synchronous=
    + This parameter controls whether kernel messages must be
    + printed to console synchronously or asynchronously.
    + Asynchronous printing avoids kernel stalling behind
    + slow serial console and thus avoids softlockups,
    + interrupt timeouts, or userspace timing out during
    + heavy printing. printk switches back to synchronous mode
    + during early boot or when oops is happening. For the
    + time being, synchronous mode considered to be more
    + reliable, besides, for debugging, printing messages to
    + console immediately (synchronous mode) is desirable.
    +
    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 bfbf284..64a98ea 100644
    --- a/kernel/printk/printk.c
    +++ b/kernel/printk/printk.c
    @@ -46,6 +46,8 @@
    #include <linux/utsname.h>
    #include <linux/ctype.h>
    #include <linux/uio.h>
    +#include <linux/kthread.h>
    +#include <linux/sched/rt.h>

    #include <asm/uaccess.h>
    #include <asm-generic/sections.h>
    @@ -284,6 +286,16 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
    static char *log_buf = __log_buf;
    static u32 log_buf_len = __LOG_BUF_LEN;

    +/* Control whether printing to console must be synchronous. */
    +static bool __read_mostly printk_sync = true;
    +module_param_named(synchronous, printk_sync, bool, S_IRUGO);
    +MODULE_PARM_DESC(synchronous, "make printing to console synchronous");
    +
    +/* Printing kthread for async printk */
    +static struct task_struct *printk_kthread;
    +/* When `true' printing thread has messages to print */
    +static bool printk_kthread_need_flush_console;
    +
    /* Return log buffer address */
    char *log_buf_addr_get(void)
    {
    @@ -1608,6 +1620,8 @@ asmlinkage int vprintk_emit(int facility, int level,
    const char *dict, size_t dictlen,
    const char *fmt, va_list args)
    {
    + /* cpu currently holding logbuf_lock in this function */
    + static unsigned int logbuf_cpu = UINT_MAX;
    static bool recursion_bug;
    static char textbuf[LOG_LINE_MAX];
    char *text = textbuf;
    @@ -1617,8 +1631,6 @@ asmlinkage int vprintk_emit(int facility, int level,
    int this_cpu;
    int printed_len = 0;
    bool in_sched = false;
    - /* cpu currently holding logbuf_lock in this function */
    - static unsigned int logbuf_cpu = UINT_MAX;

    if (level == LOGLEVEL_SCHED) {
    level = LOGLEVEL_DEFAULT;
    @@ -1757,12 +1769,35 @@ asmlinkage int vprintk_emit(int facility, int level,
    if (!in_sched) {
    lockdep_off();
    /*
    - * Try to acquire and then immediately release the console
    - * semaphore. The release will print out buffers and wake up
    - * /dev/kmsg and syslog() users.
    + * Attempt to print the messages to console asynchronously so
    + * that the kernel doesn't get stalled due to slow serial
    + * console. That can lead to softlockups, lost interrupts, or
    + * userspace timing out under heavy printing load.
    + *
    + * However we resort to synchronous printing of messages during
    + * early boot, when synchronous printing was explicitly
    + * requested by a kernel parameter, or when console_verbose()
    + * was called to print everything during panic / oops.
    + * Unlike bust_spinlocks() and oops_in_progress,
    + * console_verbose() sets console_loglevel to MOTORMOUTH and
    + * never clears it, while oops_in_progress can go back to 0,
    + * switching printk back to async mode; we want printk to
    + * operate in sync mode once panic() occurred.
    */
    - if (console_trylock())
    - console_unlock();
    + if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH &&
    + printk_kthread) {
    + /* 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();
    + }
    lockdep_on();
    }

    @@ -2722,6 +2757,56 @@ 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);
    + /*
    + * 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;
    +
    + console_lock();
    + console_unlock();
    + }
    +
    + return 0;
    +}
    +
    +/*
    + * Init async printk via late_initcall, after core/arch/device/etc.
    + * initialization.
    + */
    +static int __init init_printk_kthread(void)
    +{
    + struct task_struct *thread;
    + struct sched_param param = {
    + .sched_priority = MAX_RT_PRIO - 1,
    + };
    +
    + if (printk_sync)
    + return 0;
    +
    + thread = kthread_run(printk_kthread_func, NULL, "printk");
    + if (IS_ERR(thread)) {
    + pr_err("printk: unable to create printing thread\n");
    + printk_sync = true;
    + return PTR_ERR(thread);
    + }
    +
    + sched_setscheduler(thread, SCHED_FIFO, &param);
    + printk_kthread = thread;
    + return 0;
    +}
    +late_initcall(init_printk_kthread);
    +
    /*
    * Delayed printk version, for scheduler-internal messages:
    */
    --
    2.8.0
    \
     
     \ /
      Last update: 2016-04-07 18:41    [W:4.513 / U:0.012 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site