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

Groups > linux.kernel > #1620617 > unrolled thread

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-10 20:50 +0200
    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-11 03:50 +0200
      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-11 18:30 +0200
        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-12 20:50 +0200
          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-13 06:40 +0200
        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-13 08:00 +0200
          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-13 10:30 +0200
        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-13 16:10 +0200
          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-14 06:50 +0200

#1620617 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Multipart message — attachments visible in raw view] — view raw

On Mon 2017-04-10 13:53:39, Sergey Senozhatsky wrote:
> On (04/09/17 12:12), Pavel Machek wrote:
> [..]
> > > a side note,
> > > that's rather unclear to me how would "message delayed" really help.
> > > if your system hard-lockup so badly and there are no printk messages
> > > even from NMI watchdog, then we won't be able to print that message.
> > 
> > We are talking about
> > 
> >    printk("unusual condition");
> >    do_something_clever(); /* Which unfortunately hard-crashes the machine */
> > 
> > that works with my proposal, but not with yours. Seen it happen many
> > times before.
> 
> I see your point, sure.
> I can't completely agree on "that works with my proposal, but not with yours."
> 
> on SMP system this would be true only if no other CPU holds the console_sem
> at the time we call printk(). (skipping irrelevant cases when we have suspended
> console or !online CPU and !CON_ANYTIME console). and there is nothing that
> makes "no other CPU holds the console_sem" always true on SMP system at any
> given point in time. so no, "A always works, B never works" is not
> accurate.

Ok, you are right. OTOH the common case is console_sem is unlocked (at
least on systems I develop on). 

> but, once again, I see your point.

Good. Does that mean that the next version of patches will work ok in
that case?
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [next] | [standalone]

#1620825

On (04/10/17 20:48), Pavel Machek wrote:
[..]
> > but, once again, I see your point.
> 
> Good. Does that mean that the next version of patches will work ok in
> that case?

yes.

we also likely will get rid of printk_begin/end in PM code.
but we still need to have printk_emergency hints from the
outside world in the rest of the places (sysrq etc.)    :(

	-ss

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

#1621454

On (04/11/17 10:46), Sergey Senozhatsky wrote:
> On (04/10/17 20:48), Pavel Machek wrote:
> [..]
> > > but, once again, I see your point.
> > 
> > Good. Does that mean that the next version of patches will work ok in
> > that case?
> 
> yes.

ok... so I'm looking at something like below right now.
not really tested yet.

I put some comments into the code.

it does offloading after X printed lines by the same process.
if we reschedule, then the counter resets. which is probably OK,
we don't really want any process, except for printk_kthread, to
stay in console_unlock() forever. "number of lines printed" is
probably easier to understand (easily converted to the number of
pageup/pagedown you need to press, terminal buffer history size,
etc.) than seconds we spent on printing (which doesn't even
correspond to messages' timestamps in general case).

when the limit of "number of lines printed" is 0, then no
offloading takes place.

it also has some simple mechanism to handle cases when
we try to wake_up() printk_kthread, but it never becomes alive.
it's a bit simple minded, probably.

wake_up is done from printk_safe context, so warnings/printks
from there should do no harm (in fact, we even do pr_crit()
error reporting, when we enforce printk_emergency mode).

I'll do more tests tomorrow, and will take a closer look.
this code is basically just compiles, boots and passes some
trivial tests. quite possible I've missed something important.

once verified, then the next question will be -- do we even
need printk_emergency_begin/end or we can leave without it.

// given that printk_emergency enforcement works properly


but, once again, the code might be stupid and wrong.
and I need some sleep.

---
 include/linux/console.h |   3 +
 kernel/printk/printk.c  | 200 ++++++++++++++++++++++++++++++++++++++++++++++--
 2 files changed, 198 insertions(+), 5 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 5949d1855589..f1a86944072e 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 6cf756dbee39..c0075e8b3a09 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>
@@ -402,7 +403,8 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 	} while (0)
 
 /*
- * 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
@@ -445,6 +447,48 @@ 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 __read_mostly;
+/*
+ * 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;
+
+static unsigned int atomic_print_limit = 10000;
+
+module_param_named(atomic_print_limit, atomic_print_limit, uint, 0644);
+MODULE_PARM_DESC(atomic_print_limit,
+		 "max lines to print before offloading to printk kthread");
+
+static inline bool printk_kthread_enabled(void)
+{
+	return !printk_enforce_emergency &&
+		printk_kthread && atomic_read(&printk_emergency) == 0;
+}
+
+/*
+ * This disables printing offloading and instead attempts
+ * to do the usual console_trylock()->console_unlock().
+ *
+ * Note, this does not stop the printk_kthread if it's already
+ * printing logbuf messages.
+ */
+void printk_emergency_begin(void)
+{
+	atomic_inc(&printk_emergency);
+}
+
+/* This re-enables printk_kthread offloading. */
+void printk_emergency_end(void)
+{
+	atomic_dec(&printk_emergency);
+}
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1765,6 +1809,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(). */
@@ -1882,6 +1935,9 @@ 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) {}
+void printk_emergency_end(void) {}
+
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2141,6 +2197,89 @@ static inline int can_use_console(void)
 	return cpu_online(raw_smp_processor_id()) || have_callable_console();
 }
 
+/*
+ * Under heavy printing load/slow serial console/etc console_unlock() can
+ * stall CPUs, which can result in soft/hard-lockups, lost interrupts, RCU
+ * stalls, etc. Therefore we attempt to print the messages to console from
+ * a dedicated printk_kthread, which always runs in schedulable context.
+ *
+ * There are several possible scenarios:
+ *
+ * a) When we got a large number of pending messages to print.
+ * e.g.
+ *    vprintk_emit() or console_lock()
+ *     console_unlock()
+ *      <<massive dump>>
+ *
+ * b) When we printk() a large number of messages.
+ * e.g.
+ *   vprintk_emit()->console_unlock()   <<print 1 message>>
+ *   vprintk_emit()->console_unlock()   <<print 1 message>>
+ *   ...
+ *   vprintk_emit()->console_unlock()   <<print 1 message>>
+ *
+ * In all those cases we can be in atomic context, we need to offload
+ * printing at some point.
+ *
+ * This function must be called from 'printk_safe' context.
+ */
+static inline bool console_offload_printing(void)
+{
+	static struct task_struct *printing_task = NULL;
+	static unsigned long lines_printed = 0;
+
+	if (!atomic_print_limit || !printk_kthread_enabled())
+		return false;
+
+	/* We rescheduled - reset the counters. */
+	if (printing_task != current) {
+		lines_printed = 0;
+		printing_task = current;
+		return false;
+	}
+
+	if (current == printk_kthread)
+		return false;
+
+	/*
+	 * Don't reset the counter, let CPU overrun the limit.
+	 * The idea is that
+	 *
+	 *   a) woken up printk_kthread (if succeeded)
+	 * or
+	 *   b) concurrent printk from another CPU (if any)
+	 *
+	 * will change `printing_task' and reset the counter. This also
+	 * let us to introduce additional policies later, for instance,
+	 * if we can't wakeup printk_kthread for Y times, e.g.
+	 *
+	 *            lines_printed > 2 * atomic_print_limit
+	 *
+	 * then we can declare emergency and stop relying on printk_kthread.
+	 *
+	 * If neither a) nor b) happens - we continue printing from
+	 * current process. Which is bad and can be risky, but we can't
+	 * wake_up() printk_kthread, so things already don't look normal.
+	 */
+	lines_printed++;
+	if (lines_printed < atomic_print_limit)
+		return false;
+
+	/*
+	 * A trivial emergency enforcement.
+	 * Assumes that `atomic_print_limit' is large enough.
+	 */
+	if (lines_printed > 2 * (unsigned long)atomic_print_limit) {
+		printk_enforce_emergency = true;
+		pr_crit("Declaring printk emergency mode.\n");
+		return false;
+	}
+
+	/* Must be executed in 'printk_safe' context. */
+	wake_up_process(printk_kthread);
+	return true;
+}
+
 /**
  * console_unlock - unlock the console system
  *
@@ -2163,8 +2302,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;
 	}
@@ -2186,6 +2334,7 @@ void console_unlock(void)
 	do_cond_resched = console_may_schedule;
 again:
 	console_may_schedule = 0;
+	did_offload = 0;
 
 	/*
 	 * We released the console_sem lock, so we need to recheck if
@@ -2193,6 +2342,7 @@ void console_unlock(void)
 	 * console.
 	 */
 	if (!can_use_console()) {
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		console_locked = 0;
 		up_console_sem();
 		return;
@@ -2221,7 +2371,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);
@@ -2253,9 +2403,28 @@ void console_unlock(void)
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(ext_text, ext_len, text, len);
 		start_critical_timings();
+
+		/*
+		 * Sometimes we may lock console_sem before printk_kthread.
+		 * In this case we will jump to `again' label (if there are
+		 * pending messages), print one more line from current
+		 * process, break out of printing loop (we don't reset the
+		 * counter of printed lines) and do up_console_sem() to
+		 * wakeup printk_kthread again.
+		 *
+		 * If printk_kthread never wakes up (which may indicate that
+		 * the system is unstable or something weird is going on),
+		 * then we will keep jumping to `again' label and printing
+		 * one message from the logbuf. This is a bit ugly, but at
+		 * least we will print out the logbuf.
+		 *
+		 * If such condition occurs, console_offload_printing() can
+		 * declare `printk_emergency' at some point.
+		 */
+		did_offload = console_offload_printing();
 		printk_safe_exit_irqrestore(flags);
 
-		if (do_cond_resched)
+		if (!did_offload && do_cond_resched)
 			cond_resched();
 	}
 	console_locked = 0;
@@ -2276,6 +2445,8 @@ void console_unlock(void)
 	 */
 	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);
 
@@ -2669,8 +2840,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();
 	}
@@ -2684,6 +2858,22 @@ 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);
+		if (!test_bit(PRINTK_PENDING_OUTPUT, &printk_pending))
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+
+		console_lock();
+		console_unlock();
+	}
+
+	return 0;
+}
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
-- 
2.12.2

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

#1622479

[Multipart message — attachments visible in raw view] — view raw

On Wed 2017-04-12 01:19:53, Sergey Senozhatsky wrote:
> On (04/11/17 10:46), Sergey Senozhatsky wrote:
> > On (04/10/17 20:48), Pavel Machek wrote:
> > [..]
> > > > but, once again, I see your point.
> > > 
> > > Good. Does that mean that the next version of patches will work ok in
> > > that case?
> > 
> > yes.
> 
> ok... so I'm looking at something like below right now.
> not really tested yet.
> 
> I put some comments into the code.
> 
> it does offloading after X printed lines by the same process.
> if we reschedule, then the counter resets. which is probably OK,
> we don't really want any process, except for printk_kthread, to
> stay in console_unlock() forever. "number of lines printed" is
> probably easier to understand (easily converted to the number of
> pageup/pagedown you need to press, terminal buffer history size,
> etc.) than seconds we spent on printing (which doesn't even
> correspond to messages' timestamps in general case).

Design looks good to me... certainly better than previous version :-).
								

> when the limit of "number of lines printed" is 0, then no
> offloading takes place.

And with "number of lines printed" set to 999999, it will get us
previous behaviour, right? 

Thanks,
								Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

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

#1622711

On (04/12/17 20:43), Pavel Machek wrote:
[..]
> > when the limit of "number of lines printed" is 0, then no
> > offloading takes place.
> 
> And with "number of lines printed" set to 999999, it will get us
> previous behaviour, right? 

`atomic_print_limit' set to zero disables offloading explicitly.
at the same time, an unreasonably high `atomic_print_limit' value
makes offloading less possible and starting from some value,
basically, disables it implicitly.

	-ss

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

#1622730

On (04/12/17 01:19), Sergey Senozhatsky wrote:
[..]
> it does offloading after X printed lines by the same process.
> if we reschedule, then the counter resets. which is probably OK,
> we don't really want any process, except for printk_kthread, to
> stay in console_unlock() forever.

may be this can be changed. we don't want even printk_kthread to keep
console_sem locked for too long, because other process that might want
to lock console_sem have to sleep in TASK_UNINTERRUPTIBLE as long as
printing thread has pending messages to print. so may be the rule can
be "every process prints up to `atomic_print_limit' lines and then
offloads printing - wake_up()s printk_kthread and up()s console_sem".
some other process (printk_kthread or a process from console_sem wait
list, let them compete for console_sem) will eventually down()
console_sem and print the next `atomic_print_limit' lines, while
current process will have a chance to return from console_unlock() and
do something else.

[..]
> the next question will be -- do we even need printk_emergency_begin/end
> or we can leave without it.

what I meant here -- drop sysrq and kexec printk_emergency_begin/end
patches, but keep printk_emergency_begin/end API and do
printk_emergency_begin/end in console_suspend()/resume().
PM already calls console_suspend()/resume(). something like that...

	-ss

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

#1622810

On (04/13/17 14:50), Sergey Senozhatsky wrote:
[..]
> On (04/12/17 01:19), Sergey Senozhatsky wrote:
> [..]
> > it does offloading after X printed lines by the same process.
> > if we reschedule, then the counter resets. which is probably OK,
> > we don't really want any process, except for printk_kthread, to
> > stay in console_unlock() forever.
> 
> may be this can be changed. we don't want even printk_kthread to keep
> console_sem locked for too long, because other process that might want
> to lock console_sem have to sleep in TASK_UNINTERRUPTIBLE as long as
> printing thread has pending messages to print. so may be the rule can
> be "every process prints up to `atomic_print_limit' lines and then
> offloads printing - wake_up()s printk_kthread and up()s console_sem".
> some other process (printk_kthread or a process from console_sem wait
> list, let them compete for console_sem) will eventually down()
> console_sem and print the next `atomic_print_limit' lines, while
> current process will have a chance to return from console_unlock() and
> do something else.

something like this, perhaps.

static inline bool console_offload_printing(void)
{
	static struct task_struct *printing_task;
	static unsigned long lines_printed;
	static bool did_wakeup;

	if (!atomic_print_limit || !printk_kthread_enabled())
		return false;

	/* We rescheduled - reset the counters. */
	if (printing_task != current) {
		did_wakeup = false;
		lines_printed = 0;
		printing_task = current;
		return false;
	}

	/*
	 * Don't reset the counter, let CPU overrun the limit.
	 * The idea is that
	 *
	 *   a) woken up printk_kthread (if succeeded)
	 * or
	 *   b) concurrent printk from another CPU (if any)
	 *
	 * will change `printing_task' and reset the counter.
	 * If neither a) nor b) happens - we continue printing from
	 * current process. Which is bad and can be risky, but we can't
	 * wake_up() printk_kthread, so things already don't look normal.
	 */
	lines_printed++;
	if (lines_printed < atomic_print_limit)
		return false;

	if (current == printk_kthread) {
		/*
		 * Reset the counter, just in case if printk_kthread is the
		 * only process left that would down() console_sem.
		 */
		lines_printed = 0;
		return true;
	}

	/*
	 * A trivial emergency enforcement - give up on printk_kthread if
	 * we can't wake it up. This assumes that `atomic_print_limit' is
	 * large enough.
	 */
	if (lines_printed > 2 * (unsigned long long)atomic_print_limit) {
		printk_enforce_emergency = true;
		pr_crit("Declaring printk emergency mode.\n");
		return false;
	}

	/*
	 * Must be executed in 'printk_safe' context. Call into the
	 * scheduler just once, in case if it backfires on us with
	 * warnings and backtraces.
	 */
	if (!did_wakeup) {
		did_wakeup = true;
		wake_up_process(printk_kthread);
	}
	return true;
}

	-ss

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

#1623058

On Wed 2017-04-12 01:19:53, Sergey Senozhatsky wrote:
> On (04/11/17 10:46), Sergey Senozhatsky wrote:
> > On (04/10/17 20:48), Pavel Machek wrote:
> > [..]
> > > > but, once again, I see your point.
> > > 
> > > Good. Does that mean that the next version of patches will work ok in
> > > that case?
> > 
> > yes.
> 
> ok... so I'm looking at something like below right now.
> not really tested yet.
> 
> I put some comments into the code.
> 
> it does offloading after X printed lines by the same process.
> if we reschedule, then the counter resets. which is probably OK,
> we don't really want any process, except for printk_kthread, to
> stay in console_unlock() forever. "number of lines printed" is
> probably easier to understand (easily converted to the number of
> pageup/pagedown you need to press, terminal buffer history size,
> etc.) than seconds we spent on printing (which doesn't even
> correspond to messages' timestamps in general case).
> 
> when the limit of "number of lines printed" is 0, then no
> offloading takes place.
> 
> it also has some simple mechanism to handle cases when
> we try to wake_up() printk_kthread, but it never becomes alive.
> it's a bit simple minded, probably.
> 
> wake_up is done from printk_safe context, so warnings/printks
> from there should do no harm (in fact, we even do pr_crit()
> error reporting, when we enforce printk_emergency mode).
> 
> I'll do more tests tomorrow, and will take a closer look.
> this code is basically just compiles, boots and passes some
> trivial tests. quite possible I've missed something important.
> 
> once verified, then the next question will be -- do we even
> need printk_emergency_begin/end or we can leave without it.
> 
> // given that printk_emergency enforcement works properly
> 
> 
> but, once again, the code might be stupid and wrong.
> and I need some sleep.
> 
> ---
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 6cf756dbee39..c0075e8b3a09 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2141,6 +2197,89 @@ static inline int can_use_console(void)
>  	return cpu_online(raw_smp_processor_id()) || have_callable_console();
>  }
>  
> +/*
> + * Under heavy printing load/slow serial console/etc console_unlock() can
> + * stall CPUs, which can result in soft/hard-lockups, lost interrupts, RCU
> + * stalls, etc. Therefore we attempt to print the messages to console from
> + * a dedicated printk_kthread, which always runs in schedulable context.
> + *
> + * There are several possible scenarios:
> + *
> + * a) When we got a large number of pending messages to print.
> + * e.g.
> + *    vprintk_emit() or console_lock()
> + *     console_unlock()
> + *      <<massive dump>>
> + *
> + * b) When we printk() a large number of messages.
> + * e.g.
> + *   vprintk_emit()->console_unlock()   <<print 1 message>>
> + *   vprintk_emit()->console_unlock()   <<print 1 message>>
> + *   ...
> + *   vprintk_emit()->console_unlock()   <<print 1 message>>
> + *
> + * In all those cases we can be in atomic context, we need to offload
> + * printing at some point.
> + *
> + * This function must be called from 'printk_safe' context.
> + */
> +static inline bool console_offload_printing(void)
> +{
> +	static struct task_struct *printing_task = NULL;
> +	static unsigned long lines_printed = 0;
> +
> +	if (!atomic_print_limit || !printk_kthread_enabled())
> +		return false;
> +
> +	/* We rescheduled - reset the counters. */
> +	if (printing_task != current) {
> +		lines_printed = 0;
> +		printing_task = current;
> +		return false;
> +	}

If we want to check that the process rescheduled, we should
store/check also current->nvcsw + current->nivcsw.

This might be even more important in the detection of
the emergency situation, see below.


> +	if (current == printk_kthread)
> +		return false;

Yup, printk_kthread is special. You suggest another solution
in the other reply.

IMHO, the best solution would be if printk_kthread calls
console_unlock() with disabled preemption and does the offload
(releases console_sem) when need_resched() returns true.

By other words, printk_kthread should use its allotted time
as much as possible. But it should not block the console_sem
when sleeping.

My only fear is that it is getting more and more complicated.
On the other hand, any partial solution is asking for
troubles and complains.

> +
> +	/*
> +	 * Don't reset the counter, let CPU overrun the limit.
> +	 * The idea is that
> +	 *
> +	 *   a) woken up printk_kthread (if succeeded)
> +	 * or
> +	 *   b) concurrent printk from another CPU (if any)
> +	 *
> +	 * will change `printing_task' and reset the counter. This also
> +	 * let us to introduce additional policies later, for instance,
> +	 * if we can't wakeup printk_kthread for Y times, e.g.
> +	 *
> +	 *            lines_printed > 2 * atomic_print_limit
> +	 *
> +	 * then we can declare emergency and stop relying on printk_kthread.
> +	 *
> +	 * If neither a) nor b) happens - we continue printing from
> +	 * current process. Which is bad and can be risky, but we can't
> +	 * wake_up() printk_kthread, so things already don't look normal.
> +	 */
> +	lines_printed++;
> +	if (lines_printed < atomic_print_limit)
> +		return false;
> +
> +	/*
> +	 * A trivial emergency enforcement.
> +	 * Assumes that `atomic_print_limit' is large enough.
> +	 */
> +	if (lines_printed > 2 * (unsigned long)atomic_print_limit) {
> +		printk_enforce_emergency = true;
> +		pr_crit("Declaring printk emergency mode.\n");
> +		return false;
> +	}

The only messages that are printed on my workstation are the same
few lines everytime I connect my phone over USB to get it charged.
I am not sure if they are printed by the same process. But I would
get scared if printk switches to the emergency mode just because
there is only one process "regularly" producing messages.

It might help to check the number of process switch counts as
suggested above.


> +	/* Must be executed in 'printk_safe' context. */
> +	wake_up_process(printk_kthread);
> +	return true;
> +}
> +
>  /**
>   * console_unlock - unlock the console system
>   *
> @@ -2163,8 +2302,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;
>  	}
> @@ -2186,6 +2334,7 @@ void console_unlock(void)
>  	do_cond_resched = console_may_schedule;
>  again:
>  	console_may_schedule = 0;
> +	did_offload = 0;

It would make more sense to clear the variable before the again:
target. In fact, there is a logic mistake, see below.
>  
>  	/*
>  	 * We released the console_sem lock, so we need to recheck if
> @@ -2193,6 +2342,7 @@ void console_unlock(void)
>  	 * console.
>  	 */
>  	if (!can_use_console()) {
> +		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
>  		console_locked = 0;
>  		up_console_sem();
>  		return;
> @@ -2221,7 +2371,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);
> @@ -2253,9 +2403,28 @@ void console_unlock(void)
>  		stop_critical_timings();	/* don't trace print latency */
>  		call_console_drivers(ext_text, ext_len, text, len);
>  		start_critical_timings();
> +
> +		/*
> +		 * Sometimes we may lock console_sem before printk_kthread.
> +		 * In this case we will jump to `again' label (if there are
> +		 * pending messages), print one more line from current
> +		 * process, break out of printing loop (we don't reset the
> +		 * counter of printed lines) and do up_console_sem() to
> +		 * wakeup printk_kthread again.
> +		 *
> +		 * If printk_kthread never wakes up (which may indicate that
> +		 * the system is unstable or something weird is going on),
> +		 * then we will keep jumping to `again' label and printing
> +		 * one message from the logbuf. This is a bit ugly, but at
> +		 * least we will print out the logbuf.
> +		 *
> +		 * If such condition occurs, console_offload_printing() can
> +		 * declare `printk_emergency' at some point.

I am a bit confused by the comment above. The again goto target is
used only when there is a race between leaving the loop and releasing
the console_sem. It is a corner case.

If there are messages from other CPUs, they most likely appear during
the slow call_console_drivers(). They are handled inside the
for(;;) cycle unless we reach the atomic_print_limit and
wake up the printk_kthread.

IMHO, we should just mention here that the jobs might get offloaded
to prevent softlookups when console_unlock() is called in atomic
context.

> +		 */
> +		did_offload = console_offload_printing();
>  		printk_safe_exit_irqrestore(flags);
>  
> -		if (do_cond_resched)
> +		if (!did_offload && do_cond_resched)
>  			cond_resched();
>  	}
>  	console_locked = 0;
> @@ -2276,6 +2445,8 @@ void console_unlock(void)
>  	 */
>  	raw_spin_lock(&logbuf_lock);
>  	retry = console_seq != log_next_seq;

This should be:

	retry = console_seq != log_next_seq && !did_offload;

Otherwise, it would never leave.

I know that this was only proposal and you did it late until
late night.

Anyway, I like the proposal. I have a good feeling about
this way. Also I really like how the main logic is localized
in console_offload_printing().

Best Regards,
Petr

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

#1623504

Hello Petr,

thanks for taking a look!

On (04/13/17 16:03), Petr Mladek wrote:
> > +static inline bool console_offload_printing(void)
> > +{
> > +	static struct task_struct *printing_task = NULL;
> > +	static unsigned long lines_printed = 0;
> > +
> > +	if (!atomic_print_limit || !printk_kthread_enabled())
> > +		return false;
> > +
> > +	/* We rescheduled - reset the counters. */
> > +	if (printing_task != current) {
> > +		lines_printed = 0;
> > +		printing_task = current;
> > +		return false;
> > +	}
> 
> If we want to check that the process rescheduled, we should
> store/check also current->nvcsw + current->nivcsw.

ok.

[..]
> My only fear is that it is getting more and more complicated.
> On the other hand, any partial solution is asking for
> troubles and complains.

yeah. we have to aim slightly different and conflicting targets - introducing
a new printk behavior, while preserving an already existing guarantees. which
is a bit tricky.


[..]
> > +	if (lines_printed > 2 * (unsigned long)atomic_print_limit) {
> > +		printk_enforce_emergency = true;
> > +		pr_crit("Declaring printk emergency mode.\n");
> > +		return false;
> > +	}
> 
> The only messages that are printed on my workstation are the same
> few lines everytime I connect my phone over USB to get it charged.

you are right. this is a known and yet to be resolved issue.


> It might help to check the number of process switch counts as
> suggested above.

will take a look at your 'current->nvcsw + current->nivcsw' idea.
thanks.


[..]
> > +		/*
> > +		 * Sometimes we may lock console_sem before printk_kthread.
> > +		 * In this case we will jump to `again' label (if there are
> > +		 * pending messages), print one more line from current
> > +		 * process, break out of printing loop (we don't reset the
> > +		 * counter of printed lines) and do up_console_sem() to
> > +		 * wakeup printk_kthread again.
> > +		 *
> > +		 * If printk_kthread never wakes up (which may indicate that
> > +		 * the system is unstable or something weird is going on),
> > +		 * then we will keep jumping to `again' label and printing
> > +		 * one message from the logbuf. This is a bit ugly, but at
> > +		 * least we will print out the logbuf.
> > +		 *
> > +		 * If such condition occurs, console_offload_printing() can
> > +		 * declare `printk_emergency' at some point.
> 
> I am a bit confused by the comment above. The again goto target is
> used only when there is a race between leaving the loop and releasing
> the console_sem. It is a corner case.

not really.

this is the part where "preserve printk guarantees" jumps in.

when we limit the number of lines we can print we have to leave this loop
with not fully flushed logbuf. so `goto again' is not solely for corner
case anymore. when we prematurely leave the printing loop, we wake_up
printk_kthread, unlock console_sem... and then we have no idea if
printk_kthread going to wake_up at all, and, if it's going to, how much
time will it take. at the same time we have a task that is already in
console_unlock() and, probably, we still have pending messages in the logbuf.
that's why the process that just has left the printing loop [and there easily
might be pending messages in the logbuf] does the whole 'retry' thing. we can
have a misbehaving high priority process or something, that would prevent
printk_kthread from becoming running just when we need it. so, at least
sometimes, the printing process (the one that breaks ouf of printing loop
and wakes up printk_kthread) can re-acquire console_sem and print one more
line, then it up() console_sem, which, hopefully, will wake_up printk_kthread.
if printk_kthread did become running then if would be in console_sem wait
list at this point. if it didn't - then we

	a) wake up some other process that is probably in console_sem list
	   (hopefully there is one)

or

	b) continue printing from the current process. because printk_kthread
	   is still not running and there are no other processes that want to
	   console_lock(). not much we can do at this point.


so in expected/normal scenario, we fail to re-acquire the console_sem lock
(console_trylock()), which means that either printk_kthread or some other
process from console_sem wait list acquired the console_sem and will take
over printing.


I do something like this

---
@@ -2427,6 +2427,8 @@ void console_unlock(void)
                console_seq++;
                raw_spin_unlock(&logbuf_lock);
 
+               sprintf(text + 7, "{%s}", current->comm);
+
                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(ext_text, ext_len, text, len);
                start_critical_timings();
---


and fire up some silly printk tests (I don't care what exactly it prints,
I'm curious what process prints it). it sort of makes it easier to observe
the behaviour.



> If there are messages from other CPUs, they most likely appear during
> the slow call_console_drivers(). They are handled inside the
> for(;;) cycle unless we reach the atomic_print_limit and
> wake up the printk_kthread.

but `atomic_print_limit' can be quite restrictive. we break out of the
printing loop then `atomic_print_limit' tells us to do so, not when we
the logbuf is empty.


[..]
> > @@ -2276,6 +2445,8 @@ void console_unlock(void)
> >  	 */
> >  	raw_spin_lock(&logbuf_lock);
> >  	retry = console_seq != log_next_seq;
> 
> This should be:
> 
> 	retry = console_seq != log_next_seq && !did_offload;
> 
> Otherwise, it would never leave.

it is expected to leave at some point, when we would know for sure that
a successful offloading took place. otherwise we probably shouldn't leave.
we invoked wake_up_process(), but that does not really buy us anything
(from printk guarantees POV). we trust one thing only - a process holding
the console_sem lock. because that's "a fact"; wake_up_process() is nothing
but "a promise".


so, in short, the basic idea is:
- the worse the situation is, the closer printk behavior to the original one.


the bigger the scheduling latencies are, the more time we spent
in console_unlock(), printing more than `atomic_print_limit' chars.


in more details:

once we cross the `atomic_print_limit' we start this thing


@again label:

1) call_console_drivers()	- print a single logbuf entry

1) up()				- "somebody please take over" (we expect that at
				  least one process will do this - printk_kthread.
				  but we don't know when, and not entirely sure
				  if it will. so we are increasing our chances
				  by waking up printk_kthread, but we don't
				  completely count on it).

2) console_trylock()		- if successful
					then "eeehhh, OK... I'll print one more line"
					goto @again
				  else
					return, someone console_lock()-ed

yes, in absolutely bad scenario -- even printk_kthread can't lock
console_sem - this means old printk behaviour. but that's sort of exactly
what we want to do with the printk_emergency_begin/end annotations anyway.
in exchange we print out the logbuf eventually.


I'm trying to find a compromise that would make everyone happy. may be
I'm missing an easier/better solution, wouldn't be the first time ever :)

	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web