Re: [PATCH v10 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

On (08/18/16 12:56), Petr Mladek wrote:
> On Thu 2016-08-18 18:51:44, Sergey Senozhatsky wrote:
> > On (08/18/16 11:33), Petr Mladek wrote:
> > [..]
> > > > > 2. Force synchronous printk inside WARN()/BUG() macros.
> > > > 
> > > > will it help? semaphore up() calls wake_up_process() regardless the context.
> > > > not to mention that we still may have spin_dump() enabled.
> > > 
> > > Good point. That changes my preferences :-)
> > > 
> > > > 
> > > > > 3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
> > > > >    printk_func.
> > > > > 
> > > > >    It might be elegant. But we do not want this outside the scheduler
> > > > >    code. Therefore we would need special variants of  WARN_*_SCHED()
> > > > >    BUG_*_SCHED() macros.
> > > 
> > > Also we need to make sure that everything will be done on a single CPU
> > > as the printk_func is per-CPU variable.
> > 
> > lib/dump_stack.c dump_stack() disables local IRQs, so we will stay
> > on the same CPU.
> 
> It is less important to stay of the same CPU if you use
> printk_deferred() directly. But it us must to have if you
> use it via the printk_func per-CPU variable.
> 
> The advantage of the printk_func trick is that it is transparent.
> You do not need to modify any existing functions used by WARN()/BUG()
> macros.

good point.

so something like below, perhaps. I'm less sure about
deferred BUG()/BUG_ON():

#define DEFERRED_BUG() do { 		\
	printk_deferred_enter();	\
	BUG();				\
	printk_deferred_exit();		\
} while (0)				\

#define DEFERRED_BUG_ON(condition) do { \
	printk_deferred_enter();	\
	BUG_ON(condition);		\
	printk_deferred_exit();		\
} while (0)

depending on .config BUG() may never return back -- passing control
to do_exit(), so printk_deferred_exit() won't be executed. thus we
probably need to have a per-cpu variable that would indicate that
we are in deferred_bug. hm... but do we really need deferred BUG()
in the first place?


Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>

---

 include/asm-generic/bug.h | 50 +++++++++++++++++++++++++++++++++++++++++++++++
 include/linux/printk.h    |  6 ++++++
 kernel/printk/internal.h  | 18 +----------------
 kernel/printk/printk.c    | 42 ++++++++++++++++++++++++++++++++++-----
 4 files changed, 94 insertions(+), 22 deletions(-)

diff --git a/include/asm-generic/bug.h b/include/asm-generic/bug.h
index 6f96247..d72ee1e 100644
--- a/include/asm-generic/bug.h
+++ b/include/asm-generic/bug.h
@@ -60,6 +60,10 @@ struct bug_entry {
  * significant issues that need prompt attention if they should ever
  * appear at runtime.  Use the versions with printk format strings
  * to provide better diagnostics.
+ *
+ * DEFERRED_WARN macros call printk_deferred() to print the messages
+ * and are meant to be used from the contexts where direct printk()
+ * can deadlock the system.
  */
 #ifndef __WARN_TAINT
 extern __printf(3, 4)
@@ -145,6 +149,52 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
 	unlikely(__ret_warn_once);				\
 })
 
+#define DEFERRED_WARN_ON(condition) ({				\
+	int __ret_warn_on = !!(condition);			\
+	if (unlikely(__ret_warn_on)) {				\
+		printk_deferred_enter();			\
+		__WARN();					\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_on);				\
+})
+
+#define DEFERRED_WARN(condition, format...) ({			\
+	int __ret_warn_on = !!(condition);			\
+	if (unlikely(__ret_warn_on)) {				\
+		printk_deferred_enter();			\
+		__WARN_printf(format);				\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_on);				\
+})
+
+#define DEFERRED_WARN_ON_ONCE(condition)	({		\
+	static bool __section(.data.unlikely) __warned;		\
+	int __ret_warn_once = !!(condition);			\
+								\
+	if (unlikely(__ret_warn_once && !__warned)) {		\
+		__warned = true;				\
+		printk_deferred_enter();			\
+		WARN_ON(1);					\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_once);				\
+})
+
+#define DEFERRED_WARN_ONCE(condition, format...)	({	\
+	static bool __section(.data.unlikely) __warned;		\
+	int __ret_warn_once = !!(condition);			\
+								\
+	if (unlikely(__ret_warn_once && !__warned)) {		\
+		__warned = true;				\
+		printk_deferred_enter();			\
+		WARN(1, format);				\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_once);				\
+})
+
 #else /* !CONFIG_BUG */
 #ifndef HAVE_ARCH_BUG
 #define BUG() do {} while (1)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 696a56b..5142654 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -193,6 +193,9 @@ void __init setup_log_buf(int early);
 __printf(1, 2) void dump_stack_set_arch_desc(const char *fmt, ...);
 void dump_stack_print_info(const char *log_lvl);
 void show_regs_print_info(const char *log_lvl);
+
+extern void printk_deferred_enter(void);
+extern void printk_deferred_exit(void);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -252,6 +255,9 @@ static inline void dump_stack_print_info(const char *log_lvl)
 static inline void show_regs_print_info(const char *log_lvl)
 {
 }
+
+static void printk_deferred_enter(void) {}
+static void printk_deferred_exit(void) {}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7fd2838..70f1cf2 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -19,23 +19,12 @@
 typedef __printf(1, 0) int (*printk_func_t)(const char *fmt, va_list args);
 
 int __printf(1, 0) vprintk_default(const char *fmt, va_list args);
+DECLARE_PER_CPU(printk_func_t, printk_func);
 
 #ifdef CONFIG_PRINTK_NMI
 
 extern raw_spinlock_t logbuf_lock;
 
-/*
- * printk() could not take logbuf_lock in NMI context. Instead,
- * it temporary stores the strings into a per-CPU buffer.
- * The alternative implementation is chosen transparently
- * via per-CPU variable.
- */
-DECLARE_PER_CPU(printk_func_t, printk_func);
-static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
-{
-	return this_cpu_read(printk_func)(fmt, args);
-}
-
 extern atomic_t nmi_message_lost;
 static inline int get_nmi_message_lost(void)
 {
@@ -44,11 +33,6 @@ static inline int get_nmi_message_lost(void)
 
 #else /* CONFIG_PRINTK_NMI */
 
-static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
-{
-	return vprintk_default(fmt, args);
-}
-
 static inline int get_nmi_message_lost(void)
 {
 	return 0;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0d3e026..6e260a0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2026,7 +2026,17 @@ asmlinkage __visible int printk(const char *fmt, ...)
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk_func(fmt, args);
+	/*
+	 * printk() could not take logbuf_lock in NMI context. Instead,
+	 * it temporary stores the strings into a per-CPU buffer. The
+	 * alternative implementation is chosen transparently via per-CPU
+	 * variable.
+	 *
+	 * We also switch printk_func from default to vprintk_deferred()
+	 * when in DEFERRED_WARN()/DEFERRED_BUG(), because it may be
+	 * unsafe to execute vprintk_default().
+	 */
+	r = this_cpu_read(printk_func)(fmt, args);
 	va_end(args);
 
 	return r;
@@ -3037,6 +3047,17 @@ void wake_up_klogd(void)
 	preempt_enable();
 }
 
+static int vprintk_deferred(const char *fmt, va_list args)
+{
+	int r;
+
+	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+
+	return r;
+}
+
 int printk_deferred(const char *fmt, ...)
 {
 	va_list args;
@@ -3044,16 +3065,27 @@ int printk_deferred(const char *fmt, ...)
 
 	preempt_disable();
 	va_start(args, fmt);
-	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+	r = vprintk_deferred(fmt, args);
 	va_end(args);
-
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
-	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	preempt_enable();
 
 	return r;
 }
 
+void printk_deferred_enter(void)
+{
+	preempt_disable();
+	this_cpu_write(printk_func, vprintk_deferred);
+}
+EXPORT_SYMBOL(printk_deferred_enter);
+
+void printk_deferred_exit(void)
+{
+	this_cpu_write(printk_func, vprintk_default);
+	preempt_enable();
+}
+EXPORT_SYMBOL(printk_deferred_exit);
+
 /*
  * printk rate limiting, lifted from the networking subsystem.
  *
-- 
2.9.3