Re: [PATCH] printk: inject caller information into the body of message

[Sergey Senozhatsky]

On (09/29/18 20:13), Sergey Senozhatsky wrote:
> We used to flush "incomplete" cont lines (fragments) from console_unlock().
> 
> void console_unlock(void)
> {
> ...
>         /* flush buffered message fragment immediately to console */
>         console_cont_flush(text, sizeof(text));
> again:
>         for (;;) {
> 	...
> 	}
> ...
> }
> 
> Unless I'm missing something, we don't anymore.
> Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
> Now we print only log_buf entries. So we either wait for a \n to flush
> a complete cont buffer, or for a race to preliminary flush cont buffer.

BTW, it just crossed my mind:

Previously, we would do console_cont_flush() for each pr_cont(),
so console_unlock() would print data:

	pr_cont();
	 console_lock();
	 console_unlock()
	  console_cont_flush(); // print cont fragment
	...
	pr_cont();
	 console_lock();
	 console_unlock()
	  console_cont_flush(); // print cont fragment

We don't console_cont_flush() anymore, so when we do pr_cont()
console_unlock() does nothing (unless we flushed the cont buffer):

	pr_cont();
	 console_lock();
	 console_unlock();      // noop
	...
	pr_cont();
	 console_lock();
	 console_unlock();      // noop
	...
	pr_cont();
	  cont_flush();
	    console_lock();
	    console_unlock();   // print data

console_lock()/console_unlock() makes sense only when we flush cont
buffer.

We also wakeup klogd purposelessly for pr_cont() output - un-flushed
is not stored in log_buf; there is nothing to pull.

So we can console_lock()/console_unlock()/wake_up_klogd() only when we
know that we log_stor()-ed a message.

A quick-n-dirty patch (I can send a formal one) which compares log_next_seq
before and after vprintk_store(). log_next_seq is getting incremented each
time we log_store() a new log_buf message:

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 308497194bd4..53d9134f02a6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1931,6 +1931,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	int printed_len;
 	bool in_sched = false;
 	unsigned long flags;
+	u64 curr_log_seq;
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
@@ -1942,11 +1943,12 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	/* This stops the holder of console_sem just where we want him */
 	logbuf_lock_irqsave(flags);
+	curr_log_seq = log_next_seq;
 	printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
-	if (!in_sched) {
+	if (!in_sched && (curr_log_seq != log_next_seq)) {
 		/*
 		 * Disable preemption to avoid being preempted while holding
 		 * console_sem which would prevent anyone from printing to
@@ -1963,7 +1965,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 		preempt_enable();
 	}
 
-	wake_up_klogd();
+	if (curr_log_seq != log_next_seq)
+		wake_up_klogd();
 	return printed_len;
 }
 EXPORT_SYMBOL(vprintk_emit);

---

	-ss