Subject: printk: add pr_flush()
From: John Ogness <john.ogness@linutronix.de>
Date: Mon Nov 30 01:42:10 2020 +0106

From: John Ogness <john.ogness@linutronix.de>

Provide a function to allow waiting for console printers to catch
up to the latest logged message.

Use pr_flush() to give console printers a chance to finish in
critical situations if no atomic console is available. For now
pr_flush() is only used in the most common error paths:
panic(), print_oops_end_marker(), report_bug(), kmsg_dump().

Signed-off-by: John Ogness <john.ogness@linutronix.de>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

---
 include/linux/printk.h |    7 ++++
 kernel/panic.c         |   28 ++++++++++------
 kernel/printk/printk.c |   81 +++++++++++++++++++++++++++++++++++++++++++++++++
 lib/bug.c              |    1 
 4 files changed, 106 insertions(+), 11 deletions(-)
---
@ include/linux/printk.h:164 @ int vprintk(const char *fmt, va_list arg
 asmlinkage __printf(1, 2) __cold
 int _printk(const char *fmt, ...);
 
+bool pr_flush(int timeout_ms, bool reset_on_progress);
+
 /*
  * Please don't use printk_ratelimit(), because it shares ratelimiting state
  * with all other unrelated printk_ratelimit() callsites.  Instead use
@ include/linux/printk.h:206 @ int _printk(const char *s, ...)
 	return 0;
 }
 
+static inline bool pr_flush(int timeout_ms, bool reset_on_progress)
+{
+	return true;
+}
+
 static inline int printk_ratelimit(void)
 {
 	return 0;
--- a/kernel/panic.c
+++ b/kernel/panic.c
@ include/linux/printk.h:181 @ static void panic_print_sys_info(void)
 void panic(const char *fmt, ...)
 {
 	static char buf[1024];
+	va_list args2;
 	va_list args;
 	long i, i_next = 0, len;
 	int state = 0;
 	int old_cpu, this_cpu;
 	bool _crash_kexec_post_notifiers = crash_kexec_post_notifiers;
 
+	console_verbose();
+	pr_emerg("Kernel panic - not syncing:\n");
+	va_start(args2, fmt);
+	va_copy(args, args2);
+	vprintk(fmt, args2);
+	va_end(args2);
+#ifdef CONFIG_DEBUG_BUGVERBOSE
+	/*
+	 * Avoid nested stack-dumping if a panic occurs during oops processing
+	 */
+	if (!test_taint(TAINT_DIE) && oops_in_progress <= 1)
+		dump_stack();
+#endif
+	pr_flush(1000, true);
+
 	/*
 	 * Disable local interrupts. This will prevent panic_smp_self_stop
 	 * from deadlocking the first cpu that invokes the panic, since
@ include/linux/printk.h:233 @ void panic(const char *fmt, ...)
 	if (old_cpu != PANIC_CPU_INVALID && old_cpu != this_cpu)
 		panic_smp_self_stop();
 
-	console_verbose();
 	bust_spinlocks(1);
-	va_start(args, fmt);
 	len = vscnprintf(buf, sizeof(buf), fmt, args);
 	va_end(args);
 
 	if (len && buf[len - 1] == '\n')
 		buf[len - 1] = '\0';
 
-	pr_emerg("Kernel panic - not syncing: %s\n", buf);
-#ifdef CONFIG_DEBUG_BUGVERBOSE
-	/*
-	 * Avoid nested stack-dumping if a panic occurs during oops processing
-	 */
-	if (!test_taint(TAINT_DIE) && oops_in_progress <= 1)
-		dump_stack();
-#endif
-
 	/*
 	 * If kgdb is enabled, give it a chance to run before we stop all
 	 * the other CPUs or else we won't be able to debug processes left
@ include/linux/printk.h:561 @ static void print_oops_end_marker(void)
 {
 	init_oops_id();
 	pr_warn("---[ end trace %016llx ]---\n", (unsigned long long)oops_id);
+	pr_flush(1000, true);
 }
 
 /*
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@ include/linux/printk.h:3288 @ void kmsg_dump(enum kmsg_dump_reason rea
 			sync_mode = true;
 			pr_info("enabled sync mode\n");
 		}
+
+		/*
+		 * Give the printing threads time to flush, allowing up to
+		 * 1s of no printing forward progress before giving up.
+		 */
+		pr_flush(1000, true);
 	}
 
 	rcu_read_lock();
@ include/linux/printk.h:3615 @ bool kgdb_roundup_delay(unsigned int cpu
 }
 EXPORT_SYMBOL(kgdb_roundup_delay);
 #endif /* CONFIG_SMP */
--- a/lib/bug.c
+
+#ifdef CONFIG_PRINTK
+static void pr_msleep(bool may_sleep, int ms)
+{
+	if (may_sleep) {
+		msleep(ms);
+	} else {
+		while (ms--)
+			udelay(1000);
+	}
+}
+
+/**
+ * pr_flush() - Wait for printing threads to catch up.
+ *
+ * @timeout_ms:        The maximum time (in ms) to wait.
+ * @reset_on_progress: Reset the timeout if forward progress is seen.
+ *
+ * A value of 0 for @timeout_ms means no waiting will occur. A value of -1
+ * represents infinite waiting.
+ *
+ * If @reset_on_progress is true, the timeout will be reset whenever any
+ * printer has been seen to make some forward progress.
+ *
+ * Context: Any context.
+ * Return: true if all enabled printers are caught up.
+ */
+bool pr_flush(int timeout_ms, bool reset_on_progress)
+{
+	int remaining = timeout_ms;
+	struct console *con;
+	u64 last_diff = 0;
+	bool may_sleep;
+	u64 printk_seq;
+	u64 diff;
+	u64 seq;
+
+	may_sleep = (preemptible() && !in_softirq());
+
+	seq = prb_next_seq(prb);
+
+	for (;;) {
+		diff = 0;
+
+		for_each_console(con) {
+			if (!(con->flags & CON_ENABLED))
+				continue;
+			printk_seq = read_console_seq(con);
+			if (printk_seq < seq)
+				diff += seq - printk_seq;
+		}
+
+		if (diff != last_diff && reset_on_progress)
+			remaining = timeout_ms;
+
+		if (diff == 0 || remaining == 0)
+			break;
+
+		if (remaining < 0) {
+			pr_msleep(may_sleep, 100);
+		} else if (remaining < 100) {
+			pr_msleep(may_sleep, remaining);
+			remaining = 0;
+		} else {
+			pr_msleep(may_sleep, 100);
+			remaining -= 100;
+		}
+
+		last_diff = diff;
+	}
+
+	return (diff == 0);
+}
+EXPORT_SYMBOL(pr_flush);
+#endif /* CONFIG_PRINTK */
+++ b/lib/bug.c
@ include/linux/printk.h:209 @ enum bug_trap_type report_bug(unsigned l
 	else
 		pr_crit("Kernel BUG at %pB [verbose debug info unavailable]\n",
 			(void *)bugaddr);
+	pr_flush(1000, true);
 
 	return BUG_TRAP_TYPE_BUG;
 }