Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1711786 > unrolled thread

[RFC][PATCHv5 00/13] printk: introduce printing kernel thread

Back to article view | Back to linux.kernel

Contents

  [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:00 +0200
    [RFC][PATCHv5 12/13] printk: do not cond_resched() when we can offload Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 10/13] printk: force printk_kthread to offload printing Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 04/13] printk: add enforce_emergency parameter Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 07/13] printk: register syscore notifier Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
      Re: [RFC][PATCHv5 07/13] printk: register syscore notifier "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-08-15 14:10 +0200
        Re: [RFC][PATCHv5 07/13] printk: register syscore notifier Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-16 09:00 +0200
          Re: [RFC][PATCHv5 07/13] printk: register syscore notifier "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-08-16 15:10 +0200
    [RFC][PATCHv5 11/13] printk: always offload printing from user-space processes Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 05/13] printk: enable printk offloading Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 01/13] printk: move printk_pending out of per-cpu Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 02/13] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 08/13] printk: set watchdog_thresh as maximum value for atomic_print_limit Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 03/13] printk: add sync printk_emergency API Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 09/13] printk: add auto-emergency enforcement mechanism Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 13/13] printk: move offloading logic to per-cpu Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
    [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-15 05:10 +0200
      Re: [RFC][PATCHv5 06/13] printk: register PM notifier "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-08-15 14:00 +0200
        Re: [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-16 09:40 +0200
          Re: [RFC][PATCHv5 06/13] printk: register PM notifier "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-08-16 15:10 +0200
            Re: [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-17 08:00 +0200
              Re: [RFC][PATCHv5 06/13] printk: register PM notifier "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-08-17 18:00 +0200
                Re: [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-18 01:20 +0200
    Re: [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-23 10:40 +0200

Page 1 of 2  [1] 2  Next page →

#1711786 — [RFC][PATCHv5 00/13] printk: introduce printing kernel thread

Hello,

        RFC

        This patch set adds a printk() kernel thread which let us
to print kernel messages to the console from a non-atomic/schedule-able
context, avoiding different sort of lockups, stalls, etc.

        Offloading threshold is now in "seconds spent in console_unlock()",
not in "lines printed", this lets us to be a little bit more 'watchdog-aware'
in printk. But we still can (and probably must) do better, tho. May be there
will be a new watchdog API some day, so will be able to make better decisions
in printk.

        And a whole bunch of other improvements and tweaks. Like preemption
in console_unlock(), and so on. Any comments and thoughts are appreciated.


v4->v5
-- split some of the patches
-- make offloading time-based (not number of lines printed)
-- move offloading control to per-CPU
-- remove a pessimistic offloading spin from console_unlock()
-- adjust printk_kthread CPU affinity mask
-- disable preemption in console_unlock()
-- always offload printing from user space processes
-- add sync version of emergency_begin API
-- offload from printk_kthread as well, to periodically up() console_sem
-- limit `atomic_print_limit' to `watchdog_thresh'
-- and some other changes...

v3->v4 (Petr, Jan)
-- add syscore notifiers
-- fix 0001 compilation warnings
-- use proper CPU notifiers return values

v2->v3 (Petr, Pavel, Andreas):
-- rework offloading
-- use PM notifiers
-- dropped some patches, etc. etc.

v1->v2:
-- introduce printk_emergency mode and API to switch it on/off
-- move printk_pending out of per-CPU memory
-- add printk emergency_mode sysfs node
-- switch sysrq handlers (some of them) to printk_emergency
-- cleanus/etc.

Sergey Senozhatsky (13):
  printk: move printk_pending out of per-cpu
  printk: introduce printing kernel thread
  printk: add sync printk_emergency API
  printk: add enforce_emergency parameter
  printk: enable printk offloading
  printk: register PM notifier
  printk: register syscore notifier
  printk: set watchdog_thresh as maximum value for atomic_print_limit
  printk: add auto-emergency enforcement mechanism
  printk: force printk_kthread to offload printing
  printk: always offload printing from user-space processes
  printk: do not cond_resched() when we can offload
  printk: move offloading logic to per-cpu

 Documentation/admin-guide/kernel-parameters.txt |  17 +
 include/linux/console.h                         |   5 +
 kernel/printk/printk.c                          | 435 ++++++++++++++++++++++--
 3 files changed, 433 insertions(+), 24 deletions(-)

-- 
2.14.1

[toc] | [next] | [standalone]

#1711787 — [RFC][PATCHv5 12/13] printk: do not cond_resched() when we can offload

console_unlock() may sleep with console_sem locked, which is a bit
counter intuitive: we neither print pending logbuf messages to the
serial console, nor let anyone else to do it for us.

With printing offloading enabled, however, we can disable preemption,
because we know for sure how long we can stay in console_unlock() and
that eventually we will offload to another task.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 15 ++++++++++++++-
 1 file changed, 14 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0ffbaa33280f..ba82152ce5d9 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2432,6 +2432,14 @@ void console_unlock(void)
 	 * and cleared after the the "again" goto label.
 	 */
 	do_cond_resched = console_may_schedule;
+	/*
+	 * Forbid scheduling under the console_sem lock when offloading
+	 * is enabled. Scheduling will just slow down the print out in
+	 * this case.
+	 */
+	if (printk_offloading_enabled() && is_printk_offloading_safe())
+		do_cond_resched = 0;
+
 again:
 	console_may_schedule = 0;
 
@@ -2447,6 +2455,7 @@ void console_unlock(void)
 		return;
 	}
 
+	preempt_disable();
 	for (;;) {
 		struct printk_log *msg;
 		size_t ext_len = 0;
@@ -2507,8 +2516,11 @@ void console_unlock(void)
 		start_critical_timings();
 		printk_safe_exit_irqrestore(flags);
 
-		if (do_cond_resched)
+		if (do_cond_resched) {
+			preempt_enable();
 			cond_resched();
+			preempt_disable();
+		}
 	}
 	console_locked = 0;
 
@@ -2518,6 +2530,7 @@ void console_unlock(void)
 
 	raw_spin_unlock(&logbuf_lock);
 
+	preempt_enable();
 	up_console_sem();
 
 	/*
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711788 — [RFC][PATCHv5 10/13] printk: force printk_kthread to offload printing

As of now we don't `offload' printing from printk_kthread and
print all pending logbuf messages. This, however, may have a
negative effect. We still hold console_sem as long as we have
got messages to print, and there might be other console_lock()
callers sleeping on console_sem in TASK_UNINTERRUPTIBLE,
including user space processes (tty_open, drm IOCTL, etc.).
So we need to up() console_sem every once in a while, even if
current console_sem owner is printk_kthread, just in order to
wake up those other processes that can sleep on console_sem.

If there are no tasks skeeping on console_sem, then printk_kthread
will immediately return back to console_unclok(), because we don't
clear the PRINTK_PENDING_OUTPUT bit and printk_kthread checks it
before it decides to schedule().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 22 ++++++++++++++++++----
 1 file changed, 18 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 71950bd85eac..6da4e21c3b45 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -600,15 +600,29 @@ static inline bool console_offload_printing(void)
 		return false;
 	}
 
-	/* Once we offloaded to printk_ktread - keep printing */
-	if (current == printk_kthread)
-		return false;
-
 	adj_atomic_print_limit();
 
 	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
 		return false;
 
+	if (current == printk_kthread) {
+		/*
+		 * All tasks are equal, all tasks must offload. However,
+		 * printk_kthread may be the only process left willing to
+		 * down(). So we may return here immediately after we leave,
+		 * because of positive PRINTK_PENDING_OUTPUT check in
+		 * printk_kthread_func() loop. However, we obviously don't
+		 * want to declare printk emergency in this case, so that's
+		 * why we update `printing_start_ts' here.
+		 *
+		 * In case if `printk_kthread' will immediately return
+		 * back to console_unlock(), it will have another full
+		 * `atomic_print_limit' time slice.
+		 */
+		printing_start_ts = local_clock() >> 30LL;
+		return true;
+	}
+
 	/*
 	 * A trivial emergency enforcement - give up on printk_kthread if
 	 * we can't wake it up.
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711789 — [RFC][PATCHv5 04/13] printk: add enforce_emergency parameter

This param permits user-space to forcibly on/off printk emergency
mode via `/sys/module/printk/parameters/enforce_emergency' node.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 Documentation/admin-guide/kernel-parameters.txt | 7 +++++++
 kernel/printk/printk.c                          | 8 +++++++-
 2 files changed, 14 insertions(+), 1 deletion(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index b5b6d5d24596..001f578ec5f5 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3215,6 +3215,13 @@
 
 			default: off.
 
+	printk.enforce_emergency=
+			This parameter allows to disable/enable printing
+			offloading to printk kthread.
+			Format: <bool> (1 - emergency, 0 - permit offloading).
+
+			default: off.
+
 	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 5d4b4beeebf5..3a0e78812818 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -455,9 +455,15 @@ static cpumask_var_t printk_offload_cpus;
 static atomic_t printk_emergency __read_mostly;
 /*
  * Disable printk_kthread permanently. Unlike `oops_in_progress'
- * it doesn't go back to 0.
+ * it doesn't go back to 0 (unless set by user-space).
  */
 static bool printk_enforce_emergency __read_mostly;
+
+module_param_named(enforce_emergency, printk_enforce_emergency,
+		    bool, 0644);
+MODULE_PARM_DESC(printk_enforce_emergency,
+		 "don't offload message printing to printk kthread");
+
 /*
  * The number of seconds a task can print before it offloads printing
  * duty to printk_kthread. 0 indicates 'no limit'.
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711790 — [RFC][PATCHv5 07/13] printk: register syscore notifier

We need to switch to emergency printk mode in kernel_kexec(). One
kernel_kexec() branch calls kernel_restart_prepare(), which updates
`system_state', however, the other one, when user requested to
->preserve_context, does not and we are lacking the information
in printk about kexec being executed. Register a syscore notifier
so printk will be notified by syscore_suspend().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 19 +++++++++++++++++++
 1 file changed, 19 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d3f149fad85c..b14e35f94596 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -50,6 +50,7 @@
 #include <linux/sched/task_stack.h>
 #include <linux/kthread.h>
 #include <linux/suspend.h>
+#include <linux/syscore_ops.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -2941,6 +2942,22 @@ static struct notifier_block printk_pm_nb = {
 	.notifier_call = printk_pm_notify,
 };
 
+static int printk_syscore_suspend(void)
+{
+	printk_emergency_begin();
+	return 0;
+}
+
+static void printk_syscore_resume(void)
+{
+	printk_emergency_end();
+}
+
+static struct syscore_ops printk_syscore_ops = {
+	.suspend = printk_syscore_suspend,
+	.resume = printk_syscore_resume,
+};
+
 static int printk_kthread_func(void *data)
 {
 	while (1) {
@@ -2994,6 +3011,8 @@ static int __init init_printk_kthread(void)
 		return -EINVAL;
 	}
 
+	register_syscore_ops(&printk_syscore_ops);
+
 	thread = kthread_run(printk_kthread_func, NULL, "printk");
 	if (IS_ERR(thread)) {
 		pr_err("printk: unable to create printing thread\n");
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1712126 — Re: [RFC][PATCHv5 07/13] printk: register syscore notifier

On Tuesday, August 15, 2017 4:56:19 AM CEST Sergey Senozhatsky wrote:
> We need to switch to emergency printk mode in kernel_kexec(). One
> kernel_kexec() branch calls kernel_restart_prepare(), which updates
> `system_state', however, the other one, when user requested to
> ->preserve_context, does not and we are lacking the information
> in printk about kexec being executed. Register a syscore notifier
> so printk will be notified by syscore_suspend().
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 19 +++++++++++++++++++
>  1 file changed, 19 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index d3f149fad85c..b14e35f94596 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -50,6 +50,7 @@
>  #include <linux/sched/task_stack.h>
>  #include <linux/kthread.h>
>  #include <linux/suspend.h>
> +#include <linux/syscore_ops.h>
>  
>  #include <linux/uaccess.h>
>  #include <asm/sections.h>
> @@ -2941,6 +2942,22 @@ static struct notifier_block printk_pm_nb = {
>  	.notifier_call = printk_pm_notify,
>  };
>  
> +static int printk_syscore_suspend(void)
> +{
> +	printk_emergency_begin();
> +	return 0;
> +}

Somebody looking at suspend/resume code paths only will be wondering why
you need this, because we should be in the emergency mode already when
it is called.

It would be good to add a comment about the kexec context here.

> +
> +static void printk_syscore_resume(void)
> +{
> +	printk_emergency_end();
> +}

This will turn the emergency mode off during resume before the notifier
added by the previous patch AFAICS.  Is this intentional?

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

#1712720 — Re: [RFC][PATCHv5 07/13] printk: register syscore notifier

On (08/15/17 13:56), Rafael J. Wysocki wrote:
[..]
> > +static int printk_syscore_suspend(void)
> > +{
> > +	printk_emergency_begin();
> > +	return 0;
> > +}
> 
> Somebody looking at suspend/resume code paths only will be wondering why
> you need this, because we should be in the emergency mode already when
> it is called.
> 
> It would be good to add a comment about the kexec context here.

ok, will add.

> > +static void printk_syscore_resume(void)
> > +{
> > +	printk_emergency_end();
> > +}
> 
> This will turn the emergency mode off during resume before the notifier
> added by the previous patch AFAICS.  Is this intentional?

emergency modes can nest. so it's OK to have

	printk_emergency_begin()   +1   // on
	  printk_emergency_begin()   +1
	  printk_emergency_end()     -1
	printk_emergency_end()     -1   // off

or did I misunderstand your question?

	-ss

[toc] | [prev] | [next] | [standalone]

#1712929 — Re: [RFC][PATCHv5 07/13] printk: register syscore notifier

On Wednesday, August 16, 2017 8:55:45 AM CEST Sergey Senozhatsky wrote:
> On (08/15/17 13:56), Rafael J. Wysocki wrote:
> [..]
> > > +static int printk_syscore_suspend(void)
> > > +{
> > > +	printk_emergency_begin();
> > > +	return 0;
> > > +}
> > 
> > Somebody looking at suspend/resume code paths only will be wondering why
> > you need this, because we should be in the emergency mode already when
> > it is called.
> > 
> > It would be good to add a comment about the kexec context here.
> 
> ok, will add.
> 
> > > +static void printk_syscore_resume(void)
> > > +{
> > > +	printk_emergency_end();
> > > +}
> > 
> > This will turn the emergency mode off during resume before the notifier
> > added by the previous patch AFAICS.  Is this intentional?
> 
> emergency modes can nest. so it's OK to have
> 
> 	printk_emergency_begin()   +1   // on
> 	  printk_emergency_begin()   +1
> 	  printk_emergency_end()     -1
> 	printk_emergency_end()     -1   // off
> 

OK then.

Thanks,
Rafel

[toc] | [prev] | [next] | [standalone]

#1711791 — [RFC][PATCHv5 11/13] printk: always offload printing from user-space processes

console_lock() and, thus, console_unlock() can be executed by
user-space processes doing sys calls (e.g. tty, drm, etc.) so we
may end up in a situation when systemd loops in console_unlock()
printing kernel messages. Always offload printing duty from
user-space process (if we can safely wake up printk_kthread,
of course).

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6da4e21c3b45..0ffbaa33280f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -592,6 +592,13 @@ static inline bool console_offload_printing(void)
 	if (!is_printk_offloading_safe())
 		return false;
 
+	/*
+	 * Always offload from user-space processes, we've got printk kthread
+	 * for printing.
+	 */
+	if (!(current->flags & PF_KTHREAD))
+		goto offload;
+
 	/* A new task - reset the counters. */
 	if (printing_task != current) {
 		printing_start_ts = local_clock() >> 30LL;
@@ -634,6 +641,7 @@ static inline bool console_offload_printing(void)
 		return true;
 	}
 
+offload:
 	/*
 	 * We try to set `printk_kthread' CPU affinity to any online CPU
 	 * except for this_cpu. Because otherwise `printk_kthread' may be
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711793 — [RFC][PATCHv5 05/13] printk: enable printk offloading

Initialize kernel printing thread and make printk offloading
possible. By default `atomic_print_limit' is set to 0, so no
offloading will take place, unless requested by user.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 59 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 59 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 3a0e78812818..05165f008bc8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2913,6 +2913,65 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static int printk_kthread_func(void *data)
+{
+	while (1) {
+		set_current_state(TASK_INTERRUPTIBLE);
+		/*
+		 * We must check `printk_emergency' as well, to let
+		 * printk_emergency_begin() stop active `printk_kthread' at
+		 * some point. Otherwise we can end up in a loop:
+		 *   - we bail out of console_unlock() because of
+		 *     printk_kthread_should_stop()
+		 * and
+		 *   - don't schedule() and attempt to return back
+		 *     immediately to console_unlock() because we
+		 *     see PRINTK_PENDING_OUTPUT bit set.
+		 */
+		if (!test_bit(PRINTK_PENDING_OUTPUT, &printk_pending) ||
+				atomic_read(&printk_emergency) != 0)
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+
+		/* We might have been woken for stop */
+		if (kthread_should_park())
+			kthread_parkme();
+
+		console_lock();
+		console_unlock();
+
+		/* We might have been blocked on console_sem */
+		if (kthread_should_park())
+			kthread_parkme();
+	}
+
+	return 0;
+}
+
+/*
+ * Init printk kthread at late_initcall stage, after core/arch/device/etc.
+ * initialization.
+ */
+static int __init init_printk_kthread(void)
+{
+	struct task_struct *thread;
+
+	if (!alloc_cpumask_var(&printk_offload_cpus, GFP_KERNEL))
+		return -ENOMEM;
+
+	thread = kthread_run(printk_kthread_func, NULL, "printk");
+	if (IS_ERR(thread)) {
+		pr_err("printk: unable to create printing thread\n");
+		free_cpumask_var(printk_offload_cpus);
+		return PTR_ERR(thread);
+	}
+
+	printk_kthread = thread;
+	return 0;
+}
+late_initcall(init_printk_kthread);
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711794 — [RFC][PATCHv5 01/13] printk: move printk_pending out of per-cpu

Do not keep `printk_pending' in per-CPU area. We set the following bits
of printk_pending:
a) PRINTK_PENDING_WAKEUP
	when we need to wakeup klogd
b) PRINTK_PENDING_OUTPUT
	when there is a pending output from deferred printk and we need
	to call console_unlock().

So none of the bits control/represent a state of a particular CPU and,
basically, they should be global instead.

Besides we will use `printk_pending' to control printk kthread, so this
patch is also a preparation work.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 26 ++++++++++++--------------
 1 file changed, 12 insertions(+), 14 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 290b548e9fa9..8777003d292e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -401,6 +401,14 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 	} while (0)
 
 #ifdef CONFIG_PRINTK
+/*
+ * Delayed printk version, for scheduler-internal messages:
+ */
+#define PRINTK_PENDING_WAKEUP	0x01
+#define PRINTK_PENDING_OUTPUT	0x02
+
+static unsigned long printk_pending;
+
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
@@ -2688,25 +2696,15 @@ static int __init printk_late_init(void)
 late_initcall(printk_late_init);
 
 #if defined CONFIG_PRINTK
-/*
- * Delayed printk version, for scheduler-internal messages:
- */
-#define PRINTK_PENDING_WAKEUP	0x01
-#define PRINTK_PENDING_OUTPUT	0x02
-
-static DEFINE_PER_CPU(int, printk_pending);
-
 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 (test_and_clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
 		/* If trylock fails, someone else is doing the printing */
 		if (console_trylock())
 			console_unlock();
 	}
 
-	if (pending & PRINTK_PENDING_WAKEUP)
+	if (test_and_clear_bit(PRINTK_PENDING_WAKEUP, &printk_pending))
 		wake_up_interruptible(&log_wait);
 }
 
@@ -2719,7 +2717,7 @@ void wake_up_klogd(void)
 {
 	preempt_disable();
 	if (waitqueue_active(&log_wait)) {
-		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
+		set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
 		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	}
 	preempt_enable();
@@ -2732,7 +2730,7 @@ int vprintk_deferred(const char *fmt, va_list args)
 	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
 
 	preempt_disable();
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	preempt_enable();
 
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711795 — [RFC][PATCHv5 02/13] printk: introduce printing kernel thread

printk() is quite complex internally and, basically, it does two
slightly independent things:
 a) adds a new message to a kernel log buffer (log_store())
 b) prints kernel log messages to serial consoles (console_unlock())

while (a) is guaranteed to be executed by printk(), (b) is not, for a
variety of reasons, and, unlike log_store(), it comes at a price:

 1) console_unlock() attempts to flush all pending kernel log messages
to the console and it can loop indefinitely.

 2) while console_unlock() is executed on one particular CPU, printing
pending kernel log messages, other CPUs can simultaneously append new
messages to the kernel log buffer.

 3) the time it takes console_unlock() to print kernel messages also
depends on the speed of the console -- which may not be fast at all.

 4) console_unlock() is executed in the same context as printk(), so
it may be non-preemptible/atomic, which makes 1)-3) dangerous.

As a result, nobody knows how long a printk() call will take, so
it's not really safe to call printk() in a number of situations,
including atomic context, RCU critical sections, interrupt context,
etc.

This patch introduces a '/sys/module/printk/parameters/atomic_print_limit'
sysfs param, which sets the limit on the number of seconds a given process
can print from console_unlock(). Value 0 corresponds to the current behavior
(no limitation). The printing offloading is happening from console_unlock()
function and, briefly, looks as follows:
	as soon as process prints for more than `atomic_print_limit' seconds
it attempts to offload printing to another process.

Since nothing guarantees that there will another process sleeping on the
console_sem or calling printk() on another CPU simultaneously, the patch
also introduces auxiliary kernel thread - printk_kthread, the main
purpose of which is to take over printing duty. The workflow is, thus,
turns into:
	as soon as process prints for more than `atomic_print_limit' seconds
it wakes up printk_kthread and unlocks the console_sem.

The wakeup part is also a bit tricky, since scheduler is in position to
decide that printk_kthread should run on the very same CPU with the process
that is currently doing printing. This means that offloading potentially
may never take place. That's why we try to play games with printk_kthread
affinity mask and basically want to wake it up on a foreign CPU, so
printing take over has more chances to succeed.

There are, however, cases when we can't (or should not) offload. For
example, we can't call into the scheduler from panic(), because this
may cause deadlock. Therefore printk() has a new 'emergency mode': in
this mode we never attempt to offload printing to printk_kthread.
There are places, where printk switches to printk_emergency mode
automatically: for instance, once a EMERG log level message appears
in the log buffer; in others - user must explicitly forbid offloading.
For that purpose we provide two new functions:

 -- printk_emergency_begin()
    Disables printk offloading. All printk() calls (except for deferred
    printk) will attempt to lock the console_sem and, if successful,
    flush kernel log messages.

 -- printk_emergency_end()
    Enables printk offloading.

Offloading is not possible yet, it will be enabled in a later patch.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 Documentation/admin-guide/kernel-parameters.txt |  10 ++
 include/linux/console.h                         |   3 +
 kernel/printk/printk.c                          | 184 ++++++++++++++++++++++--
 3 files changed, 185 insertions(+), 12 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 35a31ea1d709..b5b6d5d24596 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3205,6 +3205,16 @@
 	printk.time=	Show timing data prefixed to each printk message line
 			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
 
+	printk.atomic_print_limit=
+			Specify the number of seconds a particular task
+			can spend printing messages to the console before
+			it offloads its printing duty to a special printk
+			kthread. Normally the limit should not be larger
+			than watchdog lockup detection threshold. Setting
+			this parameter to 0 disables printing offloading.
+
+			default: off.
+
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
 			max_cstate=9 overrides any DMI blacklist limit.
diff --git a/include/linux/console.h b/include/linux/console.h
index b8920a031a3e..07005db4c788 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -187,6 +187,9 @@ extern bool console_suspend_enabled;
 extern void suspend_console(void);
 extern void resume_console(void);
 
+extern void printk_emergency_begin(void);
+extern void printk_emergency_end(void);
+
 int mda_console_init(void);
 void prom_con_init(void);
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8777003d292e..a86767d4d619 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/kthread.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -400,15 +401,16 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 		printk_safe_exit_irqrestore(flags);	\
 	} while (0)
 
-#ifdef CONFIG_PRINTK
 /*
- * Delayed printk version, for scheduler-internal messages:
+ * Used both for deferred printk version (scheduler-internal messages)
+ * and printk_kthread control.
  */
 #define PRINTK_PENDING_WAKEUP	0x01
 #define PRINTK_PENDING_OUTPUT	0x02
 
 static unsigned long printk_pending;
 
+#ifdef CONFIG_PRINTK
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
@@ -444,6 +446,127 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+static struct task_struct *printk_kthread;
+static cpumask_var_t printk_offload_cpus;
+/*
+ * We can't call into the scheduler (wake_up() printk kthread) during
+ * suspend/kexec/etc. This temporarily switches printk to old behaviour.
+ */
+static atomic_t printk_emergency __read_mostly;
+/*
+ * Disable printk_kthread permanently. Unlike `oops_in_progress'
+ * it doesn't go back to 0.
+ */
+static bool printk_enforce_emergency __read_mostly;
+/*
+ * The number of seconds a task can print before it offloads printing
+ * duty to printk_kthread. 0 indicates 'no limit'.
+ */
+static unsigned int atomic_print_limit;
+
+module_param_named(atomic_print_limit, atomic_print_limit, uint, 0644);
+MODULE_PARM_DESC(atomic_print_limit,
+		 "the number of seconds task is allowed to print messages");
+
+static inline bool printk_offloading_enabled(void)
+{
+	return atomic_print_limit &&
+		printk_enforce_emergency == 0 &&
+		printk_kthread &&
+		atomic_read(&printk_emergency) == 0;
+}
+
+static inline bool is_printk_offloading_safe(void)
+{
+	return system_state == SYSTEM_RUNNING && !oops_in_progress;
+}
+
+static inline bool printk_kthread_should_stop(void)
+{
+	if (current != printk_kthread)
+		return false;
+	/* An emergency mode */
+	return (atomic_read(&printk_emergency) != 0);
+}
+
+/*
+ * This disables printing offloading and instead attempts
+ * to do the usual console_trylock()->console_unlock().
+ *
+ * Note, this does not wait for printk_kthread to stop (if it's
+ * already printing logbuf messages).
+ */
+void printk_emergency_begin(void)
+{
+	atomic_inc(&printk_emergency);
+}
+EXPORT_SYMBOL_GPL(printk_emergency_begin);
+
+/* This re-enables printk_kthread offloading. */
+void printk_emergency_end(void)
+{
+	atomic_dec(&printk_emergency);
+}
+EXPORT_SYMBOL_GPL(printk_emergency_end);
+
+/*
+ * Under heavy printing load or with a slow serial console (or both)
+ * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
+ * lost interrupts, RCU stalls, etc. Therefore we attempt to limit the
+ * amount of time a process can print from console_unlock().
+ *
+ * This function must be called from 'printk_safe' context under
+ * console_sem lock.
+ */
+static inline bool console_offload_printing(void)
+{
+	static struct task_struct *printing_task;
+	static unsigned long printing_start_ts;
+	unsigned long now = local_clock() >> 30LL; /* seconds */
+
+	if (printk_kthread_should_stop())
+		return true;
+
+	if (!printk_offloading_enabled())
+		return false;
+
+	if (!is_printk_offloading_safe())
+		return false;
+
+	/* A new task - reset the counters. */
+	if (printing_task != current) {
+		printing_start_ts = local_clock() >> 30LL;
+		printing_task = current;
+		return false;
+	}
+
+	/* Once we offloaded to printk_ktread - keep printing */
+	if (current == printk_kthread)
+		return false;
+
+	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
+		return false;
+
+	/*
+	 * We try to set `printk_kthread' CPU affinity to any online CPU
+	 * except for this_cpu. Because otherwise `printk_kthread' may be
+	 * scheduled on the same CPU and offloading will not take place.
+	 */
+	cpumask_copy(printk_offload_cpus, cpu_online_mask);
+	cpumask_clear_cpu(smp_processor_id(), printk_offload_cpus);
+
+	/*
+	 * If this_cpu is the one and only online CPU, then try to wake up
+	 * `printk_kthread' on it.
+	 */
+	if (cpumask_empty(printk_offload_cpus))
+		cpumask_set_cpu(smp_processor_id(), printk_offload_cpus);
+
+	set_cpus_allowed_ptr(printk_kthread, printk_offload_cpus);
+	wake_up_process(printk_kthread);
+	return true;
+}
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1763,6 +1886,15 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
+	/*
+	 * Emergency level indicates that the system is unstable and, thus,
+	 * we better stop relying on wake_up(printk_kthread) and try to do
+	 * a direct printing.
+	 */
+	if (level == LOGLEVEL_EMERG)
+		printk_enforce_emergency = true;
+
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -1880,6 +2012,14 @@ static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static bool suppress_message_printing(int level) { return false; }
 
+void printk_emergency_begin(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_begin);
+
+void printk_emergency_end(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_end);
+
+static inline bool console_offload_printing(void) { return false; }
+
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2161,8 +2301,17 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool do_cond_resched, retry;
+	bool did_offload;
 
 	if (console_suspended) {
+		/*
+		 * Here and later, we need to clear the PENDING_OUTPUT bit
+		 * in order to avoid an infinite loop in printk_kthread
+		 * function when console_unlock() cannot flush messages
+		 * because we suspended consoles. Someone else will print
+		 * the messages from resume_console().
+		 */
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		up_console_sem();
 		return;
 	}
@@ -2191,6 +2340,7 @@ void console_unlock(void)
 	 * console.
 	 */
 	if (!can_use_console()) {
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		console_locked = 0;
 		up_console_sem();
 		return;
@@ -2202,6 +2352,9 @@ void console_unlock(void)
 		size_t len;
 
 		printk_safe_enter_irqsave(flags);
+		/* Must be called under printk_safe */
+		did_offload = console_offload_printing();
+
 		raw_spin_lock(&logbuf_lock);
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
@@ -2219,7 +2372,7 @@ void console_unlock(void)
 			len = 0;
 		}
 skip:
-		if (console_seq == log_next_seq)
+		if (did_offload || console_seq == log_next_seq)
 			break;
 
 		msg = log_from_idx(console_idx);
@@ -2267,14 +2420,18 @@ void console_unlock(void)
 	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.
+	 * Someone could have filled up the buffer again, so re-check
+	 * if there's something to flush. In case when trylock fails,
+	 * 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(&logbuf_lock);
+	if (!did_offload) {
+		raw_spin_lock(&logbuf_lock);
+		retry = console_seq != log_next_seq;
+		if (!retry)
+			clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
+		raw_spin_unlock(&logbuf_lock);
+	}
 	printk_safe_exit_irqrestore(flags);
 
 	if (retry && console_trylock())
@@ -2698,8 +2855,11 @@ late_initcall(printk_late_init);
 #if defined CONFIG_PRINTK
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
-	if (test_and_clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
-		/* If trylock fails, someone else is doing the printing */
+	if (test_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
+		/*
+		 * If trylock fails, someone else is doing the printing.
+		 * PRINTK_PENDING_OUTPUT bit is cleared by console_unlock().
+		 */
 		if (console_trylock())
 			console_unlock();
 	}
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711796 — [RFC][PATCHv5 08/13] printk: set watchdog_thresh as maximum value for atomic_print_limit

There is no point in setting `atomic_print_limit' significantly
larger than watchdog's lockup threshold. This highly increases
the chances of lockups. Watchdog's softlockup threshold is
`2 * watchdog_thresh', but we limit `atomic_print_limit' to just
`watchdog_thresh'.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b14e35f94596..12284aa30025 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -545,6 +545,19 @@ int printk_emergency_end_sync(void)
 }
 EXPORT_SYMBOL_GPL(printk_emergency_end_sync);
 
+/*
+ * We offload to make watchdog lockup detector happy, there is little
+ * point (no point at all) in setting `atomic_print_limit' larger than
+ * `watchdog_thresh'.
+ */
+static inline void adj_atomic_print_limit(void)
+{
+#ifdef CONFIG_LOCKUP_DETECTOR
+	if (watchdog_thresh && atomic_print_limit > watchdog_thresh)
+		atomic_print_limit = watchdog_thresh;
+#endif
+}
+
 /*
  * Under heavy printing load or with a slow serial console (or both)
  * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
@@ -580,6 +593,8 @@ static inline bool console_offload_printing(void)
 	if (current == printk_kthread)
 		return false;
 
+	adj_atomic_print_limit();
+
 	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
 		return false;
 
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711797 — [RFC][PATCHv5 03/13] printk: add sync printk_emergency API

We already have `async' printk_emergency_begin(), which returns
immediately and does not guarantee that `printk_kthread' will
stop by the time it returns. Add `sync' version, which waits for
`printk_kthread' to stop.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/console.h |  2 ++
 kernel/printk/printk.c  | 38 ++++++++++++++++++++++++++++++++++++--
 2 files changed, 38 insertions(+), 2 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 07005db4c788..8ce29b2381d2 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -189,6 +189,8 @@ extern void resume_console(void);
 
 extern void printk_emergency_begin(void);
 extern void printk_emergency_end(void);
+extern int printk_emergency_begin_sync(void);
+extern int printk_emergency_end_sync(void);
 
 int mda_console_init(void);
 void prom_con_init(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a86767d4d619..5d4b4beeebf5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -485,8 +485,8 @@ static inline bool printk_kthread_should_stop(void)
 {
 	if (current != printk_kthread)
 		return false;
-	/* An emergency mode */
-	return (atomic_read(&printk_emergency) != 0);
+	/* An emergency mode or a pending printk_emergency_begin_sync() */
+	return (atomic_read(&printk_emergency) != 0 || kthread_should_park());
 }
 
 /*
@@ -509,6 +509,34 @@ void printk_emergency_end(void)
 }
 EXPORT_SYMBOL_GPL(printk_emergency_end);
 
+/*
+ * This disables printing offloading and instead attempts
+ * to do the usual console_trylock()->console_unlock().
+ *
+ * Note, this does wait for printk_kthread to stop.
+ */
+int printk_emergency_begin_sync(void)
+{
+	atomic_inc(&printk_emergency);
+	if (!printk_kthread)
+		return -EINVAL;
+
+	return kthread_park(printk_kthread);
+}
+EXPORT_SYMBOL_GPL(printk_emergency_begin_sync);
+
+/* This re-enables printk_kthread offloading. */
+int printk_emergency_end_sync(void)
+{
+	atomic_dec(&printk_emergency);
+	if (!printk_kthread)
+		return -EINVAL;
+
+	kthread_unpark(printk_kthread);
+	return 0;
+}
+EXPORT_SYMBOL_GPL(printk_emergency_end_sync);
+
 /*
  * Under heavy printing load or with a slow serial console (or both)
  * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
@@ -2018,6 +2046,12 @@ EXPORT_SYMBOL_GPL(printk_emergency_begin);
 void printk_emergency_end(void) {}
 EXPORT_SYMBOL_GPL(printk_emergency_end);
 
+int printk_emergency_begin_sync(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_begin_sync);
+
+int printk_emergency_end_sync(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_end_sync);
+
 static inline bool console_offload_printing(void) { return false; }
 
 #endif /* CONFIG_PRINTK */
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711798 — [RFC][PATCHv5 09/13] printk: add auto-emergency enforcement mechanism

Do not blindly offload printing, but check if offloading has
been successful. If we can't offload from this CPU for some
time, then we declare printk emergency and switch to old
printk behaviour (print all the pending messages with out
any offloading).

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 12284aa30025..71950bd85eac 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -558,6 +558,15 @@ static inline void adj_atomic_print_limit(void)
 #endif
 }
 
+static inline unsigned long emergency_timeout(unsigned long ts)
+{
+#ifdef CONFIG_LOCKUP_DETECTOR
+	if (watchdog_thresh)
+		return ts + 2 * watchdog_thresh;
+#endif
+	return ts + 10 * atomic_print_limit;
+}
+
 /*
  * Under heavy printing load or with a slow serial console (or both)
  * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
@@ -571,6 +580,7 @@ static inline bool console_offload_printing(void)
 {
 	static struct task_struct *printing_task;
 	static unsigned long printing_start_ts;
+	static unsigned long saved_csw;
 	unsigned long now = local_clock() >> 30LL; /* seconds */
 
 	if (printk_kthread_should_stop())
@@ -585,6 +595,7 @@ static inline bool console_offload_printing(void)
 	/* A new task - reset the counters. */
 	if (printing_task != current) {
 		printing_start_ts = local_clock() >> 30LL;
+		saved_csw = current->nvcsw + current->nivcsw;
 		printing_task = current;
 		return false;
 	}
@@ -598,6 +609,17 @@ static inline bool console_offload_printing(void)
 	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
 		return false;
 
+	/*
+	 * A trivial emergency enforcement - give up on printk_kthread if
+	 * we can't wake it up.
+	 */
+	if (time_after_eq(now, emergency_timeout(printing_start_ts)) &&
+			saved_csw == (current->nvcsw + current->nivcsw)) {
+		printk_enforce_emergency = true;
+		pr_crit("Declaring printk emergency mode.\n");
+		return true;
+	}
+
 	/*
 	 * We try to set `printk_kthread' CPU affinity to any online CPU
 	 * except for this_cpu. Because otherwise `printk_kthread' may be
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711800 — [RFC][PATCHv5 13/13] printk: move offloading logic to per-cpu

We have a global offloading state and make the offloading
decision based on printing task pointer and timestamp. If
we keep seeing the same task performing printing for too
long (`atomic_print_limit') we request offloading. Similarly
when we see that printing is now performed by another task,
we reset the timestamp counter.

This, however, will not work in the following case:

===============================================================================

CPU0						CPU1
//taskA						//taskB
preempt_disable()				preempt_disable()

 printk()
  console_trylock()
  console_unlock()
   printing_task = taskA
  up()
						printk()
						 console_trylock()
						 console_unlock()
						  printing_task = taskB
						  ^^^ reset offloading control
						up()
 printk()
  console_trylock()
  console_unlock()
   printing_task = taskA
   ^^^ reset offloading control
  up()
						printk()
						 console_trylock()
						 console_unlock()
						  printing_task = taskB
						  ^^^ reset offloading control
						up()

/*
 * X seconds later
 */

 printk()
  console_trylock()
  console_unlock()
   printing_task = taskA
   ^^^ reset offloading control
  up()
						printk()
						 console_trylock()
						 console_unlock()
						  printing_task = taskB
						  ^^^ reset offloading control
						up()

 lockup!					lockup!

===============================================================================

So this printk ping-pong confuses our offloading control logic.
Move it to per-CPU area and have a separate offloading control
on every CPU.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 36 ++++++++++++++++++++----------------
 1 file changed, 20 insertions(+), 16 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ba82152ce5d9..f9799616e9fc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -558,13 +558,14 @@ static inline void adj_atomic_print_limit(void)
 #endif
 }
 
-static inline unsigned long emergency_timeout(unsigned long ts)
+static inline unsigned long emergency_timeout(unsigned long now,
+						unsigned long ts)
 {
 #ifdef CONFIG_LOCKUP_DETECTOR
 	if (watchdog_thresh)
-		return ts + 2 * watchdog_thresh;
+		return time_after_eq(now, ts + 2 * watchdog_thresh);
 #endif
-	return ts + 10 * atomic_print_limit;
+	return time_after_eq(now, ts + 10 * atomic_print_limit);
 }
 
 /*
@@ -574,13 +575,13 @@ static inline unsigned long emergency_timeout(unsigned long ts)
  * amount of time a process can print from console_unlock().
  *
  * This function must be called from 'printk_safe' context under
- * console_sem lock.
+ * console_sem lock with preemption disabled.
  */
 static inline bool console_offload_printing(void)
 {
-	static struct task_struct *printing_task;
-	static unsigned long printing_start_ts;
-	static unsigned long saved_csw;
+	static DEFINE_PER_CPU(struct task_struct, *printing_task);
+	static DEFINE_PER_CPU(unsigned long, printing_start_ts);
+	static DEFINE_PER_CPU(unsigned long, saved_csw);
 	unsigned long now = local_clock() >> 30LL; /* seconds */
 
 	if (printk_kthread_should_stop())
@@ -600,16 +601,17 @@ static inline bool console_offload_printing(void)
 		goto offload;
 
 	/* A new task - reset the counters. */
-	if (printing_task != current) {
-		printing_start_ts = local_clock() >> 30LL;
-		saved_csw = current->nvcsw + current->nivcsw;
-		printing_task = current;
+	if (this_cpu_read(printing_task) != current) {
+		this_cpu_write(printing_start_ts, local_clock() >> 30LL);
+		this_cpu_write(saved_csw, current->nvcsw + current->nivcsw);
+		this_cpu_write(printing_task, current);
 		return false;
 	}
 
 	adj_atomic_print_limit();
 
-	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
+	if (!time_after_eq(now, this_cpu_read(printing_start_ts) +
+				atomic_print_limit))
 		return false;
 
 	if (current == printk_kthread) {
@@ -626,7 +628,7 @@ static inline bool console_offload_printing(void)
 		 * back to console_unlock(), it will have another full
 		 * `atomic_print_limit' time slice.
 		 */
-		printing_start_ts = local_clock() >> 30LL;
+		this_cpu_write(printing_start_ts, local_clock() >> 30LL);
 		return true;
 	}
 
@@ -634,10 +636,12 @@ static inline bool console_offload_printing(void)
 	 * A trivial emergency enforcement - give up on printk_kthread if
 	 * we can't wake it up.
 	 */
-	if (time_after_eq(now, emergency_timeout(printing_start_ts)) &&
-			saved_csw == (current->nvcsw + current->nivcsw)) {
+	if (this_cpu_read(saved_csw) == (current->nvcsw + current->nivcsw)
+		&& emergency_timeout(now, this_cpu_read(printing_start_ts))) {
+
 		printk_enforce_emergency = true;
-		pr_crit("Declaring printk emergency mode.\n");
+		pr_crit("CPU%d declared a printk emergency mode.\n",
+				smp_processor_id());
 		return true;
 	}
 
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1711801 — [RFC][PATCHv5 06/13] printk: register PM notifier

It's not always possible/safe to wake_up() printk kernel
thread. For example, late suspend/early resume may printk()
while timekeeping is not initialized yet, so calling into the
scheduler may result in recursive warnings.

Another thing to notice is the fact that PM at some point
freezes user space and kernel threads: freeze_processes()
and freeze_kernel_threads(), correspondingly. Thus we need
printk() to operate in emergency mode there and attempt to
immediately flush pending kernel message to the console.

This patch registers PM notifier, so PM can switch printk
to emergency mode from PM_FOO_PREPARE notifiers and return
back to printk threaded mode from PM_POST_FOO notifiers.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Andreas Mohr <andi@lisas.de>
---
 kernel/printk/printk.c | 35 +++++++++++++++++++++++++++++++++++
 1 file changed, 35 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 05165f008bc8..d3f149fad85c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -49,6 +49,7 @@
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
 #include <linux/kthread.h>
+#include <linux/suspend.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -2913,6 +2914,33 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static int printk_pm_notify(struct notifier_block *notify_block,
+			    unsigned long mode, void *unused)
+{
+	switch (mode) {
+	case PM_HIBERNATION_PREPARE:
+	case PM_SUSPEND_PREPARE:
+	case PM_RESTORE_PREPARE:
+		printk_emergency_begin_sync();
+		break;
+
+	case PM_POST_SUSPEND:
+	case PM_POST_HIBERNATION:
+	case PM_POST_RESTORE:
+		printk_emergency_end_sync();
+		break;
+
+	default:
+		return NOTIFY_DONE;
+	}
+
+	return NOTIFY_OK;
+}
+
+static struct notifier_block printk_pm_nb = {
+	.notifier_call = printk_pm_notify,
+};
+
 static int printk_kthread_func(void *data)
 {
 	while (1) {
@@ -2960,9 +2988,16 @@ static int __init init_printk_kthread(void)
 	if (!alloc_cpumask_var(&printk_offload_cpus, GFP_KERNEL))
 		return -ENOMEM;
 
+	if (register_pm_notifier(&printk_pm_nb) != 0) {
+		pr_err("printk: unable to register PM notifier\n");
+		free_cpumask_var(printk_offload_cpus);
+		return -EINVAL;
+	}
+
 	thread = kthread_run(printk_kthread_func, NULL, "printk");
 	if (IS_ERR(thread)) {
 		pr_err("printk: unable to create printing thread\n");
+		unregister_pm_notifier(&printk_pm_nb);
 		free_cpumask_var(printk_offload_cpus);
 		return PTR_ERR(thread);
 	}
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1712115 — Re: [RFC][PATCHv5 06/13] printk: register PM notifier

On Tuesday, August 15, 2017 4:56:18 AM CEST Sergey Senozhatsky wrote:
> It's not always possible/safe to wake_up() printk kernel
> thread. For example, late suspend/early resume may printk()
> while timekeeping is not initialized yet, so calling into the
> scheduler may result in recursive warnings.
> 
> Another thing to notice is the fact that PM at some point
> freezes user space and kernel threads: freeze_processes()
> and freeze_kernel_threads(), correspondingly. Thus we need
> printk() to operate in emergency mode there and attempt to
> immediately flush pending kernel message to the console.
> 
> This patch registers PM notifier, so PM can switch printk
> to emergency mode from PM_FOO_PREPARE notifiers and return

Isn't that too early?  That's before user space is frozen even.

> back to printk threaded mode from PM_POST_FOO notifiers.

And isn't that too late?

> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Suggested-by: Andreas Mohr <andi@lisas.de>
> ---
>  kernel/printk/printk.c | 35 +++++++++++++++++++++++++++++++++++
>  1 file changed, 35 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 05165f008bc8..d3f149fad85c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -49,6 +49,7 @@
>  #include <linux/sched/debug.h>
>  #include <linux/sched/task_stack.h>
>  #include <linux/kthread.h>
> +#include <linux/suspend.h>
>  
>  #include <linux/uaccess.h>
>  #include <asm/sections.h>
> @@ -2913,6 +2914,33 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
>  	.flags = IRQ_WORK_LAZY,
>  };
>  
> +static int printk_pm_notify(struct notifier_block *notify_block,
> +			    unsigned long mode, void *unused)
> +{
> +	switch (mode) {
> +	case PM_HIBERNATION_PREPARE:
> +	case PM_SUSPEND_PREPARE:
> +	case PM_RESTORE_PREPARE:
> +		printk_emergency_begin_sync();

I'm not sure what would be wrong with calling this directly
from dpm_suspend_noirq().

> +		break;
> +
> +	case PM_POST_SUSPEND:
> +	case PM_POST_HIBERNATION:
> +	case PM_POST_RESTORE:
> +		printk_emergency_end_sync();

And this could be called from dpm_resume_noirq().

In which case you wouldn't really need the stuff below.

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

#1712736 — Re: [RFC][PATCHv5 06/13] printk: register PM notifier

On (08/15/17 13:51), Rafael J. Wysocki wrote:
> On Tuesday, August 15, 2017 4:56:18 AM CEST Sergey Senozhatsky wrote:
[..]
> > This patch registers PM notifier, so PM can switch printk
> > to emergency mode from PM_FOO_PREPARE notifiers and return
> 
> Isn't that too early?  That's before user space is frozen even.
> 
> > back to printk threaded mode from PM_POST_FOO notifiers.
> 
> And isn't that too late?

hm, those two are interesting questions. in short - well, it might
be. I don't want to interfere with PM by doing 'accidental' offloading
etc., PM is too complicated already. so I'd prefer to switch to old
printk behavior early (besides, I tend to see lockups reports more
often when the kernel is up and running, rather than during PM events.)
but, once again, may be it is too early and we can move emergency_mode
switch.

[..]
> > +static int printk_pm_notify(struct notifier_block *notify_block,
> > +			    unsigned long mode, void *unused)
> > +{
> > +	switch (mode) {
> > +	case PM_HIBERNATION_PREPARE:
> > +	case PM_SUSPEND_PREPARE:
> > +	case PM_RESTORE_PREPARE:
> > +		printk_emergency_begin_sync();
> 
> I'm not sure what would be wrong with calling this directly
> from dpm_suspend_noirq().
> 
> > +		break;
> > +
> > +	case PM_POST_SUSPEND:
> > +	case PM_POST_HIBERNATION:
> > +	case PM_POST_RESTORE:
> > +		printk_emergency_end_sync();
> 
> And this could be called from dpm_resume_noirq().
> 
> In which case you wouldn't really need the stuff below.

we didn't want to spread printk_emergency_{begin, end}
calls across the kernel.

as of dpm_suspend_noirq/dpm_resume_noirq - I need to look more.
isn't dpm_{suspend, resume}_noirq too late/early? :)

dpm_resume_noirq() happens much earlier than
suspend_finish()->suspend_thaw_processes(), right?
do we want to enable offloading this early?

currently what we have is the following sequence

suspend_finish()
  suspend_thaw_processes()
    pm_notifier_call_chain(PM_POST_SUSPEND)    // enable offloading
      pm_restore_console()

which looks OK to me, frankly.
do you see any problems here?

	-ss

[toc] | [prev] | [next] | [standalone]

#1712927 — Re: [RFC][PATCHv5 06/13] printk: register PM notifier

On Wednesday, August 16, 2017 9:31:17 AM CEST Sergey Senozhatsky wrote:
> On (08/15/17 13:51), Rafael J. Wysocki wrote:
> > On Tuesday, August 15, 2017 4:56:18 AM CEST Sergey Senozhatsky wrote:
> [..]
> > > This patch registers PM notifier, so PM can switch printk
> > > to emergency mode from PM_FOO_PREPARE notifiers and return
> > 
> > Isn't that too early?  That's before user space is frozen even.
> > 
> > > back to printk threaded mode from PM_POST_FOO notifiers.
> > 
> > And isn't that too late?
> 
> hm, those two are interesting questions. in short - well, it might
> be. I don't want to interfere with PM by doing 'accidental' offloading
> etc., PM is too complicated already. so I'd prefer to switch to old
> printk behavior early (besides, I tend to see lockups reports more
> often when the kernel is up and running, rather than during PM events.)
> but, once again, may be it is too early and we can move emergency_mode
> switch.

Well, that depends on what your goal is really.

I thought you wanted to do the offloading as far into the suspend as it
was safe to do (and analogously for resume), but now I see you want to
stop doing it as early as it makes sense. :-)

In that case I would call printk_emergency_begin_sync() from
dpm_prepare() and printk_emergency_end_sync() from dpm_complete().

> 
> [..]
> > > +static int printk_pm_notify(struct notifier_block *notify_block,
> > > +			    unsigned long mode, void *unused)
> > > +{
> > > +	switch (mode) {
> > > +	case PM_HIBERNATION_PREPARE:
> > > +	case PM_SUSPEND_PREPARE:
> > > +	case PM_RESTORE_PREPARE:
> > > +		printk_emergency_begin_sync();
> > 
> > I'm not sure what would be wrong with calling this directly
> > from dpm_suspend_noirq().
> > 
> > > +		break;
> > > +
> > > +	case PM_POST_SUSPEND:
> > > +	case PM_POST_HIBERNATION:
> > > +	case PM_POST_RESTORE:
> > > +		printk_emergency_end_sync();
> > 
> > And this could be called from dpm_resume_noirq().
> > 
> > In which case you wouldn't really need the stuff below.
> 
> we didn't want to spread printk_emergency_{begin, end}
> calls across the kernel.

But this adds one invocation of each of them anyway *plus* some
extra code around those.  Wouldn't it be cleaner to add those
invocations alone?

> 
> as of dpm_suspend_noirq/dpm_resume_noirq - I need to look more.
> isn't dpm_{suspend, resume}_noirq too late/early? :)
> 
> dpm_resume_noirq() happens much earlier than
> suspend_finish()->suspend_thaw_processes(), right?
> do we want to enable offloading this early?
> 
> currently what we have is the following sequence
> 
> suspend_finish()
>   suspend_thaw_processes()
>     pm_notifier_call_chain(PM_POST_SUSPEND)    // enable offloading
>       pm_restore_console()
> 
> which looks OK to me, frankly.
> do you see any problems here?

I just don't see much point in using the notifier thing if you can
achieve basically the same without using it. :-)

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web