[RFC][PATCH 0/3] printk: some pr_cont tweaks and cleanups

[RFC][PATCH 0/3] printk: some pr_cont tweaks and cleanups

[Sergey Senozhatsky]

	Hello,

	RFC

	Forked from "printk feature for syzbot". Let's have a separate
discussion thread.
	A buch of pr_cont tweaks and cleanups, please see commits and
commits' messages for more details.

Sergey Senozhatsky (3):
  printk: keep kernel cont support always enabled
  printk: lock/unlock console only for new logbuf entries
  printk: do not preliminary split up cont buffer

 kernel/printk/printk.c | 35 +++++++++++------------------------
 1 file changed, 11 insertions(+), 24 deletions(-)

-- 
2.19.0

[RFC][PATCH 1/3] printk: keep kernel cont support always enabled

[Sergey Senozhatsky]

Since 5c2992ee7fd8a29 ("printk: remove console flushing special
cases for partial buffered lines") we don't print cont fragments
to the consoles; cont lines are now proper log_buf entries and
there is no "consecutive continuation flag" anymore: we either
have 'c' entries that mark continuation lines without fragments;
or '-' entries that mark normal logbuf entries. There are no '+'
entries anymore.

However, we still have a small leftover - presence of ext_console
drivers disables kernel cont support and we flush each pr_cont()
and store it as a separate log_buf entry. Previously, it worked
because msg_print_ext_header() had that "an optional external merge
of the records" functionality:

	if (msg->flags & LOG_CONT)
		cont = (prev_flags & LOG_CONT) ? '+' : 'c';

We don't do this as of now, so keep kernel cont always enabled.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 22 ++++------------------
 1 file changed, 4 insertions(+), 18 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 308497194bd4..e72cb793aff1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -192,16 +192,7 @@ int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write,
 	return 0;
 }
 
-/*
- * Number of registered extended console drivers.
- *
- * If extended consoles are present, in-kernel cont reassembly is disabled
- * and each fragment is stored as a separate log entry with proper
- * continuation flag so that every emitted message has full metadata.  This
- * doesn't change the result for regular consoles or /proc/kmsg.  For
- * /dev/kmsg, as long as the reader concatenates messages according to
- * consecutive continuation flags, the end result should be the same too.
- */
+/* Number of registered extended console drivers. */
 static int nr_ext_console_drivers;
 
 /*
@@ -1806,12 +1797,8 @@ static void cont_flush(void)
 
 static bool cont_add(int facility, int level, enum log_flags flags, const char *text, size_t len)
 {
-	/*
-	 * If ext consoles are present, flush and skip in-kernel
-	 * continuation.  See nr_ext_console_drivers definition.  Also, if
-	 * the line gets too long, split it up in separate records.
-	 */
-	if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
+	/* If the line gets too long, split it up in separate records. */
+	if (cont.len + len > sizeof(cont.buf)) {
 		cont_flush();
 		return false;
 	}
@@ -2731,8 +2718,7 @@ void register_console(struct console *newcon)
 	}
 
 	if (newcon->flags & CON_EXTENDED)
-		if (!nr_ext_console_drivers++)
-			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
+		nr_ext_console_drivers++;
 
 	if (newcon->flags & CON_PRINTBUFFER) {
 		/*
-- 
2.19.0

Re: [RFC][PATCH 1/3] printk: keep kernel cont support always enabled

[Petr Mladek]

On Tue 2018-10-02 11:38:34, Sergey Senozhatsky wrote:
> Since 5c2992ee7fd8a29 ("printk: remove console flushing special
> cases for partial buffered lines") we don't print cont fragments
> to the consoles; cont lines are now proper log_buf entries and
> there is no "consecutive continuation flag" anymore: we either
> have 'c' entries that mark continuation lines without fragments;
> or '-' entries that mark normal logbuf entries. There are no '+'
> entries anymore.
> 
> However, we still have a small leftover - presence of ext_console
> drivers disables kernel cont support and we flush each pr_cont()
> and store it as a separate log_buf entry. Previously, it worked
> because msg_print_ext_header() had that "an optional external merge
> of the records" functionality:
> 
> 	if (msg->flags & LOG_CONT)
> 		cont = (prev_flags & LOG_CONT) ? '+' : 'c';
> 
> We don't do this as of now, so keep kernel cont always enabled.
>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 22 ++++------------------
>  1 file changed, 4 insertions(+), 18 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 308497194bd4..e72cb793aff1 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -192,16 +192,7 @@ int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write,
>  	return 0;
>  }
>  
> -/*
> - * Number of registered extended console drivers.
> - *
> - * If extended consoles are present, in-kernel cont reassembly is disabled
> - * and each fragment is stored as a separate log entry with proper
> - * continuation flag so that every emitted message has full metadata.  This
> - * doesn't change the result for regular consoles or /proc/kmsg.  For
> - * /dev/kmsg, as long as the reader concatenates messages according to
> - * consecutive continuation flags, the end result should be the same too.
> - */
> +/* Number of registered extended console drivers. */
>  static int nr_ext_console_drivers;
>  
>  /*
> @@ -1806,12 +1797,8 @@ static void cont_flush(void)
>  
>  static bool cont_add(int facility, int level, enum log_flags flags, const char *text, size_t len)
>  {
> -	/*
> -	 * If ext consoles are present, flush and skip in-kernel
> -	 * continuation.  See nr_ext_console_drivers definition.  Also, if
> -	 * the line gets too long, split it up in separate records.
> -	 */
> -	if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
> +	/* If the line gets too long, split it up in separate records. */
> +	if (cont.len + len > sizeof(cont.buf)) {
>  		cont_flush();
>  		return false;
>  	}

Just to be sure. The original purpose was to get full information
including the metadata and dictionary via extended console drivers,
see commit 6fe29354befe4c46e ("printk: implement support for extended
console drivers").

IMHO, only the dictionary was really important but it was actually
lost:

  static void cont_flush(void)
  {
  [...]
	log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
		  NULL, 0, cont.buf, cont.len);

Nobody noticed because the only dictionary user is dev_printk()
and dev_cont() is _not_ defined.

As a result, I think that this change will rather improve things.
Well, I wonder if we should write something of the above into
the commit message. Either way:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [RFC][PATCH 1/3] printk: keep kernel cont support always enabled

[Sergey Senozhatsky]

On (10/09/18 10:14), Petr Mladek wrote:
> Just to be sure. The original purpose was to get full information
> including the metadata and dictionary via extended console drivers,
> see commit 6fe29354befe4c46e ("printk: implement support for extended
> console drivers").

Right.

> IMHO, only the dictionary was really important but it was actually
> lost:
> 
>   static void cont_flush(void)
>   {
>   [...]
> 	log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
> 		  NULL, 0, cont.buf, cont.len);
> 
> Nobody noticed because the only dictionary user is dev_printk()
> and dev_cont() is _not_ defined.

Right.

> As a result, I think that this change will rather improve things.
> Well, I wonder if we should write something of the above into
> the commit message. Either way:

The commit message probably can be improved, agreed.

> Reviewed-by: Petr Mladek <pmladek@suse.com>

Thanks.

	-ss

[RFC][PATCH 2/3] printk: lock/unlock console only for new logbuf entries

[Sergey Senozhatsky]

From: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>

Prior to 5c2992ee7fd8a29 ("printk: remove console flushing special
cases for partial buffered lines") we would do console_cont_flush()
for each pr_cont() to print cont fragments, so console_unlock() would
actually 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 do 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

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

Thus we can console_lock()/console_unlock()/wake_up_klogd() only when
we know that we log_store()-ed a message and there is something to
print to the consoles/syslog.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e72cb793aff1..aea37b7927dd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1916,8 +1916,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 			    const char *fmt, va_list args)
 {
 	int printed_len;
-	bool in_sched = false;
+	bool in_sched = false, pending_output;
 	unsigned long flags;
+	u64 curr_log_seq;
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
@@ -1929,11 +1930,13 @@ 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);
+	pending_output = (curr_log_seq != log_next_seq);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
-	if (!in_sched) {
+	if (!in_sched && pending_output) {
 		/*
 		 * Disable preemption to avoid being preempted while holding
 		 * console_sem which would prevent anyone from printing to
@@ -1950,7 +1953,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 		preempt_enable();
 	}
 
-	wake_up_klogd();
+	if (pending_output)
+		wake_up_klogd();
 	return printed_len;
 }
 EXPORT_SYMBOL(vprintk_emit);
-- 
2.19.0

Re: [RFC][PATCH 2/3] printk: lock/unlock console only for new logbuf entries

[Petr Mladek]

On Tue 2018-10-02 11:38:35, Sergey Senozhatsky wrote:
> From: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
> 
> Prior to 5c2992ee7fd8a29 ("printk: remove console flushing special
> cases for partial buffered lines") we would do console_cont_flush()
> for each pr_cont() to print cont fragments, so console_unlock() would
> actually 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 do 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
> 
> We also wakeup klogd purposelessly for pr_cont() output - un-flushed
> cont buffer is not stored in log_buf; there is nothing to pull.
> 
> Thus we can console_lock()/console_unlock()/wake_up_klogd() only when
> we know that we log_store()-ed a message and there is something to
> print to the consoles/syslog.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 10 +++++++---
>  1 file changed, 7 insertions(+), 3 deletions(-)

The patch makes perfect sense. It looks a bit hacky but I can't
think about any less hacky one.

I wonder if it is worth it. But if nobody else is against it
I am going to push it.

I just hope that we will get rid of it with the buffered printk
rather sooner than later.

Best Regards,
Petr

Re: [RFC][PATCH 2/3] printk: lock/unlock console only for new logbuf entries

[Sergey Senozhatsky]

On (10/09/18 10:39), Petr Mladek wrote:
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> > ---
> >  kernel/printk/printk.c | 10 +++++++---
> >  1 file changed, 7 insertions(+), 3 deletions(-)
> 
> The patch makes perfect sense. It looks a bit hacky but I can't
> think about any less hacky one.
>
> I wonder if it is worth it. But if nobody else is against it
> I am going to push it.

Well, getting to buffered printk may take some time; so I'd probably
apply it, shouldn't hurt :)

	-ss

[RFC][PATCH 3/3] printk: do not preliminary split up cont buffer

[Sergey Senozhatsky]

We have a proper 'overflow' check which tells us that we need to
split up existing cont buffer in separate records:

	if (cont.len + len > sizeof(cont.buf))
		cont_flush();

At the same time we also have one extra flush: "if cont buffer is
80% full then split it up" in cont_add():

	if (cont.len > (sizeof(cont.buf) * 80) / 100)
		cont_flush();

This looks to be redundant, since the existing "overflow" check
should work just fine, so remove this 80% check and wait for either
a normal cont termination \n, for preliminary flush due to
possible buffer overflow or for preliminary flush due to cont race.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 3 ---
 1 file changed, 3 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index aea37b7927dd..1856db8128c6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1822,9 +1822,6 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char *
 		cont_flush();
 	}
 
-	if (cont.len > (sizeof(cont.buf) * 80) / 100)
-		cont_flush();
-
 	return true;
 }
 
-- 
2.19.0

Re: [RFC][PATCH 3/3] printk: do not preliminary split up cont buffer

[Petr Mladek]

On Tue 2018-10-02 11:38:36, Sergey Senozhatsky wrote:
> We have a proper 'overflow' check which tells us that we need to
> split up existing cont buffer in separate records:
> 
> 	if (cont.len + len > sizeof(cont.buf))
> 		cont_flush();
> 
> At the same time we also have one extra flush: "if cont buffer is
> 80% full then split it up" in cont_add():
> 
> 	if (cont.len > (sizeof(cont.buf) * 80) / 100)
> 		cont_flush();
> 
> This looks to be redundant, since the existing "overflow" check
> should work just fine, so remove this 80% check and wait for either
> a normal cont termination \n, for preliminary flush due to
> possible buffer overflow or for preliminary flush due to cont race.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

I wonder if this check ever triggered ;-) It is a nice clean up:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [RFC][PATCH 3/3] printk: do not preliminary split up cont buffer

[Sergey Senozhatsky]

On (10/09/18 10:42), Petr Mladek wrote:
> On Tue 2018-10-02 11:38:36, Sergey Senozhatsky wrote:
> > We have a proper 'overflow' check which tells us that we need to
> > split up existing cont buffer in separate records:
> > 
> > 	if (cont.len + len > sizeof(cont.buf))
> > 		cont_flush();
> > 
> > At the same time we also have one extra flush: "if cont buffer is
> > 80% full then split it up" in cont_add():
> > 
> > 	if (cont.len > (sizeof(cont.buf) * 80) / 100)
> > 		cont_flush();
> > 
> > This looks to be redundant, since the existing "overflow" check
> > should work just fine, so remove this 80% check and wait for either
> > a normal cont termination \n, for preliminary flush due to
> > possible buffer overflow or for preliminary flush due to cont race.
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> I wonder if this check ever triggered ;-) It is a nice clean up:
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

Thanks.

	-ss

Re: [RFC][PATCH 0/3] printk: some pr_cont tweaks and cleanups

[Petr Mladek]

On Tue 2018-10-02 11:38:33, Sergey Senozhatsky wrote:
> 	Hello,
> 
> 	RFC
> 
> 	Forked from "printk feature for syzbot". Let's have a separate
> discussion thread.
> 	A buch of pr_cont tweaks and cleanups, please see commits and
> commits' messages for more details.
> 
> Sergey Senozhatsky (3):
>   printk: keep kernel cont support always enabled
>   printk: lock/unlock console only for new logbuf entries
>   printk: do not preliminary split up cont buffer

JFYI, I have pushed all three patches into printk.git, for-4.20
branch.

Best Regards,
Petr

Re: [RFC][PATCH 0/3] printk: some pr_cont tweaks and cleanups

[Sergey Senozhatsky]

On (10/12/18 10:27), Petr Mladek wrote:
> > 	Forked from "printk feature for syzbot". Let's have a separate
> > discussion thread.
> > 	A buch of pr_cont tweaks and cleanups, please see commits and
> > commits' messages for more details.
> > 
> > Sergey Senozhatsky (3):
> >   printk: keep kernel cont support always enabled
> >   printk: lock/unlock console only for new logbuf entries
> >   printk: do not preliminary split up cont buffer
> 
> JFYI, I have pushed all three patches into printk.git, for-4.20
> branch.

Thanks.

	-ss