[PATCH] printk/console: Do not suppress information about dropped messages

[PATCH] printk/console: Do not suppress information about dropped messages

[Petr Mladek]

The warning about dropped messages gets lost when the current
message is above console_loglevel and suppressed.

The suppressed messages allow even slow consoles to caught up
with a flood of messages. The consoles must not get slowed
down by many warnings. Instead, the warning is delayed until
the next printable message.

The handling of newly registered consoles is handled with a compromise:

  + It does not make sense to reply the log when it is already behind.
    This prevents a bogus number at the beginning of the replayed log.

  + The counter is restarted when switching to all consoles. This
    prevents a bogus number on already registered consoles.

  + The last number in the replayed log might be lower than reality.
    But it does not look worth existing.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 54 ++++++++++++++++++++++++++++++++------------------
 1 file changed, 35 insertions(+), 19 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b4d26388bc62..c3f287422ef4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -420,6 +420,7 @@ static u32 log_next_idx;
 /* the next printk record to write to the console */
 static u64 console_seq;
 static u32 console_idx;
+static u64 console_dropped_cnt;
 static u64 exclusive_console_stop_seq;
 
 /* the next printk record to read after the last 'clear' command */
@@ -2060,6 +2061,7 @@ static u64 syslog_seq;
 static u32 syslog_idx;
 static u64 console_seq;
 static u32 console_idx;
+static u64 console_dropped_cnt;
 static u64 exclusive_console_stop_seq;
 static u64 log_first_seq;
 static u32 log_first_idx;
@@ -2398,20 +2400,24 @@ void console_unlock(void)
 	for (;;) {
 		struct printk_log *msg;
 		size_t ext_len = 0;
-		size_t len;
+		size_t len = 0;
 
 		printk_safe_enter_irqsave(flags);
 		raw_spin_lock(&logbuf_lock);
+
+		/* Reset dropped msg count when switching to all consoles. */
+		if (unlikely(exclusive_console &&
+			     exclusive_console_stop_seq < log_first_seq)) {
+			console_dropped_cnt = 0;
+			console_seq = exclusive_console_stop_seq;
+		}
+
 		if (console_seq < log_first_seq) {
-			len = sprintf(text,
-				      "** %llu printk messages dropped **\n",
-				      log_first_seq - console_seq);
+			console_dropped_cnt += log_first_seq - console_seq;
 
 			/* messages are gone, move to first one */
 			console_seq = log_first_seq;
 			console_idx = log_first_idx;
-		} else {
-			len = 0;
 		}
 skip:
 		if (console_seq == log_next_seq)
@@ -2435,6 +2441,13 @@ void console_unlock(void)
 			exclusive_console = NULL;
 		}
 
+		if (unlikely(console_dropped_cnt)) {
+			len = sprintf(text,
+				      "** %llu printk messages dropped **\n",
+				      console_dropped_cnt);
+			console_dropped_cnt = 0;
+		}
+
 		len += msg_print_text(msg,
 				console_msg_format & MSG_FORMAT_SYSLOG,
 				printk_time, text + len, sizeof(text) - len);
@@ -2750,19 +2763,22 @@ void register_console(struct console *newcon)
 		 * for us.
 		 */
 		logbuf_lock_irqsave(flags);
-		console_seq = syslog_seq;
-		console_idx = syslog_idx;
-		/*
-		 * We're about to replay the log buffer.  Only do this to the
-		 * just-registered console to avoid excessive message spam to
-		 * the already-registered consoles.
-		 *
-		 * Set exclusive_console with disabled interrupts to reduce
-		 * race window with eventual console_flush_on_panic() that
-		 * ignores console_lock.
-		 */
-		exclusive_console = newcon;
-		exclusive_console_stop_seq = console_seq;
+		/* Nothing to replay when consoles are already behind. */
+		if (!console_dropped_cnt) {
+			console_seq = syslog_seq;
+			console_idx = syslog_idx;
+			/*
+			 * We're about to replay the log buffer.  Only do this
+			 * to the just-registered console to avoid excessive
+			 * message spam to the already-registered consoles.
+			 *
+			 * Set exclusive_console with disabled interrupts to
+			 * reduce race window with eventual
+			 * console_flush_on_panic() that ignores console_lock.
+			 */
+			exclusive_console = newcon;
+			exclusive_console_stop_seq = console_seq;
+		}
 		logbuf_unlock_irqrestore(flags);
 	}
 	console_unlock();
-- 
2.13.7

Re: [PATCH] printk/console: Do not suppress information about dropped messages

[John Ogness]

On 2019-02-26, Petr Mladek <pmladek@suse.com> wrote:
> The warning about dropped messages gets lost when the current
> message is above console_loglevel and suppressed.

Here you are reporting a bug. (More on this below.)

> The suppressed messages allow even slow consoles to caught up
> with a flood of messages. The consoles must not get slowed
> down by many warnings. Instead, the warning is delayed until
> the next printable message.

Here you are introducing a new behavior. (Also discussed below.)
Although the two are similar, they are really 2 different things.

> The handling of newly registered consoles is handled with a compromise:
>
>   + It does not make sense to reply the log when it is already behind.
>     This prevents a bogus number at the beginning of the replayed log.
>
>   + The counter is restarted when switching to all consoles. This
>     prevents a bogus number on already registered consoles.
>
>   + The last number in the replayed log might be lower than reality.
>     But it does not look worth existing.
>
> Signed-off-by: Petr Mladek <pmladek@suse.com>
> ---
>  kernel/printk/printk.c | 54 ++++++++++++++++++++++++++++++++------------------
>  1 file changed, 35 insertions(+), 19 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index b4d26388bc62..c3f287422ef4 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -420,6 +420,7 @@ static u32 log_next_idx;
>  /* the next printk record to write to the console */
>  static u64 console_seq;
>  static u32 console_idx;
> +static u64 console_dropped_cnt;
>  static u64 exclusive_console_stop_seq;
>  
>  /* the next printk record to read after the last 'clear' command */
> @@ -2060,6 +2061,7 @@ static u64 syslog_seq;
>  static u32 syslog_idx;
>  static u64 console_seq;
>  static u32 console_idx;
> +static u64 console_dropped_cnt;
>  static u64 exclusive_console_stop_seq;
>  static u64 log_first_seq;
>  static u32 log_first_idx;
> @@ -2398,20 +2400,24 @@ void console_unlock(void)
>  	for (;;) {
>  		struct printk_log *msg;
>  		size_t ext_len = 0;
> -		size_t len;
> +		size_t len = 0;
>  
>  		printk_safe_enter_irqsave(flags);
>  		raw_spin_lock(&logbuf_lock);
> +
> +		/* Reset dropped msg count when switching to all consoles. */
> +		if (unlikely(exclusive_console &&
> +			     exclusive_console_stop_seq < log_first_seq)) {
> +			console_dropped_cnt = 0;
> +			console_seq = exclusive_console_stop_seq;
> +		}
> +

Wouldn't the fix to the bug be to move the "skip" target here?

skip:

>  		if (console_seq < log_first_seq) {
> -			len = sprintf(text,
> -				      "** %llu printk messages dropped **\n",
> -				      log_first_seq - console_seq);
> +			console_dropped_cnt += log_first_seq - console_seq;
>  
>  			/* messages are gone, move to first one */
>  			console_seq = log_first_seq;
>  			console_idx = log_first_idx;
> -		} else {
> -			len = 0;
>  		}
>  skip:
>  		if (console_seq == log_next_seq)
> @@ -2435,6 +2441,13 @@ void console_unlock(void)
>  			exclusive_console = NULL;
>  		}
>  
> +		if (unlikely(console_dropped_cnt)) {
> +			len = sprintf(text,
> +				      "** %llu printk messages dropped **\n",
> +				      console_dropped_cnt);
> +			console_dropped_cnt = 0;
> +		}
> +

My only objection to this is that the "messages dropped" only comes if a
non-supressed message comes. So information about dropped information
may never get printed unless some task prints something non-supressed.

Imagine a situation where I am expecting a message to come, but don't
see it because it was dropped. But if no more non-supressed messages
come, I see neither the expected message nor the dropped message.

John Ogness

Re: [PATCH] printk/console: Do not suppress information about dropped messages

[Sergey Senozhatsky]

On (02/26/19 17:26), John Ogness wrote:
[..]
> >  		if (console_seq < log_first_seq) {
> > -			len = sprintf(text,
> > -				      "** %llu printk messages dropped **\n",
> > -				      log_first_seq - console_seq);
> > +			console_dropped_cnt += log_first_seq - console_seq;
> >  
> >  			/* messages are gone, move to first one */
> >  			console_seq = log_first_seq;
> >  			console_idx = log_first_idx;
> > -		} else {
> > -			len = 0;
> >  		}
> >  skip:
> >  		if (console_seq == log_next_seq)
> > @@ -2435,6 +2441,13 @@ void console_unlock(void)
> >  			exclusive_console = NULL;
> >  		}
> >  
> > +		if (unlikely(console_dropped_cnt)) {
> > +			len = sprintf(text,
> > +				      "** %llu printk messages dropped **\n",
> > +				      console_dropped_cnt);
> > +			console_dropped_cnt = 0;
> > +		}
> > +
> 
> My only objection to this is that the "messages dropped" only comes if a
> non-supressed message comes. So information about dropped information
> may never get printed unless some task prints something non-supressed.
> 
> Imagine a situation where I am expecting a message to come, but don't
> see it because it was dropped. But if no more non-supressed messages
> come, I see neither the expected message nor the dropped message.

I think this is exactly the problem (and thus the patch) we discussed some
3 years ago. I had a number of rather strangely looking serial logs, which
clearly had lost messages but no "%llu printk messages dropped" markers. So
I added `static bool lost_messages' to console_unlock(), set it when printing
loop would discover lost messages, then print "%llu printk messages dropped"
attached to whatever msg was next in the logbuf, regardless of msg->level.
IOW, if lost_messages was set then suppress_message_printing(msg->level)
was not even invoked. Yes, that would sometimes print several "debugging
noise" messages, but the main part was that I would have "%llu printk
messages dropped" markers in the logs; which was much more important to
me.

P.S. I'm very sorry, I'm overloaded with work at the moment; will start
     looking at pending patches in a day or two, or three, or four...

	-ss

Re: [PATCH] printk/console: Do not suppress information about dropped messages

[John Ogness]

On 2019-02-27, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>>  		if (console_seq < log_first_seq) {
>>> -			len = sprintf(text,
>>> -				      "** %llu printk messages dropped **\n",
>>> -				      log_first_seq - console_seq);
>>> +			console_dropped_cnt += log_first_seq - console_seq;
>>>  
>>>  			/* messages are gone, move to first one */
>>>  			console_seq = log_first_seq;
>>>  			console_idx = log_first_idx;
>>> -		} else {
>>> -			len = 0;
>>>  		}
>>>  skip:
>>>  		if (console_seq == log_next_seq)
>>> @@ -2435,6 +2441,13 @@ void console_unlock(void)
>>>  			exclusive_console = NULL;
>>>  		}
>>>  
>>> +		if (unlikely(console_dropped_cnt)) {
>>> +			len = sprintf(text,
>>> +				      "** %llu printk messages dropped **\n",
>>> +				      console_dropped_cnt);
>>> +			console_dropped_cnt = 0;
>>> +		}
>>> +
>> 
>> My only objection to this is that the "messages dropped" only comes if a
>> non-supressed message comes. So information about dropped information
>> may never get printed unless some task prints something non-supressed.
>> 
>> Imagine a situation where I am expecting a message to come, but don't
>> see it because it was dropped. But if no more non-supressed messages
>> come, I see neither the expected message nor the dropped message.
>
> I think this is exactly the problem (and thus the patch) we discussed
> some 3 years ago.

I guess you are referring to this [0] thread.

> I had a number of rather strangely looking serial logs, which clearly
> had lost messages but no "%llu printk messages dropped" markers. So I
> added `static bool lost_messages' to console_unlock(), set it when
> printing loop would discover lost messages, then print "%llu printk
> messages dropped" attached to whatever msg was next in the logbuf,
> regardless of msg->level.  IOW, if lost_messages was set then
> suppress_message_printing(msg->level) was not even invoked. Yes, that
> would sometimes print several "debugging noise" messages, but the main
> part was that I would have "%llu printk messages dropped" markers in
> the logs; which was much more important to me.

I would agree with the proposed solution from 2016. My experience is
that the dropped messages are very important. Yes, printing them could
lead to the loss of even more messages. But still, it is important
information that needs to get out.

John Ogness

[0] https://lkml.kernel.org/r/20161224140902.1962-3-sergey.senozhatsky@gmail.com

Re: [PATCH] printk/console: Do not suppress information about dropped messages

[Petr Mladek]

On Tue 2019-02-26 17:26:57, John Ogness wrote:
> On 2019-02-26, Petr Mladek <pmladek@suse.com> wrote:
> > The warning about dropped messages gets lost when the current
> > message is above console_loglevel and suppressed.
> 
> Here you are reporting a bug. (More on this below.)

Yes.

> > The suppressed messages allow even slow consoles to caught up
> > with a flood of messages. The consoles must not get slowed
> > down by many warnings. Instead, the warning is delayed until
> > the next printable message.
> 
> Here you are introducing a new behavior. (Also discussed below.)
> Although the two are similar, they are really 2 different things.

No, I am replacing random behavior with a predictable one to fix
the bug. The above paragraph explains why the fix looks like it looks.
Maybe I should have written somethink like:

A solution would be to print the warning regardless the log level.
But it might cause loosing more important messages because of
delay caused by the warnings.

A better solution is to count all dropped messages until there
is a non-suppressed one. Then we could print the summary
together with the message.


> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index b4d26388bc62..c3f287422ef4 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2398,20 +2400,24 @@ void console_unlock(void)
> >  	for (;;) {
> >  		struct printk_log *msg;
> >  		size_t ext_len = 0;
> > -		size_t len;
> > +		size_t len = 0;
> >  
> >  		printk_safe_enter_irqsave(flags);
> >  		raw_spin_lock(&logbuf_lock);
> > +
> > +		/* Reset dropped msg count when switching to all consoles. */
> > +		if (unlikely(exclusive_console &&
> > +			     exclusive_console_stop_seq < log_first_seq)) {
> > +			console_dropped_cnt = 0;
> > +			console_seq = exclusive_console_stop_seq;
> > +		}
> > +
> 
> Wouldn't the fix to the bug be to move the "skip" target here?

No, the entire loop skiping suppressed messages is done under
the logbuf_lock. No old messages can be lost inside this loop.

> skip:
> 
> >  		if (console_seq < log_first_seq) {
> > -			len = sprintf(text,
> > -				      "** %llu printk messages dropped **\n",
> > -				      log_first_seq - console_seq);
> > +			console_dropped_cnt += log_first_seq - console_seq;
> >  
> >  			/* messages are gone, move to first one */
> >  			console_seq = log_first_seq;
> >  			console_idx = log_first_idx;
> > -		} else {
> > -			len = 0;
> >  		}
> >  skip:
> >  		if (console_seq == log_next_seq)
> > @@ -2435,6 +2441,13 @@ void console_unlock(void)
> >  			exclusive_console = NULL;
> >  		}
> >  
> > +		if (unlikely(console_dropped_cnt)) {
> > +			len = sprintf(text,
> > +				      "** %llu printk messages dropped **\n",
> > +				      console_dropped_cnt);
> > +			console_dropped_cnt = 0;
> > +		}
> > +
> 
> My only objection to this is that the "messages dropped" only comes if a
> non-supressed message comes. So information about dropped information
> may never get printed unless some task prints something non-supressed.
> 
> Imagine a situation where I am expecting a message to come, but don't
> see it because it was dropped. But if no more non-supressed messages
> come, I see neither the expected message nor the dropped message.

Good point! There is a simple fix for this. We could print the warning
also when all messages are proceed and we are about to leave
the for-cycle.

Best Regards,
Petr

Re: [PATCH] printk/console: Do not suppress information about dropped messages

[Sergey Senozhatsky]

On (02/27/19 09:12), John Ogness wrote:
> >> 
> >> My only objection to this is that the "messages dropped" only comes if a
> >> non-supressed message comes. So information about dropped information
> >> may never get printed unless some task prints something non-supressed.
> >> 
> >> Imagine a situation where I am expecting a message to come, but don't
> >> see it because it was dropped. But if no more non-supressed messages
> >> come, I see neither the expected message nor the dropped message.
> >
> > I think this is exactly the problem (and thus the patch) we discussed
> > some 3 years ago.
> 
> I guess you are referring to this [0] thread.

Right.

[..]
> I would agree with the proposed solution from 2016. My experience is
> that the dropped messages are very important. Yes, printing them could
> lead to the loss of even more messages.

Yes, printing out messages does take time. But I think it's easier to
start losing messages due to preemption under console_sem than due to
call_console_drivers() latencies.

> But still, it is important information that needs to get out.

I'd agree. A summary "you lost %d messages somewhere between current
and previous messages" is surely better than what we have now, but is
still a bit less informative than "you lost %d messages just now".

	-ss

Re: [PATCH] printk/console: Do not suppress information about dropped messages

[John Ogness]

On 2019-02-27, Petr Mladek <pmladek@suse.com> wrote:
>> Imagine a situation where I am expecting a message to come, but don't
>> see it because it was dropped. But if no more non-supressed messages
>> come, I see neither the expected message nor the dropped message.
>
> Good point! There is a simple fix for this. We could print the warning
> also when all messages are proceed and we are about to leave the
> for-cycle.

Yes! That is the piece that was missing!

John Ogness

Re: [PATCH] printk/console: Do not suppress information about dropped messages

[Sergey Senozhatsky]

On (02/27/19 09:30), Petr Mladek wrote:
> Good point! There is a simple fix for this. We could print the warning
> also when all messages are proceed and we are about to leave
> the for-cycle.

I'd prefer to have lost-messages reporting be less of a summary
and more of an "error". I think the sooner we report it the better.
I don't think that the time we need to print lost-messages on the
consoles is significant enough to worry about it; if call_console_drivers()
becomes such a problem that any extra char we print causes message-drop then
we can disable printk_time or/and printk caller_id prefix printout (can
save us more CPU cycles).

	-ss