* [PATCH v12 0/3] printk: Make printk() completely async @ 2016-04-22 13:52 Sergey Senozhatsky 2016-04-22 13:52 ` [PATCH v12 1/3] " Sergey Senozhatsky ` (2 more replies) 0 siblings, 3 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-04-22 13:52 UTC (permalink / raw) To: Andrew Morton Cc: Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky Hello, This patch set makes printk() completely asynchronous: new messages are getting upended to the kernel printk buffer, but instead of 'direct' printing the actual print job is performed by a dedicated kthread. This has the advantage that printing always happens from a schedulable context and thus we don't lockup any particular CPU or even interrupts. against next-20160422 v12: -- rename printk_kthread_can_run bool flag -- update printk_kthread_can_run comment (Petr) -- drop mutex from printk_sync_set(), sysfs writes are synchronised (Petr) v11: -- switch default to sync printk -- make `synchronous' param RW (Andrew, Jan) -- set RT priority to printk kthread (Andrew) -- correct comments (Andrew) v10: -- simplify printk_kthread_need_flush_console (Jan, Petr) v9: -- move need_flush_console assignment down in vprintk_emit (Jan) -- simplify need_flush_console assignment rules (Petr) -- clear need_flush_console in printing function (Petr) -- rename need_flush_console (Petr) v8: -- rename kthread printing function (Petr) -- clear need_flush_console in console_unlock() under logbuf (Petr) v7: -- do not set global printk_sync in panic in vrintk_emit() (Petr) -- simplify vprintk_emit(). drop some of local variables (Petr) -- move handling of LOGLEVEL_SCHED messages back to printk_deferred() so we wake_up_process()/console_trylock() in vprintk_emit() only for !in_sched messages v6: -- move wake_up_process out of logbuf lock (Jan, Byungchul) -- do not disable async printk in recursion handling code. -- rebase against next-20160321 (w/NMI patches) v5: -- make printk.synchronous RO (Petr) -- make printing_func() correct and do not use wait_queue (Petr) -- do not panic() when can't allocate printing thread (Petr) -- do not wake_up_process() only in IRQ, prefer vprintk_emit() (Jan) -- move wake_up_klogd_work_func() to a separate patch (Petr) -- move wake_up_process() under logbuf lock so printk recursion logic can help us out -- switch to sync_print mode if printk recursion occured -- drop "printk: Skip messages on oops" patch v4: -- do not directly wake_up() the printing kthread from vprintk_emit(), need to go via IRQ->wake_up() to avoid sched deadlocks (Jan) v3: -- use a dedicated kthread for printing instead of using wq (Jan, Tetsuo, Tejun) v2: - use dedicated printk workqueue with WQ_MEM_RECLAIM bit - fallback to system-wide workqueue only if allocation of printk_wq has failed - do not use system_wq as a fallback wq. both console_lock() and onsole_unlock() can spend a significant amount of time; so we need to use system_long_wq. - rework sync/!sync detection logic a) we can have deferred (in_sched) messages before we allocate printk_wq, so the only way to handle those messages is via IRQ context b) even in printk.synchronous mode, deferred messages must not be printed directly, and should go via IRQ context c) even if we allocated printk_wq and have !sync_printk mode, we must route deferred messages via IRQ context - so this adds additional bool flags to vprint_emit() and introduces a new pending bit to `printk_pending' - fix build on !PRINTK configs Jan Kara (2): printk: Make printk() completely async printk: Make wake_up_klogd_work_func() async Sergey Senozhatsky (1): printk: make printk.synchronous param rw Documentation/kernel-parameters.txt | 12 +++ kernel/printk/printk.c | 141 +++++++++++++++++++++++++++++++++--- 2 files changed, 143 insertions(+), 10 deletions(-) -- 2.8.0 ^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v12 1/3] printk: Make printk() completely async 2016-04-22 13:52 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky @ 2016-04-22 13:52 ` Sergey Senozhatsky 2016-04-26 14:13 ` Petr Mladek 2016-04-22 13:52 ` [PATCH v12 2/3] printk: Make wake_up_klogd_work_func() async Sergey Senozhatsky 2016-04-22 13:53 ` [PATCH v12 3/3] printk: make printk.synchronous param rw Sergey Senozhatsky 2 siblings, 1 reply; 25+ messages in thread From: Sergey Senozhatsky @ 2016-04-22 13:52 UTC (permalink / raw) To: Andrew Morton Cc: Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky, Jan Kara 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 55990e4..0c3bee3 100644 --- a/Documentation/kernel-parameters.txt +++ b/Documentation/kernel-parameters.txt @@ -3135,6 +3135,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, ¶m); + printk_kthread = thread; + return 0; +} +late_initcall(init_printk_kthread); + /* * Delayed printk version, for scheduler-internal messages: */ -- 2.8.0 ^ permalink raw reply related [flat|nested] 25+ messages in thread
* Re: [PATCH v12 1/3] printk: Make printk() completely async 2016-04-22 13:52 ` [PATCH v12 1/3] " Sergey Senozhatsky @ 2016-04-26 14:13 ` Petr Mladek 0 siblings, 0 replies; 25+ messages in thread From: Petr Mladek @ 2016-04-26 14:13 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Jan Kara On Fri 2016-04-22 22:52:58, Sergey Senozhatsky wrote: > This patch makes printk() completely asynchronous (similar to what > > Signed-off-by: Jan Kara <jack@suse.cz> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> Reviewed-by: Petr Mladek <pmladek@suse.com> Best Regards, Petr ^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v12 2/3] printk: Make wake_up_klogd_work_func() async 2016-04-22 13:52 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky 2016-04-22 13:52 ` [PATCH v12 1/3] " Sergey Senozhatsky @ 2016-04-22 13:52 ` Sergey Senozhatsky 2016-04-22 13:53 ` [PATCH v12 3/3] printk: make printk.synchronous param rw Sergey Senozhatsky 2 siblings, 0 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-04-22 13:52 UTC (permalink / raw) To: Andrew Morton Cc: Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky, Jan Kara From: Jan Kara <jack@suse.cz> Offload printing of scheduler deferred messages from IRQ context to a schedulable printing kthread, when possible (the same way we do it in vprintk_emit()). Otherwise, the CPU can spend unbounded amount of time doing printing in console_unlock() from IRQ. Signed-off-by: Jan Kara <jack@suse.cz> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> Reviewed-by: Petr Mladek <pmladek@suse.com> --- kernel/printk/printk.c | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 64a98ea..89f5441 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2820,9 +2820,16 @@ static void wake_up_klogd_work_func(struct irq_work *irq_work) int pending = __this_cpu_xchg(printk_pending, 0); if (pending & PRINTK_PENDING_OUTPUT) { - /* If trylock fails, someone else is doing the printing */ - if (console_trylock()) - console_unlock(); + if (printk_kthread) { + wake_up_process(printk_kthread); + } else { + /* + * If trylock fails, someone else is doing + * the printing + */ + if (console_trylock()) + console_unlock(); + } } if (pending & PRINTK_PENDING_WAKEUP) -- 2.8.0 ^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v12 3/3] printk: make printk.synchronous param rw 2016-04-22 13:52 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky 2016-04-22 13:52 ` [PATCH v12 1/3] " Sergey Senozhatsky 2016-04-22 13:52 ` [PATCH v12 2/3] printk: Make wake_up_klogd_work_func() async Sergey Senozhatsky @ 2016-04-22 13:53 ` Sergey Senozhatsky 2016-04-23 6:56 ` Jan Kara 2016-04-23 15:01 ` [PATCH] " Sergey Senozhatsky 2 siblings, 2 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-04-22 13:53 UTC (permalink / raw) To: Andrew Morton Cc: Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky Change `synchronous' printk param to be RW, so user space can change printk mode back and forth to/from sync mode (which is considered to be more reliable). Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> --- kernel/printk/printk.c | 51 +++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 40 insertions(+), 11 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 89f5441..61e639a 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -288,9 +288,6 @@ 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 */ @@ -1785,7 +1782,7 @@ asmlinkage int vprintk_emit(int facility, int level, * operate in sync mode once panic() occurred. */ if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH && - printk_kthread) { + !printk_sync && printk_kthread) { /* Offload printing to a schedulable context. */ printk_kthread_need_flush_console = true; wake_up_process(printk_kthread); @@ -2757,6 +2754,13 @@ static int __init printk_late_init(void) late_initcall(printk_late_init); #if defined CONFIG_PRINTK +/* + * Prevent starting printk_kthread from start_kernel()->parse_args(). + * It's not possible at this stage. Instead, do it via the inticall + * or a sysfs knob. + */ +static bool printk_kthread_can_run; + static int printk_kthread_func(void *data) { while (1) { @@ -2780,18 +2784,14 @@ static int printk_kthread_func(void *data) return 0; } -/* - * Init async printk via late_initcall, after core/arch/device/etc. - * initialization. - */ -static int __init init_printk_kthread(void) +static int __init_printk_kthread(void) { struct task_struct *thread; struct sched_param param = { .sched_priority = MAX_RT_PRIO - 1, }; - if (printk_sync) + if (!printk_kthread_can_run || printk_sync || printk_kthread) return 0; thread = kthread_run(printk_kthread_func, NULL, "printk"); @@ -2805,6 +2805,35 @@ static int __init init_printk_kthread(void) printk_kthread = thread; return 0; } + +static int printk_sync_set(const char *val, const struct kernel_param *kp) +{ + int ret; + + ret = param_set_bool(val, kp); + if (ret) + return ret; + return __init_printk_kthread(); +} + +static const struct kernel_param_ops param_ops_printk_sync = { + .set = printk_sync_set, + .get = param_get_bool, +}; + +module_param_cb(synchronous, ¶m_ops_printk_sync, &printk_sync, + S_IRUGO | S_IWUSR); +MODULE_PARM_DESC(synchronous, "make printing to console synchronous"); + +/* + * Init async printk via late_initcall, after core/arch/etc. + * initialization. + */ +static __init int init_printk_kthread(void) +{ + printk_kthread_can_run = true; + return __init_printk_kthread(); +} late_initcall(init_printk_kthread); /* @@ -2820,7 +2849,7 @@ static void wake_up_klogd_work_func(struct irq_work *irq_work) int pending = __this_cpu_xchg(printk_pending, 0); if (pending & PRINTK_PENDING_OUTPUT) { - if (printk_kthread) { + if (!printk_sync && printk_kthread) { wake_up_process(printk_kthread); } else { /* -- 2.8.0 ^ permalink raw reply related [flat|nested] 25+ messages in thread
* Re: [PATCH v12 3/3] printk: make printk.synchronous param rw 2016-04-22 13:53 ` [PATCH v12 3/3] printk: make printk.synchronous param rw Sergey Senozhatsky @ 2016-04-23 6:56 ` Jan Kara 2016-04-23 8:26 ` Sergey Senozhatsky 2016-04-23 15:01 ` [PATCH] " Sergey Senozhatsky 1 sibling, 1 reply; 25+ messages in thread From: Jan Kara @ 2016-04-23 6:56 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Andrew Morton, Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Fri 22-04-16 22:53:00, Sergey Senozhatsky wrote: > Change `synchronous' printk param to be RW, so user space > can change printk mode back and forth to/from sync mode > (which is considered to be more reliable). > > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> The patch looks good to me. One suggestion below: > @@ -1785,7 +1782,7 @@ asmlinkage int vprintk_emit(int facility, int level, > * operate in sync mode once panic() occurred. > */ > if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH && > - printk_kthread) { > + !printk_sync && printk_kthread) { > /* Offload printing to a schedulable context. */ > printk_kthread_need_flush_console = true; > wake_up_process(printk_kthread); It would seem more future-proof to hide '!printk_sync && printk_kthread' into a wrapper function as it is somewhat subtle detail that printk_kthread needn't exist while !printk_sync and I can imagine someone forgetting to check that in the future. Something like 'can_print_async()'? But I don't feel too strongly about that so feel free to add: Reviewed-by: Jan Kara <jack@suse.cz> regardless whether you change this or not. Honza -- Jan Kara <jack@suse.com> SUSE Labs, CR ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 3/3] printk: make printk.synchronous param rw 2016-04-23 6:56 ` Jan Kara @ 2016-04-23 8:26 ` Sergey Senozhatsky 0 siblings, 0 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-04-23 8:26 UTC (permalink / raw) To: Jan Kara Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky Hello, On (04/23/16 08:56), Jan Kara wrote: > > > > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> > > The patch looks good to me. One suggestion below: > > > @@ -1785,7 +1782,7 @@ asmlinkage int vprintk_emit(int facility, int level, > > * operate in sync mode once panic() occurred. > > */ > > if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH && > > - printk_kthread) { > > + !printk_sync && printk_kthread) { > > /* Offload printing to a schedulable context. */ > > printk_kthread_need_flush_console = true; > > wake_up_process(printk_kthread); > > It would seem more future-proof to hide '!printk_sync && printk_kthread' > into a wrapper function as it is somewhat subtle detail that printk_kthread > needn't exist while !printk_sync and I can imagine someone forgetting to > check that in the future. Something like 'can_print_async()'? But I don't > feel too strongly about that so feel free to add: hm, yes. this is what I eventually do in "yet to be posted" make-console_unlock()-async patch. I move printing kthread wakeup-s and those async printing checks out of vprintk_emit() and wake_up_klogd_work_func() to a special function: static bool console_unlock_async_flush(void) { ... if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH && !printk_sync && printk_kthread) { /* Offload printing to a schedulable context. */ printk_kthread_need_flush_console = true; console_locked = 0; up_console_sem(); wake_up_process(printk_kthread); return true; } return false; } so async_printk flags live in one place (which makes it easier to maintain) and vprintk_emit()/wake_up_klogd_work_func() simply do: if (console_trylock()) console_unlock(); console_unlock() is the one who decides if it can do async printk or a 'direct printing' via console_flush_and_unlock(). void console_unlock(void) { if (console_unlock_async_flush()) return; console_flush_and_unlock(); } console_flush_and_unlock() is what was previously known as console_unlock() - emit the messages and call_console_drivers(). I guess I can send out an updated version of 0003 as a reply to the initial patch and hide '!printk_sync && printk_kthread'. > Reviewed-by: Jan Kara <jack@suse.cz> > > regardless whether you change this or not. thanks. -ss ^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH] printk: make printk.synchronous param rw 2016-04-22 13:53 ` [PATCH v12 3/3] printk: make printk.synchronous param rw Sergey Senozhatsky 2016-04-23 6:56 ` Jan Kara @ 2016-04-23 15:01 ` Sergey Senozhatsky 2016-04-26 14:15 ` Petr Mladek 1 sibling, 1 reply; 25+ messages in thread From: Sergey Senozhatsky @ 2016-04-23 15:01 UTC (permalink / raw) To: Andrew Morton Cc: Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky Change `synchronous' printk param to be RW, so user space can change printk mode back and forth to/from sync mode (which is considered to be more reliable). Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> Reviewed-by: Jan Kara <jack@suse.cz> --- -- added Jan's Reviewed-by -- factored out async printk checks to can_printk_async() kernel/printk/printk.c | 56 ++++++++++++++++++++++++++++++++++++++++---------- 1 file changed, 45 insertions(+), 11 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 89f5441..9345a29 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -288,14 +288,16 @@ 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; +static inline bool can_printk_async(void) +{ + return !printk_sync && printk_kthread; +} + /* Return log buffer address */ char *log_buf_addr_get(void) { @@ -1785,7 +1787,7 @@ asmlinkage int vprintk_emit(int facility, int level, * operate in sync mode once panic() occurred. */ if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH && - printk_kthread) { + can_printk_async()) { /* Offload printing to a schedulable context. */ printk_kthread_need_flush_console = true; wake_up_process(printk_kthread); @@ -2757,6 +2759,13 @@ static int __init printk_late_init(void) late_initcall(printk_late_init); #if defined CONFIG_PRINTK +/* + * Prevent starting printk_kthread from start_kernel()->parse_args(). + * It's not possible at this stage. Instead, do it via the inticall + * or a sysfs knob. + */ +static bool printk_kthread_can_run; + static int printk_kthread_func(void *data) { while (1) { @@ -2780,18 +2789,14 @@ static int printk_kthread_func(void *data) return 0; } -/* - * Init async printk via late_initcall, after core/arch/device/etc. - * initialization. - */ -static int __init init_printk_kthread(void) +static int __init_printk_kthread(void) { struct task_struct *thread; struct sched_param param = { .sched_priority = MAX_RT_PRIO - 1, }; - if (printk_sync) + if (!printk_kthread_can_run || printk_sync || printk_kthread) return 0; thread = kthread_run(printk_kthread_func, NULL, "printk"); @@ -2805,6 +2810,35 @@ static int __init init_printk_kthread(void) printk_kthread = thread; return 0; } + +static int printk_sync_set(const char *val, const struct kernel_param *kp) +{ + int ret; + + ret = param_set_bool(val, kp); + if (ret) + return ret; + return __init_printk_kthread(); +} + +static const struct kernel_param_ops param_ops_printk_sync = { + .set = printk_sync_set, + .get = param_get_bool, +}; + +module_param_cb(synchronous, ¶m_ops_printk_sync, &printk_sync, + S_IRUGO | S_IWUSR); +MODULE_PARM_DESC(synchronous, "make printing to console synchronous"); + +/* + * Init async printk via late_initcall, after core/arch/etc. + * initialization. + */ +static __init int init_printk_kthread(void) +{ + printk_kthread_can_run = true; + return __init_printk_kthread(); +} late_initcall(init_printk_kthread); /* @@ -2820,7 +2854,7 @@ static void wake_up_klogd_work_func(struct irq_work *irq_work) int pending = __this_cpu_xchg(printk_pending, 0); if (pending & PRINTK_PENDING_OUTPUT) { - if (printk_kthread) { + if (can_printk_async()) { wake_up_process(printk_kthread); } else { /* -- 2.8.0 ^ permalink raw reply related [flat|nested] 25+ messages in thread
* Re: [PATCH] printk: make printk.synchronous param rw 2016-04-23 15:01 ` [PATCH] " Sergey Senozhatsky @ 2016-04-26 14:15 ` Petr Mladek 2016-04-27 1:09 ` Sergey Senozhatsky 0 siblings, 1 reply; 25+ messages in thread From: Petr Mladek @ 2016-04-26 14:15 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Sun 2016-04-24 00:01:05, Sergey Senozhatsky wrote: > Change `synchronous' printk param to be RW, so user space > can change printk mode back and forth to/from sync mode > (which is considered to be more reliable). > > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> > Reviewed-by: Jan Kara <jack@suse.cz> > --- > > -- added Jan's Reviewed-by > -- factored out async printk checks to can_printk_async() > > kernel/printk/printk.c | 56 ++++++++++++++++++++++++++++++++++++++++---------- > 1 file changed, 45 insertions(+), 11 deletions(-) > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 89f5441..9345a29 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -2757,6 +2759,13 @@ static int __init printk_late_init(void) > late_initcall(printk_late_init); > > #if defined CONFIG_PRINTK > +/* > + * Prevent starting printk_kthread from start_kernel()->parse_args(). > + * It's not possible at this stage. Instead, do it via the inticall ^^^^^^^^ s/inticall/initcall/ Otherwise, it looks fine. I like the series and keep my fingers crossed. Reviewed-by: Petr Mladek <pmladek@suse.com> Best Regards, Petr ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] printk: make printk.synchronous param rw 2016-04-26 14:15 ` Petr Mladek @ 2016-04-27 1:09 ` Sergey Senozhatsky 0 siblings, 0 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-04-27 1:09 UTC (permalink / raw) To: Petr Mladek Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky Hello, On (04/26/16 16:15), Petr Mladek wrote: [..] > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > > index 89f5441..9345a29 100644 > > --- a/kernel/printk/printk.c > > +++ b/kernel/printk/printk.c > > @@ -2757,6 +2759,13 @@ static int __init printk_late_init(void) > > late_initcall(printk_late_init); > > > > #if defined CONFIG_PRINTK > > +/* > > + * Prevent starting printk_kthread from start_kernel()->parse_args(). > > + * It's not possible at this stage. Instead, do it via the inticall > ^^^^^^^^ > > s/inticall/initcall/ geez, english is hard :( > Otherwise, it looks fine. I like the series and keep my fingers > crossed. > > Reviewed-by: Petr Mladek <pmladek@suse.com> thanks! my system was massively Oopsing (due to kcompactd direct freepage allocation, I suspect), OOM panicking, etc. during zsmalloc/zram stress tests yesterday. and async printk worked fine for me. just for note. -ss ^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v12 0/3] printk: Make printk() completely async @ 2016-05-13 13:18 Sergey Senozhatsky 2016-06-09 2:20 ` Sergey Senozhatsky ` (2 more replies) 0 siblings, 3 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-05-13 13:18 UTC (permalink / raw) To: Andrew Morton Cc: Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky Hello, no code changes, just refreshing the series so it'll be easier to pick up. added Reviwed-by-s and corrected a typo spotted by Petr. This patch permits to change printk() to operate in completely asynchronous mode: new messages are getting upended to the kernel printk buffer, but instead of 'direct' printing the actual print job is performed by a dedicated kthread. This has the advantage that printing always happens from a schedulable context and thus we don't lockup any particular CPU or even interrupts. against next-20160513 v12: -- rename printk_kthread_can_run bool flag -- update printk_kthread_can_run comment (Petr) -- drop mutex from printk_sync_set(), sysfs writes are synchronised (Petr) v11: -- switch default to sync printk -- make `synchronous' param RW (Andrew, Jan) -- set RT priority to printk kthread (Andrew) -- correct comments (Andrew) v10: -- simplify printk_kthread_need_flush_console (Jan, Petr) v9: -- move need_flush_console assignment down in vprintk_emit (Jan) -- simplify need_flush_console assignment rules (Petr) -- clear need_flush_console in printing function (Petr) -- rename need_flush_console (Petr) v8: -- rename kthread printing function (Petr) -- clear need_flush_console in console_unlock() under logbuf (Petr) v7: -- do not set global printk_sync in panic in vrintk_emit() (Petr) -- simplify vprintk_emit(). drop some of local variables (Petr) -- move handling of LOGLEVEL_SCHED messages back to printk_deferred() so we wake_up_process()/console_trylock() in vprintk_emit() only for !in_sched messages v6: -- move wake_up_process out of logbuf lock (Jan, Byungchul) -- do not disable async printk in recursion handling code. -- rebase against next-20160321 (w/NMI patches) v5: -- make printk.synchronous RO (Petr) -- make printing_func() correct and do not use wait_queue (Petr) -- do not panic() when can't allocate printing thread (Petr) -- do not wake_up_process() only in IRQ, prefer vprintk_emit() (Jan) -- move wake_up_klogd_work_func() to a separate patch (Petr) -- move wake_up_process() under logbuf lock so printk recursion logic can help us out -- switch to sync_print mode if printk recursion occured -- drop "printk: Skip messages on oops" patch v4: -- do not directly wake_up() the printing kthread from vprintk_emit(), need to go via IRQ->wake_up() to avoid sched deadlocks (Jan) v3: -- use a dedicated kthread for printing instead of using wq (Jan, Tetsuo, Tejun) v2: - use dedicated printk workqueue with WQ_MEM_RECLAIM bit - fallback to system-wide workqueue only if allocation of printk_wq has failed - do not use system_wq as a fallback wq. both console_lock() and onsole_unlock() can spend a significant amount of time; so we need to use system_long_wq. - rework sync/!sync detection logic a) we can have deferred (in_sched) messages before we allocate printk_wq, so the only way to handle those messages is via IRQ context b) even in printk.synchronous mode, deferred messages must not be printed directly, and should go via IRQ context c) even if we allocated printk_wq and have !sync_printk mode, we must route deferred messages via IRQ context - so this adds additional bool flags to vprint_emit() and introduces a new pending bit to `printk_pending' - fix build on !PRINTK configs Jan Kara (2): printk: Make printk() completely async printk: Make wake_up_klogd_work_func() async Sergey Senozhatsky (1): printk: make printk.synchronous param rw Documentation/kernel-parameters.txt | 12 +++ kernel/printk/printk.c | 146 +++++++++++++++++++++++++++++++++--- 2 files changed, 148 insertions(+), 10 deletions(-) -- 2.8.2.372.g63a3502 ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-05-13 13:18 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky @ 2016-06-09 2:20 ` Sergey Senozhatsky 2016-06-29 5:08 ` Sergey Senozhatsky 2016-07-11 19:25 ` Viresh Kumar 2 siblings, 0 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-06-09 2:20 UTC (permalink / raw) To: Andrew Morton Cc: Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky On (05/13/16 22:18), Sergey Senozhatsky wrote: > Hello, > > no code changes, just refreshing the series so it'll be easier to > pick up. added Reviwed-by-s and corrected a typo spotted by Petr. > Andrew, Did you get a chance to look at the series? -ss ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-05-13 13:18 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky 2016-06-09 2:20 ` Sergey Senozhatsky @ 2016-06-29 5:08 ` Sergey Senozhatsky 2016-06-29 5:16 ` Joe Perches 2016-07-12 16:28 ` Petr Mladek 2016-07-11 19:25 ` Viresh Kumar 2 siblings, 2 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-06-29 5:08 UTC (permalink / raw) To: Petr Mladek, Andrew Morton Cc: Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky, Sergey Senozhatsky Hello, the patch to fix the async KERN_CONT printk regression I mentioned several days ago in another thread. as a separate patch for now, to ease the review. will squash with 0001. ============== 8< ============== >From 70f65ed55eb82a1b8b74fdbd1a7afc9e77e9b380 Mon Sep 17 00:00:00 2001 From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> Subject: [PATCH] printk: print KERN_CONT buffer in sync printk mode One of my boxen has revealed that there is a race condition now between pr_cot() output and printk_kthread wake_up() time. Schematically, the CPU that triggered the race conditions was doing something like this: for (...) { for (....) { ... pr_cont(...); ... } pr_cont("\n"); } the resulting output was: $ dmesg 00000001 00000002 00000003 00000004 00000005 00000006 00000007 00000008 00000009 0000000a 0000000b 0000000c 0000000d 0000000e 0000000f 00000010 00000011 00000012 00000013 00000014 00000015 0000002b 0000002c 0000002d 0000002e 0000002f 00000030 00000031 .... KERN_CONT output is heavily relying on the fact there will be no other CPU(-s)/process(-es) doing any sort (KERN_CONT etc.) of printk-s simultaneously. This basically means that pr_cont() CPU is expected to be the one that actually does the printing and log_store() of the entire cont buffer: pr_cont() console_unlock() console_cont_flush() log_store() /* cont buffer */ pr_cont() console_unlock() console_cont_flush() log_store() /* cont buffer */ .... Async printk breaks this contract, because console_cont_flush() is now deferred. Thus pr_cont() will see a not fully flushed cont buffer, which will force it to append a new KERN_CONT not to cont buffer, but to buffer log as a separate log entry via log_store(). Due to the deferred nature of console_cont_flush() the very next pr_cont() may see cont buffer being flushed, so it will keep the message in the cont buffer and log_store() it later. So the cont line will split across several log entries -- printk_kthread can take some time to wkeup, during which pr_cont() will keep splitting cont line: $ dmesg 00000001 00000002 00000003 00000004 00000005 00000006 00000007 00000008 00000009 0000000a 0000000b 0000000c 0000000d 0000000e .... To fix the issue we need to switch to sync printk mode for KERN_CONT messages and when we cont_flush() the cont buffer. CPU0 CPU1 vprintk_emit(KERN_CONT "00000001") if (!(lflags & LOG_NEWLINE)) cont_add() if (!cont.len) starts a new cont line wake_up() printk_kthread ... vprintk_emit(KERN_CONT "0000004") entering console_unlock() if (!(lflags & LOG_NEWLINE)) cont_add() wake_up() printk_kthread vprintk_emit(KERN_CONT "0000005") if (!(lflags & LOG_NEWLINE)) cont_add() wake_up() printk_kthread console_cont_flush() cont_print_text() vprintk_emit(KERN_CONT "0000006") if (!(lflags & LOG_NEWLINE)) cont_add() wake_up() printk_kthread leaving console_unlock() vprintk_emit(KERN_CONT "0000007") if (!(lflags & LOG_NEWLINE)) entering console_unlock() cont_add() wake_up() printk_kthread console_cont_flush() cont_print_text() leaving console_unlock() vprintk_emit(KERN_CONT "\n") if (lflags & LOG_NEWLINE) if (cont.len) { cont_add() cont_flush() if (cont.cons) { cont.flags = flags; cont.flushed = true; ^^^^^^^^^^^^^^^^^^^^ } log_store() /* "0000001 .. 0000007" */ ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ } wake_up() process leaving console_unlock() vprintk_emit(KERN_CONT "0000008") if (!(lflags & LOG_NEWLINE)) entering console_unlock() cont_add() { if (cont.len && cont.flushed) ^^^^^^^^^^^ not flushed yet! return false; ... } log_store() /* "0000008" */ ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ ! wake_up() printk_kthread console_cont_flush() ^^^^^^^^^^^ now flushed! cont_print_text() call_console_drivers('\n'); vprintk_emit(KERN_CONT "0000009") if (!(lflags & LOG_NEWLINE)) cont_add() wake_up() printk_kthread msg_print_text() call_console_drivers("0000008") ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ leaving console_unlock() ... vprintk_emit(KERN_CONT "\n") if (lflags & LOG_NEWLINE) log_store() /* "00000009 ... 0000000e" */ ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ ! and so on. Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> --- kernel/printk/printk.c | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index eeafd73..bbb4180 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1705,6 +1705,8 @@ asmlinkage int vprintk_emit(int facility, int level, int printed_len = 0; int nmi_message_lost; bool in_sched = false; + /* do not print the KERN_CONT buffer asynchronously */ + bool has_cont_msg = false; if (level == LOGLEVEL_SCHED) { level = LOGLEVEL_DEFAULT; @@ -1804,6 +1806,8 @@ asmlinkage int vprintk_emit(int facility, int level, lflags |= LOG_PREFIX|LOG_NEWLINE; if (!(lflags & LOG_NEWLINE)) { + has_cont_msg = true; + /* * Flush the conflicting buffer. An earlier newline was missing, * or another task also prints continuation lines. @@ -1834,6 +1838,7 @@ asmlinkage int vprintk_emit(int facility, int level, stored = cont_add(facility, level, text, text_len); cont_flush(LOG_NEWLINE); + has_cont_msg = true; } if (stored) @@ -1859,8 +1864,9 @@ asmlinkage int vprintk_emit(int facility, int level, * * 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. + * requested by a kernel parameter, when we have a KERN_CONT + * buffer to print, 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, @@ -1868,7 +1874,8 @@ asmlinkage int vprintk_emit(int facility, int level, * operate in sync mode once panic() occurred. */ if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH && - can_printk_async()) { + can_printk_async() && + !has_cont_msg) { /* Offload printing to a schedulable context. */ printk_kthread_need_flush_console = true; wake_up_process(printk_kthread); -- 2.9.0.rc1 ^ permalink raw reply related [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-06-29 5:08 ` Sergey Senozhatsky @ 2016-06-29 5:16 ` Joe Perches 2016-06-29 5:32 ` Sergey Senozhatsky 2016-07-12 16:28 ` Petr Mladek 1 sibling, 1 reply; 25+ messages in thread From: Joe Perches @ 2016-06-29 5:16 UTC (permalink / raw) To: Sergey Senozhatsky, Petr Mladek, Andrew Morton Cc: Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Wed, 2016-06-29 at 14:08 +0900, Sergey Senozhatsky wrote: > the patch to fix the async KERN_CONT printk regression I mentioned > several days ago in another thread. KERN_CONT is effectively a no-op. This is any printk without a KERN_<LEVEL> ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-06-29 5:16 ` Joe Perches @ 2016-06-29 5:32 ` Sergey Senozhatsky 0 siblings, 0 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-06-29 5:32 UTC (permalink / raw) To: Joe Perches Cc: Sergey Senozhatsky, Petr Mladek, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On (06/28/16 22:16), Joe Perches wrote: > On Wed, 2016-06-29 at 14:08 +0900, Sergey Senozhatsky wrote: > > the patch to fix the async KERN_CONT printk regression I mentioned > > several days ago in another thread. > > KERN_CONT is effectively a no-op. > This is any printk without a KERN_<LEVEL> if the message has no LOG_NEWLINE in flags then it's stored as LOG_CONT in log buffer, but before getting there it sits in cont buffer. and those are usually KERN_CONT messages that don't have LOG_NEWLINE in flags. may be the wording is not exactly correct in the original message. -ss ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-06-29 5:08 ` Sergey Senozhatsky 2016-06-29 5:16 ` Joe Perches @ 2016-07-12 16:28 ` Petr Mladek 2016-07-13 7:42 ` Sergey Senozhatsky 1 sibling, 1 reply; 25+ messages in thread From: Petr Mladek @ 2016-07-12 16:28 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Wed 2016-06-29 14:08:35, Sergey Senozhatsky wrote: > Hello, > > the patch to fix the async KERN_CONT printk regression I mentioned > several days ago in another thread. > > as a separate patch for now, to ease the review. will squash with 0001. > > ============== 8< ============== > > >From 70f65ed55eb82a1b8b74fdbd1a7afc9e77e9b380 Mon Sep 17 00:00:00 2001 > From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> > Subject: [PATCH] printk: print KERN_CONT buffer in sync printk mode > > One of my boxen has revealed that there is a race condition now between > pr_cot() output and printk_kthread wake_up() time. Schematically, the CPU > that triggered the race conditions was doing > something like this: > > for (...) { > for (....) { > ... > pr_cont(...); > ... > } > pr_cont("\n"); > } I have tried the following: int a,b; for (a = 0; a < 1000; a++) { for (b = 0; b < 10; b++) { pr_cont("item%04d", a*10 + b); } pr_cont("\n"); } > the resulting output was: > > $ dmesg > > 00000001 00000002 00000003 00000004 00000005 00000006 00000007 > 00000008 > 00000009 0000000a 0000000b 0000000c 0000000d 0000000e > 0000000f 00000010 00000011 00000012 00000013 00000014 00000015 > 0000002b 0000002c 0000002d 0000002e 0000002f 00000030 00000031 > .... This patch helped a lot but I still see the problem from time to time. For example, [ 4913.000290] item8720item8721item8722item8723item8724item8725item8726item8727item8728item8729 [ 4913.000294] item8730item8731item8732item8733item8734item8735item8736item8737item8738item8739 [ 4913.000298] item8740item8741item8742item8743item8744item8745item8746item8747item8748item8749 [ 4913.000310] item8750item8751item8752item8753item8754item8755item8756item8757item8758item8759 [ 4913.000327] item8760item8761item8762item8763item8764item8765item8766item8767item8768item8769 [ 4913.000342] item8770item8771item8772item8773item8774item8775item8776item8777item8778item8779 [ 4913.000356] item8780 [ 4913.000357] item8781 [ 4913.000358] item8782 [ 4913.000358] item8783 [ 4913.000359] item8784 [ 4913.000359] item8785 [ 4913.000359] item8786 [ 4913.000360] item8787 [ 4913.000360] item8788 [ 4913.000360] item8789 [ 4913.000361] item8790 [ 4913.000361] item8791 [ 4913.000361] item8792 [...] > > KERN_CONT output is heavily relying on the fact there will be no other > CPU(-s)/process(-es) doing any sort (KERN_CONT etc.) of printk-s simultaneously. > This basically means that pr_cont() CPU is expected to be the one that actually > does the printing and log_store() of the entire cont buffer: In particular, the partially flushed cont buffer could not be used for new messages until the rest of it is flushed to the console. It is because the number of flushed characters is stored in the struct cont. > pr_cont() > console_unlock() > console_cont_flush() > log_store() /* cont buffer */ > pr_cont() > console_unlock() > console_cont_flush() > log_store() /* cont buffer */ > .... > > Async printk breaks this contract, because console_cont_flush() is now deferred. > Thus pr_cont() will see a not fully flushed cont buffer, which will force it to > append a new KERN_CONT not to cont buffer, but to buffer log as a separate log > entry via log_store(). Due to the deferred nature of console_cont_flush() the > very next pr_cont() may see cont buffer being flushed, so it will keep the > message in the cont buffer and log_store() it later. So the cont line will split > across several log entries -- printk_kthread can take some time to wkeup, > during which pr_cont() will keep splitting cont line: I guess that the problem was there even before async printk. For example, we do not keep lockbuf_lock between console_cont_flush() and printing other lines from the ring buffer. It means that new lines might appear in the buffer in the meantime. Note that we call consoles in console_cont_flush() without lockbuf_lock. So there is relatively long time for the race. In each case, the async printk made it worse because there might be longer periods between the printk thread is scheduled and the rest of the cont buffer is flushed. Anyway, this solution makes the async printk less helpful. Any message that does not end with a new line will force the sync mode and the risk of the soft lookup. Another solution would be to remember cont.cons outside of struct cont. Then the cont buffer could be reused immediately. The saved position will be used either for the actual cont buffer or for the very first message in the ring buffer. The situation might be detected by comparing console_seq, log_next_seq, and log_first_seq. if (console_seq == log_next_seq) cont buffer still includes the very last message if (console_seq < log_first_seq) the message was lost => no partialy flushed message around if (console_seq < log_next_seq && cont.cons) the current message in the log buffer is partially printed Well, this looks quite complicated. And I am afraid that I have missed something. I am still scratching my head around it. Best Regards, Petr ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-12 16:28 ` Petr Mladek @ 2016-07-13 7:42 ` Sergey Senozhatsky 2016-07-13 11:14 ` Petr Mladek 0 siblings, 1 reply; 25+ messages in thread From: Sergey Senozhatsky @ 2016-07-13 7:42 UTC (permalink / raw) To: Petr Mladek Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky Hello, On (07/12/16 18:28), Petr Mladek wrote: > I have tried the following: > > int a,b; > > for (a = 0; a < 1000; a++) { > for (b = 0; b < 10; b++) { > pr_cont("item%04d", a*10 + b); > } > pr_cont("\n"); > } > > > [ 4913.000298] item8740item8741item8742item8743item8744item8745item8746item8747item8748item8749 > [ 4913.000310] item8750item8751item8752item8753item8754item8755item8756item8757item8758item8759 > [ 4913.000327] item8760item8761item8762item8763item8764item8765item8766item8767item8768item8769 > [ 4913.000342] item8770item8771item8772item8773item8774item8775item8776item8777item8778item8779 > [ 4913.000356] item8780 > [ 4913.000357] item8781 > [ 4913.000358] item8782 > [...] hm.. so are there any 'concurrent' printk()-s coming from other CPUs that are not getting printed on the console (because of loglevel restrictions), but still screw up the cont buffer?.... otherwise, my expectation was that in this particular case cpu issues a new pr_cont() only after it has printed the current message via call_console_drivers()->write(). so partially flushed cont buffer was not really expected to happen. I was wrong, obviously. > > KERN_CONT output is heavily relying on the fact there will be no other > > CPU(-s)/process(-es) doing any sort (KERN_CONT etc.) of printk-s simultaneously. > > This basically means that pr_cont() CPU is expected to be the one that actually > > does the printing and log_store() of the entire cont buffer: > > In particular, the partially flushed cont buffer could not be used for new > messages until the rest of it is flushed to the console. It is because > the number of flushed characters is stored in the struct cont. > > pr_cont() > > console_unlock() > > console_cont_flush() > > log_store() /* cont buffer */ > > pr_cont() > > console_unlock() > > console_cont_flush() > > log_store() /* cont buffer */ > > .... > > > > Async printk breaks this contract, because console_cont_flush() is now deferred. > > Thus pr_cont() will see a not fully flushed cont buffer, which will force it to > > append a new KERN_CONT not to cont buffer, but to buffer log as a separate log > > entry via log_store(). Due to the deferred nature of console_cont_flush() the > > very next pr_cont() may see cont buffer being flushed, so it will keep the > > message in the cont buffer and log_store() it later. So the cont line will split > > across several log entries -- printk_kthread can take some time to wkeup, > > during which pr_cont() will keep splitting cont line: > > I guess that the problem was there even before async printk. For > example, we do not keep lockbuf_lock between console_cont_flush() > and printing other lines from the ring buffer. It means that > new lines might appear in the buffer in the meantime. > > Note that we call consoles in console_cont_flush() without > lockbuf_lock. So there is relatively long time for the race. > [...] > Another solution would be to remember cont.cons outside > of struct cont. Then the cont buffer could be reused > immediately. just an idea. ... or try to make KERN_CONT SMP-safe. there are many pr_cont() call sites. ACPI is one notable example. the others include OOM, some cgroup related output (or... was it memcg), etc., etc. so we *may be* can have a per-cpu cont buffer and add new API pr_cont_begin()/pr_cont_end(), that would disable preemption. + pr_cont_begin() /* preempt_disable() */ for (.....) pr_cont("%pS ....); + pr_cont_end() /* preempt_enable() */ pr_cont_end() also can flush this CPU's cont buffer and store the log line. this will probably break very long cont lines (not sure if we have any of those though). and may be flush_on_panic() would have to do some extra work iterating each cpu. > The saved position will be used either for the actual > cont buffer or for the very first message in the ring > buffer. The situation might be detected by comparing > console_seq, log_next_seq, and log_first_seq. we still can have pr_cont() happening on several cpus simultaneously. console_seq is getting reset, when we register a new CON_PRINTBUFFER console. > if (console_seq == log_next_seq) > cont buffer still includes the very last message > > if (console_seq < log_first_seq) > the message was lost => no partialy flushed message around > > if (console_seq < log_next_seq && cont.cons) > the current message in the log buffer is partially printed > > > Well, this looks quite complicated. And I am afraid that > I have missed something. > > I am still scratching my head around it. -ss ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-13 7:42 ` Sergey Senozhatsky @ 2016-07-13 11:14 ` Petr Mladek 2016-07-13 13:24 ` Sergey Senozhatsky 0 siblings, 1 reply; 25+ messages in thread From: Petr Mladek @ 2016-07-13 11:14 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Wed 2016-07-13 16:42:42, Sergey Senozhatsky wrote: > Hello, > > On (07/12/16 18:28), Petr Mladek wrote: > > I have tried the following: > > > > int a,b; > > > > for (a = 0; a < 1000; a++) { > > for (b = 0; b < 10; b++) { > > pr_cont("item%04d", a*10 + b); > > } > > pr_cont("\n"); > > } > > > > > > [ 4913.000298] item8740item8741item8742item8743item8744item8745item8746item8747item8748item8749 > > [ 4913.000310] item8750item8751item8752item8753item8754item8755item8756item8757item8758item8759 > > [ 4913.000327] item8760item8761item8762item8763item8764item8765item8766item8767item8768item8769 > > [ 4913.000342] item8770item8771item8772item8773item8774item8775item8776item8777item8778item8779 > > [ 4913.000356] item8780 > > [ 4913.000357] item8781 > > [ 4913.000358] item8782 > > [...] > > hm.. so are there any 'concurrent' printk()-s coming from other CPUs > that are not getting printed on the console (because of loglevel restrictions), > but still screw up the cont buffer?.... otherwise, my expectation was that in > this particular case cpu issues a new pr_cont() only after it has printed > the current message via call_console_drivers()->write(). so partially flushed > cont buffer was not really expected to happen. I was wrong, obviously. To be honest. I am not 100% sure what happens here. One theory is that the printk kthread is waken because of some previous non-continuous message. It steals console_lock() and partially flushes the cont buffer. In this case, the pr_cont() calls are not able to get console_lock() and basically work in the async mode. The pr_cont() calls have to store each piece sepatately because the partially flushed cont buffer is blocked until flushed completely. Hmm, the strange thing is that I see this problem even when I force the global synch more by echo Y > /sys/module/printk/parameters/synchronous I need to dig more into it. > > Another solution would be to remember cont.cons outside > > of struct cont. Then the cont buffer could be reused > > immediately. > > just an idea. > ... or try to make KERN_CONT SMP-safe. there are many pr_cont() call > sites. ACPI is one notable example. the others include OOM, some cgroup > related output (or... was it memcg), etc., etc. > > so we *may be* can have a per-cpu cont buffer and add new API > pr_cont_begin()/pr_cont_end(), that would disable preemption. > > > + pr_cont_begin() /* preempt_disable() */ > > for (.....) > pr_cont("%pS ....); > > + pr_cont_end() /* preempt_enable() */ > > pr_cont_end() also can flush this CPU's cont buffer and store the log > line. this will probably break very long cont lines (not sure if we > have any of those though). and may be flush_on_panic() would have to > do some extra work iterating each cpu. It would work but I am a bit scared by the complexity. I think that we should find a compromise between complexity and reliability. > > The saved position will be used either for the actual > > cont buffer or for the very first message in the ring > > buffer. The situation might be detected by comparing > > console_seq, log_next_seq, and log_first_seq. > > we still can have pr_cont() happening on several cpus simultaneously. > console_seq is getting reset, when we register a new CON_PRINTBUFFER > console. I agree that mixing part of lines from different processes/cpus is not ideal. But it is not much worse than mixing whole lines. We should do a best effort but we do not need to be perfect. I continue with scratching my head. Best Regards, Petr ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-13 11:14 ` Petr Mladek @ 2016-07-13 13:24 ` Sergey Senozhatsky 2016-07-13 14:22 ` Petr Mladek 0 siblings, 1 reply; 25+ messages in thread From: Sergey Senozhatsky @ 2016-07-13 13:24 UTC (permalink / raw) To: Petr Mladek Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky Hello, On (07/13/16 13:14), Petr Mladek wrote: [..] > > > [ 4913.000310] item8750item8751item8752item8753item8754item8755item8756item8757item8758item8759 > > > [ 4913.000327] item8760item8761item8762item8763item8764item8765item8766item8767item8768item8769 > > > [ 4913.000342] item8770item8771item8772item8773item8774item8775item8776item8777item8778item8779 > > > [ 4913.000356] item8780 > > > [ 4913.000357] item8781 > > > [ 4913.000358] item8782 > > > [...] > > > > hm.. so are there any 'concurrent' printk()-s coming from other CPUs > > that are not getting printed on the console (because of loglevel restrictions), > > but still screw up the cont buffer?.... otherwise, my expectation was that in > > this particular case cpu issues a new pr_cont() only after it has printed > > the current message via call_console_drivers()->write(). so partially flushed > > cont buffer was not really expected to happen. I was wrong, obviously. > > To be honest. I am not 100% sure what happens here. One theory is > that the printk kthread is waken because of some previous > non-continuous message. It steals console_lock() and partially flushes > the cont buffer. In this case, the pr_cont() calls are not able to get > console_lock() and basically work in the async mode. The pr_cont() > calls have to store each piece sepatately because the partially > flushed cont buffer is blocked until flushed completely. > > Hmm, the strange thing is that I see this problem even when I force > the global synch more by > > echo Y > /sys/module/printk/parameters/synchronous oh, even in sync mode. hm... > > just an idea. > > ... or try to make KERN_CONT SMP-safe. there are many pr_cont() call > > sites. ACPI is one notable example. the others include OOM, some cgroup > > related output (or... was it memcg), etc., etc. > > > > so we *may be* can have a per-cpu cont buffer and add new API > > pr_cont_begin()/pr_cont_end(), that would disable preemption. > > > > > > + pr_cont_begin() /* preempt_disable() */ > > > > for (.....) > > pr_cont("%pS ....); > > > > + pr_cont_end() /* preempt_enable() */ > > > > pr_cont_end() also can flush this CPU's cont buffer and store the log > > line. this will probably break very long cont lines (not sure if we > > have any of those though). and may be flush_on_panic() would have to > > do some extra work iterating each cpu. > > It would work but I am a bit scared by the complexity. I think > that we should find a compromise between complexity and > reliability. I understand your concerns. but, realistically, KERN_CONT will still be SMP unsafe and will not do what people probably expect it to do: e.g. ACPI_ERROR or ACPI_anything. it does acpi_os_vprintf() -> printk(KERN_CONT). the whole thing is already complicated, we already have all those len, cons etc. checks in various places, it also has that owner task, etc. static struct cont { char buf[LOG_LINE_MAX]; size_t len; /* length == 0 means unused buffer */ size_t cons; /* bytes written to console */ struct task_struct *owner; /* task of first print*/ u64 ts_nsec; /* time of first print */ u8 level; /* log level of first message */ u8 facility; /* log facility of first message */ enum log_flags flags; /* prefix, newline flags */ bool flushed:1; /* buffer sealed and committed */ } cont; so I think, personally... it's sort of kind of not exactly what people need (aka 'broken'). so my idea is to forbid concurrent cont buffer usage. each CPU will have it's own buffer, and touch it with preemption_disabled. there will be no more partial flushes, cont buffer will be flushed when it's done -- via pr_cont_end()->log_store()->wake_up(printk_kthread). IOW it will just add the cont buffer content to log_buf and print it via console_unlock(), like the rest of the messages. no more console_cont_flush(). > > we still can have pr_cont() happening on several cpus simultaneously. > > console_seq is getting reset, when we register a new CON_PRINTBUFFER > > console. > > I agree that mixing part of lines from different processes/cpus > is not ideal. But it is not much worse than mixing whole lines. > We should do a best effort but we do not need to be perfect. sure, thanks! I'll try to think of something other than "throw it away". but.., well, you know my opinion by now :) -ss ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-13 13:24 ` Sergey Senozhatsky @ 2016-07-13 14:22 ` Petr Mladek 0 siblings, 0 replies; 25+ messages in thread From: Petr Mladek @ 2016-07-13 14:22 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park On Wed 2016-07-13 22:24:38, Sergey Senozhatsky wrote: > Hello, > > On (07/13/16 13:14), Petr Mladek wrote: > [..] > > > > [ 4913.000310] item8750item8751item8752item8753item8754item8755item8756item8757item8758item8759 > > > > [ 4913.000327] item8760item8761item8762item8763item8764item8765item8766item8767item8768item8769 > > > > [ 4913.000342] item8770item8771item8772item8773item8774item8775item8776item8777item8778item8779 > > > > [ 4913.000356] item8780 > > > > [ 4913.000357] item8781 > > > > [ 4913.000358] item8782 > > > > [...] > > > > > > hm.. so are there any 'concurrent' printk()-s coming from other CPUs > > > that are not getting printed on the console (because of loglevel restrictions), > > > but still screw up the cont buffer?.... otherwise, my expectation was that in > > > this particular case cpu issues a new pr_cont() only after it has printed > > > the current message via call_console_drivers()->write(). so partially flushed > > > cont buffer was not really expected to happen. I was wrong, obviously. > > > > To be honest. I am not 100% sure what happens here. One theory is > > that the printk kthread is waken because of some previous > > non-continuous message. It steals console_lock() and partially flushes > > the cont buffer. In this case, the pr_cont() calls are not able to get > > console_lock() and basically work in the async mode. The pr_cont() > > calls have to store each piece sepatately because the partially > > flushed cont buffer is blocked until flushed completely. > > > > Hmm, the strange thing is that I see this problem even when I force > > the global synch more by > > > > echo Y > /sys/module/printk/parameters/synchronous > > oh, even in sync mode. hm... It seems that the rsyslogd daemon steps in. I have dumped all processes that called console_cont_flush() and really flushed something. It was mostly the process that triggered the test for-cycle and called console_unlock() from every pr_cont the syncronous way. But there was the following sinner from time to time: rs:main Q:Reg-771 [001] d... 87486.753353: console_unlock: rs:main Q:Reg calling console_cont_flush rs:main Q:Reg-771 [001] d... 87486.753360: <stack trace> => console_unlock => do_con_write.part.22 => con_write => do_output_char => n_tty_write => tty_write => __vfs_write => vfs_write => SyS_write => entry_SYSCALL_64_fastpath It means that some other process does console_unlock() and blocks using the cont buffer. I am not sure what is the exact purpose of this syscall. But it seems reasonable that rsystemlog is active when there is some activity in the kernel log buffer. > > > just an idea. > > > ... or try to make KERN_CONT SMP-safe. there are many pr_cont() call > > > sites. ACPI is one notable example. the others include OOM, some cgroup > > > related output (or... was it memcg), etc., etc. > > > > > > so we *may be* can have a per-cpu cont buffer and add new API > > > pr_cont_begin()/pr_cont_end(), that would disable preemption. > > > > > > > > > + pr_cont_begin() /* preempt_disable() */ > > > > > > for (.....) > > > pr_cont("%pS ....); > > > > > > + pr_cont_end() /* preempt_enable() */ > > > > > > pr_cont_end() also can flush this CPU's cont buffer and store the log > > > line. this will probably break very long cont lines (not sure if we > > > have any of those though). and may be flush_on_panic() would have to > > > do some extra work iterating each cpu. > > > > It would work but I am a bit scared by the complexity. I think > > that we should find a compromise between complexity and > > reliability. > > I understand your concerns. > but, realistically, KERN_CONT will still be SMP unsafe and will not do > what people probably expect it to do: e.g. ACPI_ERROR or ACPI_anything. > it does acpi_os_vprintf() -> printk(KERN_CONT). > > the whole thing is already complicated, we already have all those len, > cons etc. checks in various places, it also has that owner task, etc. > > static struct cont { > char buf[LOG_LINE_MAX]; > size_t len; /* length == 0 means unused buffer */ > size_t cons; /* bytes written to console */ > struct task_struct *owner; /* task of first print*/ > u64 ts_nsec; /* time of first print */ > u8 level; /* log level of first message */ > u8 facility; /* log facility of first message */ > enum log_flags flags; /* prefix, newline flags */ > bool flushed:1; /* buffer sealed and committed */ > } cont; > > so I think, personally... it's sort of kind of not exactly what people > need (aka 'broken'). so my idea is to forbid concurrent cont buffer usage. > each CPU will have it's own buffer, and touch it with preemption_disabled. > there will be no more partial flushes, cont buffer will be flushed when it's > done -- via pr_cont_end()->log_store()->wake_up(printk_kthread). IOW it will > just add the cont buffer content to log_buf and print it via console_unlock(), > like the rest of the messages. no more console_cont_flush(). I think that people primary wants to have the messages stored in the log buffer and visible on the console. Also they expect that printk will be an easy interface. Any more complicated code and more temporary buffers will increase the risk that a message will get lost somewhere and it will be hard to dig it from a crashdump, ... I would be great to get a perfect log. But I am afraid that we would need to redesign the printk code first to keep it maintainable. I am still thinking if we could do better with the single cont buffer. BTW: I think that the LOG_CONT/LOG_PREFIX/LOG_NEWLINE informations are stored correctly in the ring buffer. I think that dmesg could do a better job when showing parts of the continuous messages that are were stored separately. Best Regards, Petr ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-05-13 13:18 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky 2016-06-09 2:20 ` Sergey Senozhatsky 2016-06-29 5:08 ` Sergey Senozhatsky @ 2016-07-11 19:25 ` Viresh Kumar 2016-07-12 15:59 ` Petr Mladek 2 siblings, 1 reply; 25+ messages in thread From: Viresh Kumar @ 2016-07-11 19:25 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Andrew Morton, Jan Kara, Petr Mladek, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Fri, May 13, 2016 at 6:18 AM, Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote: > Hello, > > no code changes, just refreshing the series so it'll be easier to > pick up. added Reviwed-by-s and corrected a typo spotted by Petr. > > This patch permits to change printk() to operate in completely > asynchronous mode: new messages are getting upended to the kernel > printk buffer, but instead of 'direct' printing the actual print > job is performed by a dedicated kthread. This has the advantage > that printing always happens from a schedulable context and thus > we don't lockup any particular CPU or even interrupts. > > against next-20160513 > > > v12: > -- rename printk_kthread_can_run bool flag > -- update printk_kthread_can_run comment (Petr) > -- drop mutex from printk_sync_set(), sysfs writes are synchronised (Petr) We were also screwed because of the problem this thread is trying to solve, which I posted last week [1]. And then I found this thread which fixed my issue, thanks a lot guys :) Tested-by: Viresh Kumar <viresh.kumar@linaro.org> Though, I would also like to mention one unwanted thing that happened on my setup :) [ 12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0) [ 12.874909] potential CPU hogs: [ 12.874909] printk (292) On my system, the excessive printing happens during suspend/resume and this happened after all the non-boot CPUs were offlined. So, only CPU 0 was left and that was doing printing for a long time and so these errors :) It resulted in missing some print messages eventually as the scheduler probably didn't schedule this thread for sometime after that. Will it be fine to get the priority of this kthread to a somewhat lower value, etc ? -- viresh [1] http://marc.info/?l=linux-kernel&m=146739243615687 ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-11 19:25 ` Viresh Kumar @ 2016-07-12 15:59 ` Petr Mladek 2016-07-12 16:46 ` Sergey Senozhatsky 2016-07-12 17:04 ` Viresh Kumar 0 siblings, 2 replies; 25+ messages in thread From: Petr Mladek @ 2016-07-12 15:59 UTC (permalink / raw) To: Viresh Kumar Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Mon 2016-07-11 12:25:11, Viresh Kumar wrote: > On Fri, May 13, 2016 at 6:18 AM, Sergey Senozhatsky > <sergey.senozhatsky@gmail.com> wrote: > > Hello, > > > > no code changes, just refreshing the series so it'll be easier to > > pick up. added Reviwed-by-s and corrected a typo spotted by Petr. > > > > This patch permits to change printk() to operate in completely > > asynchronous mode: new messages are getting upended to the kernel > > printk buffer, but instead of 'direct' printing the actual print > > job is performed by a dedicated kthread. This has the advantage > > that printing always happens from a schedulable context and thus > > we don't lockup any particular CPU or even interrupts. > > > > against next-20160513 > > > > > > v12: > > -- rename printk_kthread_can_run bool flag > > -- update printk_kthread_can_run comment (Petr) > > -- drop mutex from printk_sync_set(), sysfs writes are synchronised (Petr) > > We were also screwed because of the problem this thread is trying to solve, > which I posted last week [1]. > > And then I found this thread which fixed my issue, thanks a lot guys :) > > Tested-by: Viresh Kumar <viresh.kumar@linaro.org> > > Though, I would also like to mention one unwanted thing that happened on > my setup :) > > [ 12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0) > [ 12.874909] potential CPU hogs: > [ 12.874909] printk (292) > > On my system, the excessive printing happens during suspend/resume and this > happened after all the non-boot CPUs were offlined. So, only CPU 0 was left and > that was doing printing for a long time and so these errors :) > > It resulted in missing some print messages eventually as the scheduler probably > didn't schedule this thread for sometime after that. > > Will it be fine to get the priority of this kthread to a somewhat lower value, > etc ? I think that this patch helped only by chance. It causes that any message without a new line will force printk to the sync mode. Then it will print even the buffered messages immediately. It causes printk to behave more or less in the sync mode all the time. I am still scratching my head about the problem fixed by this patch and also about suspend problems. Best Regards, Petr ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-12 15:59 ` Petr Mladek @ 2016-07-12 16:46 ` Sergey Senozhatsky 2016-07-12 17:04 ` Viresh Kumar 1 sibling, 0 replies; 25+ messages in thread From: Sergey Senozhatsky @ 2016-07-12 16:46 UTC (permalink / raw) To: Petr Mladek Cc: Viresh Kumar, Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On (07/12/16 17:59), Petr Mladek wrote: [..] > > [ 12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0) > > [ 12.874909] potential CPU hogs: > > [ 12.874909] printk (292) > > > > On my system, the excessive printing happens during suspend/resume and this > > happened after all the non-boot CPUs were offlined. So, only CPU 0 was left and > > that was doing printing for a long time and so these errors :) > > > > It resulted in missing some print messages eventually as the scheduler probably > > didn't schedule this thread for sometime after that. > > > > Will it be fine to get the priority of this kthread to a somewhat lower value, > > etc ? > > I think that this patch helped only by chance. It causes that any > message without a new line will force printk to the sync mode. > Then it will print even the buffered messages immediately. It > causes printk to behave more or less in the sync mode all the time. KERN_CONT messages are not so often, because they are not SMP-safe, any intruding non-KERN_CONT message will wake_up() printk_kthread. there is a chance, you are right, that printk will operate in sync mode for some time, when we would want it to be async, so 0004 probably better try harder. but KERN_CONT is not what's going on in this case, I think. at lest "[ 12.874909] printk (292)" line suggests so -- printk was in async mode... and somehow non-preemptible for some time... a delay from spin_lock() in call_console_drivers()->write()?... but why would async printk worsen it. > I am still scratching my head about the problem fixed by this patch > and also about suspend problems. yeah, quite puzzled myself. thanks Petr and Viresh for digging this up. I need some sleep now, it's 2 am here, will return back tomorrow. -ss ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-12 15:59 ` Petr Mladek 2016-07-12 16:46 ` Sergey Senozhatsky @ 2016-07-12 17:04 ` Viresh Kumar 2016-07-13 11:19 ` Petr Mladek 1 sibling, 1 reply; 25+ messages in thread From: Viresh Kumar @ 2016-07-12 17:04 UTC (permalink / raw) To: Petr Mladek Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On 12-07-16, 17:59, Petr Mladek wrote: > On Mon 2016-07-11 12:25:11, Viresh Kumar wrote: > > We were also screwed because of the problem this thread is trying to solve, > > which I posted last week [1]. > > > > And then I found this thread which fixed my issue, thanks a lot guys :) > > > > Tested-by: Viresh Kumar <viresh.kumar@linaro.org> > > > > Though, I would also like to mention one unwanted thing that happened on > > my setup :) > > > > [ 12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0) > > [ 12.874909] potential CPU hogs: > > [ 12.874909] printk (292) > > > > On my system, the excessive printing happens during suspend/resume and this > > happened after all the non-boot CPUs were offlined. So, only CPU 0 was left and > > that was doing printing for a long time and so these errors :) > > > > It resulted in missing some print messages eventually as the scheduler probably > > didn't schedule this thread for sometime after that. > > > > Will it be fine to get the priority of this kthread to a somewhat lower value, > > etc ? > > I think that this patch helped only by chance. Sorry got confused a bit here.. Which patch are you taking about here ? As you replied below my message, I believe that you are talking about the 3 patches that were posted in this series. But the rest of your comment looks like the fourth fixup patch that Sergey shared :) So, the fixup patch doesn't fix any issues in my case, to make it clear. I still have my system hanging somewhere. > I am still scratching my head about the problem fixed by this patch > and also about suspend problems. :) -- viresh ^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v12 0/3] printk: Make printk() completely async 2016-07-12 17:04 ` Viresh Kumar @ 2016-07-13 11:19 ` Petr Mladek 0 siblings, 0 replies; 25+ messages in thread From: Petr Mladek @ 2016-07-13 11:19 UTC (permalink / raw) To: Viresh Kumar Cc: Sergey Senozhatsky, Andrew Morton, Jan Kara, Tejun Heo, Tetsuo Handa, linux-kernel, Byungchul Park, Sergey Senozhatsky On Tue 2016-07-12 10:04:59, Viresh Kumar wrote: > On 12-07-16, 17:59, Petr Mladek wrote: > > On Mon 2016-07-11 12:25:11, Viresh Kumar wrote: > > > We were also screwed because of the problem this thread is trying to solve, > > > which I posted last week [1]. > > > > > > And then I found this thread which fixed my issue, thanks a lot guys :) > > > > > > Tested-by: Viresh Kumar <viresh.kumar@linaro.org> > > > > > > Though, I would also like to mention one unwanted thing that happened on > > > my setup :) > > > > > > [ 12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0) > > > [ 12.874909] potential CPU hogs: > > > [ 12.874909] printk (292) > > > > > > On my system, the excessive printing happens during suspend/resume and this > > > happened after all the non-boot CPUs were offlined. So, only CPU 0 was left and > > > that was doing printing for a long time and so these errors :) > > > > > > It resulted in missing some print messages eventually as the scheduler probably > > > didn't schedule this thread for sometime after that. > > > > > > Will it be fine to get the priority of this kthread to a somewhat lower value, > > > etc ? > > > > I think that this patch helped only by chance. > > Sorry got confused a bit here.. > > Which patch are you taking about here ? As you replied below my > message, I believe that you are talking about the 3 patches that were > posted in this series. But the rest of your comment looks like the > fourth fixup patch that Sergey shared :) You are right. I was talking about the 4th patch. It was sent as another reply to this mail. I thought the 4th patch solved your problems with missing messages during the suspend. > So, the fixup patch doesn't fix any issues in my case, to make it > clear. I still have my system hanging somewhere. I see. Thanks for clarification and I am sorry for the confusion. Best Regards, Petr ^ permalink raw reply [flat|nested] 25+ messages in thread
end of thread, other threads:[~2016-07-13 14:22 UTC | newest] Thread overview: 25+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2016-04-22 13:52 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky 2016-04-22 13:52 ` [PATCH v12 1/3] " Sergey Senozhatsky 2016-04-26 14:13 ` Petr Mladek 2016-04-22 13:52 ` [PATCH v12 2/3] printk: Make wake_up_klogd_work_func() async Sergey Senozhatsky 2016-04-22 13:53 ` [PATCH v12 3/3] printk: make printk.synchronous param rw Sergey Senozhatsky 2016-04-23 6:56 ` Jan Kara 2016-04-23 8:26 ` Sergey Senozhatsky 2016-04-23 15:01 ` [PATCH] " Sergey Senozhatsky 2016-04-26 14:15 ` Petr Mladek 2016-04-27 1:09 ` Sergey Senozhatsky 2016-05-13 13:18 [PATCH v12 0/3] printk: Make printk() completely async Sergey Senozhatsky 2016-06-09 2:20 ` Sergey Senozhatsky 2016-06-29 5:08 ` Sergey Senozhatsky 2016-06-29 5:16 ` Joe Perches 2016-06-29 5:32 ` Sergey Senozhatsky 2016-07-12 16:28 ` Petr Mladek 2016-07-13 7:42 ` Sergey Senozhatsky 2016-07-13 11:14 ` Petr Mladek 2016-07-13 13:24 ` Sergey Senozhatsky 2016-07-13 14:22 ` Petr Mladek 2016-07-11 19:25 ` Viresh Kumar 2016-07-12 15:59 ` Petr Mladek 2016-07-12 16:46 ` Sergey Senozhatsky 2016-07-12 17:04 ` Viresh Kumar 2016-07-13 11:19 ` Petr Mladek
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).