diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt index 7116fda7077f..74826b1e2529 100644 --- a/Documentation/kernel-parameters.txt +++ b/Documentation/kernel-parameters.txt @@ -2621,6 +2621,21 @@ bytes respectively. Such letter suffixes can also be entirely omitted. Format: (1/Y/y=enable, 0/N/n=disable) default: disabled + printk.offload_chars= + Printing to console can be relatively slow especially + in case of serial console. When there is intensive + printing happening from several cpus (as is the case + during boot), a cpu can be spending significant time + (seconds or more) doing printing. To avoid softlockups, + lost interrupts, and similar problems other cpus + will take over printing after the currently printing + cpu has printed 'printk.offload_chars' characters. + Higher value means possibly longer interrupt and other + latencies but lower overhead of printing due to handing + over of printing. + Format: (0 = disabled) + default: 1000 + printk.time= Show timing data prefixed to each printk message line Format: (1/Y/y=enable, 0/N/n=disable) diff --git a/kernel/printk.c b/kernel/printk.c index 91c554e027c5..cb7e06850eb5 100644 --- a/kernel/printk.c +++ b/kernel/printk.c @@ -45,6 +45,7 @@ #include #include #include +#include #include @@ -87,6 +88,31 @@ static DEFINE_SEMAPHORE(console_sem); struct console *console_drivers; EXPORT_SYMBOL_GPL(console_drivers); +/* State machine for handing over printing */ +enum { + /* + * Set by the holder of console_sem if currently printing task wants to + * hand over printing. Cleared before console_sem is released. + */ + PRINTK_HANDOVER_B, + /* + * Set if there's someone spinning on console_sem to take over printing. + * Cleared after acquiring console_sem. + */ + PRINTK_CONSOLE_SPIN_B, +}; +static long printk_handover_state; + +/* + * Number of kernel threads for offloading printing. We need at least two so + * that they can hand over printing from one to another one and thus switch + * CPUs. + */ +#define PRINTING_TASKS 2 + +/* Wait queue printing kthreads sleep on when idle */ +static DECLARE_WAIT_QUEUE_HEAD(print_queue); + #ifdef CONFIG_LOCKDEP static struct lockdep_map console_lock_dep_map = { .name = "console_lock" @@ -254,6 +280,19 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN); static char *log_buf = __log_buf; static u32 log_buf_len = __LOG_BUF_LEN; +/* + * How many characters can we print in one call of printk before asking + * other cpus to continue printing. 0 means infinity. Tunable via + * printk.offload_chars kernel parameter. Our default 1000 means about + * 0.1s maximum latency due to printing. + */ +static unsigned int __read_mostly printk_offload_chars = 1000; + +module_param_named(offload_chars, printk_offload_chars, uint, + S_IRUGO | S_IWUSR); +MODULE_PARM_DESC(offload_chars, "offload printing to console to a different" + " cpu after this number of characters"); + /* human readable text of the record */ static char *log_text(const struct printk_log *msg) { @@ -1942,6 +1981,7 @@ void console_lock(void) if (console_suspended) return; console_locked = 1; + printk_handover_state = 0; console_may_schedule = 1; mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_); } @@ -1964,12 +2004,45 @@ int console_trylock(void) return 0; } console_locked = 1; + printk_handover_state = 0; console_may_schedule = 0; mutex_acquire(&console_lock_dep_map, 0, 1, _RET_IP_); return 1; } EXPORT_SYMBOL(console_trylock); +/* + * This is a version of console_lock() which spins to acquire console_sem. + * It is only for use by threads that take care of flushing printk buffer so + * that they can be sure they are not preempted while waiting for console_sem. + * + * The function returns 1 if we acquired console_sem, 0 if we failed (either + * someone else is already spinning, someone acquired console_sem, or console + * is suspended). + */ +static int console_lock_try_spin(void) +{ + WARN_ON_ONCE(preemptible()); + /* Someone already spinning? Don't waste cpu time... */ + if (test_and_set_bit(PRINTK_CONSOLE_SPIN_B, &printk_handover_state)) + return 0; + while (down_trylock(&console_sem)) { + /* Someone else took console_sem? */ + if (!test_bit(PRINTK_CONSOLE_SPIN_B, &printk_handover_state)) + return 0; + cpu_relax(); + } + printk_handover_state = 0; + if (console_suspended) { + up(&console_sem); + return 0; + } + console_locked = 1; + console_may_schedule = 0; + mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_); + return 1; +} + int is_console_locked(void) { return console_locked; @@ -2004,15 +2077,44 @@ out: raw_spin_unlock_irqrestore(&logbuf_lock, flags); } +/* + * Returns true iff there is other cpu waiting to take over printing. This + * function also takes are of setting PRINTK_HANDOVER_B if we want to hand over + * printing to some other cpu. + */ +static bool cpu_stop_printing(int printed_chars) +{ + /* Oops? Print everything now to maximize chances user will see it */ + if (oops_in_progress) + return false; + if (!printk_offload_chars || printed_chars < printk_offload_chars) + return false; + /* Someone is spinning on console_sem? Give away to him. */ + if (test_bit(PRINTK_CONSOLE_SPIN_B, &printk_handover_state)) + return true; + if (!test_bit(PRINTK_HANDOVER_B, &printk_handover_state)) { + set_bit(PRINTK_HANDOVER_B, &printk_handover_state); + /* + * Paired with barrier in prepare_to_wait_exclusive() in + * printing_task() + */ + smp_mb(); + wake_up(&print_queue); + } + return false; +} + /** * console_unlock - unlock the console system * * Releases the console_lock which the caller holds on the console system * and the console driver list. * - * While the console_lock was held, console output may have been buffered - * by printk(). If this is the case, console_unlock(); emits - * the output prior to releasing the lock. + * While the console_lock was held, console output may have been buffered by + * printk(). If this is the case, console_unlock() emits the output prior to + * releasing the lock. However we need not write all the data in the buffer if + * we would hog the CPU for too long. In such case we try to hand over printing + * to a different cpu. * * If there is output waiting, we wake /dev/kmsg and syslog() users. * @@ -2025,6 +2127,8 @@ void console_unlock(void) unsigned long flags; bool wake_klogd = false; bool retry; + bool hand_over = false; + int printed_chars = 0; if (console_suspended) { up(&console_sem); @@ -2041,6 +2145,11 @@ again: size_t len; int level; + if (cpu_stop_printing(printed_chars)) { + hand_over = true; + break; + } + raw_spin_lock_irqsave(&logbuf_lock, flags); if (seen_seq != log_next_seq) { wake_klogd = true; @@ -2054,8 +2163,10 @@ again: console_prev = 0; } skip: - if (console_seq == log_next_seq) + if (console_seq == log_next_seq) { + raw_spin_unlock(&logbuf_lock); break; + } msg = log_from_idx(console_idx); if (msg->flags & LOG_NOCONS) { @@ -2086,31 +2197,39 @@ skip: stop_critical_timings(); /* don't trace print latency */ call_console_drivers(level, text, len); start_critical_timings(); + printed_chars += len; local_irq_restore(flags); } - console_locked = 0; - mutex_release(&console_lock_dep_map, 1, _RET_IP_); /* Release the exclusive_console once it is used */ if (unlikely(exclusive_console)) exclusive_console = NULL; - raw_spin_unlock(&logbuf_lock); - + /* Save modification of printk_handover_state in the common fast path */ + if (test_bit(PRINTK_HANDOVER_B, &printk_handover_state)) + clear_bit(PRINTK_HANDOVER_B, &printk_handover_state); + console_locked = 0; + mutex_release(&console_lock_dep_map, 1, _RET_IP_); up(&console_sem); /* - * Someone could have filled up the buffer again, so re-check if there's - * something to flush. In case we cannot trylock the console_sem again, - * there's a new owner and the console_unlock() from them will do the - * flush, no worries. + * Subtlety: We have interrupts disabled iff hand_over == false (to + * save one cli/sti pair in the fast path. */ - raw_spin_lock(&logbuf_lock); - retry = console_seq != log_next_seq; - raw_spin_unlock_irqrestore(&logbuf_lock, flags); + if (!hand_over) { + /* + * Someone could have filled up the buffer again, so re-check + * if there's something to flush. In case we cannot trylock the + * console_sem again, there's a new owner and the + * console_unlock() from them will do the flush, no worries. + */ + raw_spin_lock(&logbuf_lock); + retry = console_seq != log_next_seq; + raw_spin_unlock_irqrestore(&logbuf_lock, flags); - if (retry && console_trylock()) - goto again; + if (retry && console_trylock()) + goto again; + } if (wake_klogd) wake_up_klogd(); @@ -2148,6 +2267,7 @@ void console_unblank(void) console_lock(); console_locked = 1; + printk_handover_state = 0; console_may_schedule = 0; for_each_console(c) if ((c->flags & CON_ENABLED) && c->unblank) @@ -2424,9 +2544,38 @@ int unregister_console(struct console *console) } EXPORT_SYMBOL(unregister_console); +/* Kthread which takes over printing from a CPU which asks for help */ +static int printing_task(void *arg) +{ + DEFINE_WAIT(wait); + + while (1) { + prepare_to_wait_exclusive(&print_queue, &wait, + TASK_INTERRUPTIBLE); + if (!test_bit(PRINTK_HANDOVER_B, &printk_handover_state)) + schedule(); + finish_wait(&print_queue, &wait); + /* + * We don't want to be scheduled away once we got the CPU (that + * would be especially problematic if we hold console_sem at + * that moment since noone else could print to console). So + * disable preemption and spin on console_sem. We shouldn't + * spin for long since printing CPU drops console_sem as soon + * as it notices there is someone spinning on it. + */ + preempt_disable(); + if (console_lock_try_spin()) + console_unlock(); + preempt_enable(); + } + return 0; +} + static int __init printk_late_init(void) { struct console *con; + int i; + struct task_struct *task; for_each_console(con) { if (!keep_bootcon && con->flags & CON_BOOT) { @@ -2434,6 +2583,19 @@ static int __init printk_late_init(void) } } hotcpu_notifier(console_cpu_notify, 0); + + /* Does any handover of printing have any sence? */ + if (num_possible_cpus() <= 1) + return 0; + + for (i = 0; i < PRINTING_TASKS; i++) { + task = kthread_run(printing_task, NULL, "print/%d", i); + if (IS_ERR(task)) { + pr_err("printk: Cannot create printing thread: %ld\n", + PTR_ERR(task)); + } + } + return 0; } late_initcall(printk_late_init); -- 1.8.1.4