Re: [PATCH v2 7/7] sched/core: Add debug code to catch missing update_rq_clock()

[Peter Zijlstra <peterz@infradead.org>]

On Thu, Sep 22, 2016 at 10:36:37AM +0200, Jan Kara wrote:
> On Thu 22-09-16 10:04:36, Peter Zijlstra wrote:
> > On Wed, Sep 21, 2016 at 05:58:27PM +0200, Petr Mladek wrote:
> > > > +static inline void assert_clock_updated(struct rq *rq)
> > > > +{
> > > > +#ifdef CONFIG_SCHED_DEBUG
> > > > +	/*
> > > > +	 * The only reason for not seeing a clock update since the
> > > > +	 * last rq_pin_lock() is if we're currently skipping updates.
> > > > +	 */
> > > > +	WARN_ON_ONCE(rq->clock_update_flags < RQCF_ACT_SKIP);
> > > > +#endif
> > > > +}
> > > 
> > > I am afraid that it might eventually create a deadlock.
> > > For example, there is the following call chain:
> > > 
> > 
> > Yeah, meh. There's already plenty WARNs in the sched code. The idea of
> > course being that they should not trigger. If they do, something
> > buggered already, so who bloody cares about a deadlock later ;-)
> 
> Yeah, the trouble is that you usually won't see the WARN message
> before deadlocking. So WARN_ON in scheduler is usually equivalent to
> 
> 	if (condition)
> 		while (1);
> 
> ;) Not really helping debugging much...

Only if you use the normal piece of crap printk() cruft ;-)

I have the below patch that cures all its woes.. Of course, the driver
model is still broken, but it was that before this as well.
vprintk_emit() really should not be exposed and used directly.

bit banging the serial port is absolutely awesome, the rest of printk
not so much.

---
 kernel/printk/printk.c | 63 +++++++++++++++++++++++++++++++++-----------------
 1 file changed, 42 insertions(+), 21 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index eea6dbc2d8cf..24951ed47835 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -344,6 +344,42 @@ __packed __aligned(4)
 #endif
 ;
 
+#ifdef CONFIG_EARLY_PRINTK
+struct console *early_console;
+
+static bool __read_mostly force_early_printk;
+
+static int __init force_early_printk_setup(char *str)
+{
+	force_early_printk = true;
+	return 0;
+}
+early_param("force_early_printk", force_early_printk_setup);
+
+static int early_vprintk(const char *fmt, va_list args)
+{
+	char buf[512];
+	int n;
+
+	n = vscnprintf(buf, sizeof(buf), fmt, args);
+	early_console->write(early_console, buf, n);
+
+	return n;
+}
+
+asmlinkage __visible void early_printk(const char *fmt, ...)
+{
+	va_list ap;
+
+	if (!early_console)
+		return;
+
+	va_start(ap, fmt);
+	early_vprintk(fmt, ap);
+	va_end(ap);
+}
+#endif
+
 /*
  * The logbuf_lock protects kmsg buffer, indices, counters.  This can be taken
  * within the scheduler's rq lock. It must be released before calling
@@ -1973,7 +2009,12 @@ asmlinkage __visible int printk(const char *fmt, ...)
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk_func(fmt, args);
+#ifdef CONFIG_EARLY_PRINTK
+	if (force_early_printk && early_console)
+		r = early_vprintk(fmt, args);
+	else
+#endif
+		r = vprintk_func(fmt, args);
 	va_end(args);
 
 	return r;
@@ -2023,26 +2064,6 @@ DEFINE_PER_CPU(printk_func_t, printk_func);
 
 #endif /* CONFIG_PRINTK */
 
-#ifdef CONFIG_EARLY_PRINTK
-struct console *early_console;
-
-asmlinkage __visible void early_printk(const char *fmt, ...)
-{
-	va_list ap;
-	char buf[512];
-	int n;
-
-	if (!early_console)
-		return;
-
-	va_start(ap, fmt);
-	n = vscnprintf(buf, sizeof(buf), fmt, ap);
-	va_end(ap);
-
-	early_console->write(early_console, buf, n);
-}
-#endif
-
 static int __add_preferred_console(char *name, int idx, char *options,
 				   char *brl_options)
 {