On Mon 2016-04-04 13:49:28, Sergey Senozhatsky wrote:

Hello,

On (03/30/16 17:53), Petr Mladek wrote:
[..]

quoted

@@ -67,10 +67,12 @@ extern void irq_exit(void);
 		preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET);	\
 		rcu_nmi_enter();				\
 		trace_hardirq_enter();				\
+		printk_nmi_enter();				\
 	} while (0)
 
 #define nmi_exit()						\
 	do {							\
+		printk_nmi_exit();				\
 		trace_hardirq_exit();				\
 		rcu_nmi_exit();					\
 		BUG_ON(!in_nmi());				\

isn't it a bit too early to printk_nmi_exit()? rcu_nmi_exit() can
WARN_ON_ONCE() in 3 places.

the same goes for printk_nmi_enter(). rcu_nmi_enter() can WARN_ON_ONCE().

seems that in both cases we can endup having WARN_ON_ONCE() from nmi,
but with default printk function.

Great catch! You are right.

quoted

+/*
+ * Flush data from the associated per_CPU buffer. The function
+ * can be called either via IRQ work or independently.
+ */
+static void __printk_nmi_flush(struct irq_work *work)
+{
+	static raw_spinlock_t read_lock =
+		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
+	struct nmi_seq_buf *s = container_of(work, struct nmi_seq_buf, work);
+	unsigned long flags;
+	size_t len, size;
+	int i, last_i;
+
+	/*
+	 * The lock has two functions. First, one reader has to flush all
+	 * available message to make the lockless synchronization with
+	 * writers easier. Second, we do not want to mix messages from
+	 * different CPUs. This is especially important when printing
+	 * a backtrace.
+	 */
+	raw_spin_lock_irqsave(&read_lock, flags);
+

hm... so here we have
	for (; i < size; i++)
		printk()

under the spinlock. the thing is that one of printk() can end up
in console_unlock()->call_console_drivers() loop, iterating there
long enough to spinlock lockup other CPUs that might want to flush
NMI buffers (if any), assuming that there are enough printk() (or
may be a slow serial console) happening concurrently on other CPUs
to keep the current ->read_lock busy. async printk can help here,
but user can request sync version of printk.

I think that printk() is called on many other locations under
a spinlock and they all are waiting for the async printk.

how about using deferred printk for nmi flush?
print_nmi_seq_line()->printk_deferred() ?

But this is great idea. It will help to avoid the ugly macro
deferred_console_in_nmi() as you mentioned in the other mail.

Heh, I remember that I thought about this but I did not want
to override the original log level of the messages. Now, I see
that LOGLEVEL_SCHED is added on top and the original level
is preserved.

Thanks a lot for review. I am going to wait with respin a bit
and give others some time for feedback.


Best Regards,
Petr