Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1554498 > unrolled thread

Re: [PATCH 2/2] printk: always report lost messages on serial console

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH 2/2] printk: always report lost messages on serial console Petr Mladek <pmladek@suse.com> - 2017-01-09 18:00 +0100
    Re: [PATCH 2/2] printk: always report lost messages on serial console Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-01-10 09:50 +0100
      Re: [PATCH 2/2] printk: always report lost messages on serial console Petr Mladek <pmladek@suse.com> - 2017-01-11 18:00 +0100
        Re: [PATCH 2/2] printk: always report lost messages on serial console Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-01-13 06:20 +0100

#1554498 — Re: [PATCH 2/2] printk: always report lost messages on serial console

On Sat 2016-12-24 23:09:02, Sergey Senozhatsky wrote:
> The "printk messages dropped" report is 'attached' to a kernel
> message located at console_idx offset. This does not work well
> if we skip that message due to loglevel filtering, because in
> this case we also skip/lose dropped message report.
> 
> Disable suppress_message_printing() loglevel filtering if we
> must report "printk messages dropped" condition.

I have looked at this once again. Please, do you have a real-life
example when the "printk messages dropped" was not printed?

I ask because the original code looks like this this:

		if (console_seq < log_first_seq) {
			<store warning into "text" buffer>
			console_seq = log_first_seq;
			console_idx = log_first_idx;

skip:
		if (console_seq == log_next_seq)
			break;

		msg = log_from_idx(console_idx);
		if (suppress_message_printing(msg->level)) {
			console_idx = log_next(console_idx);
			console_seq++;
			goto skip;
		}

		<add visible messsage into "text" buffer>

		console_idx = log_next(console_idx);
		console_seq++;
		raw_spin_unlock(&logbuf_lock);

		<push "text" buffer to console>


By other words, the search for a visible message is finished when
we find one or when the entire log buffer is checked.

As a consequence, the warning about "printk messages dropped" is
lost _only_ when there was no visible message in the entire buffer.

Therefore, the warning might get lost only when the log buffer
was very small or when console_level filter was too restricting.
I wonder if this is a case for a real user or a real life.
In each case, such a scenario most likely comes from a very
curious setup.

It is possible that your fix is fine. If we lose messages,
we are screwed anyway. But I still have problems to accept
that we would start printing less important messages (that would
normally be ignored) in situation when we have troubles
to print the more important ones. This logic rings warning
bells in my head and this is why I suggest more conservative
solution and ask the many questions.

Am I so wrong in my thinking, please?

Best Regards,
Petr

[toc] | [next] | [standalone]

#1555052

On (01/09/17 17:56), Petr Mladek wrote:
> I have looked at this once again. Please, do you have a real-life
> example when the "printk messages dropped" was not printed?

.....


> By other words, the search for a visible message is finished when
> we find one or when the entire log buffer is checked.
> 
> As a consequence, the warning about "printk messages dropped" is
> lost _only_ when there was no visible message in the entire buffer.
> 
> Therefore, the warning might get lost only when the log buffer
> was very small or when console_level filter was too restricting.

with a slow serial console even a relatively large logbuf can
easily become a "not quite large enough" logbuf. especially
when the underlying uart_port ->lock is concurrently accessed
by uart circ_buf flushing.


> I wonder if this is a case for a real user or a real life.
> In each case, such a scenario most likely comes from a very
> curious setup.
> 
> It is possible that your fix is fine. If we lose messages,
> we are screwed anyway. But I still have problems to accept
> that we would start printing less important messages (that would
> normally be ignored) in situation when we have troubles
> to print the more important ones. This logic rings warning
> bells in my head and this is why I suggest more conservative
> solution and ask the many questions.

once the system is in "oh, let me drop some of the messages for you"
mood, loglevel filtering is unreliable and in some cases unneeded.
it's so unreliable that I'm even considering disabling it in *in-house*
builds when console_unlock() detects that there was no room for all
'yet to be seen' messages.


those are another messages, with 'visible' loglevel or with 'suppressed'
loglevel or both 'visible' and 'suppressed' loglevels, that caused the
logbuf overflow.

now, if the loss of messages was caused by:

a) flood of suppressed loglevel messages
   then printing at least some of those messages makes *a lot* of sense.
   it really does. because those messages will point at the root cause of
   the problem. and there is no other way of finding that out when all you
   have is a serial log of visible messages. those 'suppressed messages'
   part is the key. whatever loglevel it was, the fact that we overflowed
   the logbuf with those messages is already bad.



b) flood of visible loglevel messages
   then may be those messages are not so important. there a whole logbuf of
   them. per my experience, it is quite hard to overflow the logbuf with
   really important, unique, sensible messages of 'visible' loglevel with
   active loglevel filtering. in most of the cases I've seen, those "important"
   messages are the same repeating messages. OOM is the most notable example:
   it can flood logbuf with pretty much same backtraces and Mem-Info printouts.
   for instance - CPU that stuck in GFP_REPEAT allocation under OOM. or memory
   allocation error in swap out path under OOM:

   ...
   [3282.5292] Node    0, zone   XXXX, type      Isolate      0      0      0      0      0      0      0      0      0      0      0 
   [3282.5292] Node    0, zone   XXXX, type    Unmovable      0      0      0      0      0      0      0      0      0      0      0 
   ** 1389 printk messages dropped ** [3282.5430] Write-error on swap-device (254:0:1471944)
   ** 354 printk messages dropped ** [3282.5526] Write-error on swap-device (254:0:1473240)
   ** 254 printk messages dropped ** [3282.5598] Write-error on swap-device (254:0:1474472)
   [3282.5598] SLUB: Unable to allocate memory on xxxxxxx
   		blah-blah-blah
   ...
   [3282.5606] Write-error on swap-device (254:0:1474480)
   [3282.5607] Write-error on swap-device (254:0:1474496)
   [3282.5607] Write-error on swap-device (254:0:1474504)
   [3282.5608] Write-error on swap-device (254:0:1474504)
   [3282.5610] Write-error on swap-device (254:0:1474528)
   [3282.5611] Write-error on swap-device (254:0:1474544)
   ** 519 printk messages dropped ** [3282.5611] Write-error on swap-device (254:0:1477152)
   ** 15 printk messages dropped ** [3282.5616] Write-error on swap-device (254:0:1477208)
   ...
   [3283.0532] zram: Error allocating memory for compressed page: 200385, size=2824
   ...

   those messages preempt each other and preempt other *may be actually
   important* 'visible' loglevel messages. but there is no way to tell
   which one of the messages vprintk_emit() is about to overwrite is actually
   important. the outcome is -- the important repeating messages are _mostly_
   as valuable as the suppressed ones. IOW, not every important message is
   really important under 'out of logbuf' condition. and vice versa.



c) both a) and b)
   printing both suppressible and 'visible' loglevels makes sense here.


considering a) and b):

once the system is out of logbuf space it is impossible to clearly
distinguish between 'important' and 'not so important' messages. all
we know in console_unlock(), when we pick up next_idx message, is that
there is an abnormal/unusual/weird/unexpected/sick/whatever amount of
messages - 'suppressed' or 'visible' or both. and that's the problem.

"print as much of those messages as possible, don't hide the problem" - that's
why I'm thinking of no loglevel filtering in 'ouf of logbuf space' case.

	-ss

[toc] | [prev] | [next] | [standalone]

#1556715

Hi Sergey,

first, thanks a lot for the detailed description. I have finally
understood what was important on the "non-important" messages
and how you used them. I am sorry that I was not able to get
it earlier.

On Tue 2017-01-10 17:49:39, Sergey Senozhatsky wrote:
> On (01/09/17 17:56), Petr Mladek wrote:
> > It is possible that your fix is fine. If we lose messages,
> > we are screwed anyway. But I still have problems to accept
> > that we would start printing less important messages (that would
> > normally be ignored) in situation when we have troubles
> > to print the more important ones. This logic rings warning
> > bells in my head and this is why I suggest more conservative
> > solution and ask the many questions.
>
> once the system is in "oh, let me drop some of the messages for you"
> mood, loglevel filtering is unreliable and in some cases unneeded.
> it's so unreliable that I'm even considering disabling it in *in-house*
> builds when console_unlock() detects that there was no room for all
> 'yet to be seen' messages.
> 
> those are another messages, with 'visible' loglevel or with 'suppressed'
> loglevel or both 'visible' and 'suppressed' loglevels, that caused the
> logbuf overflow.
> 
> now, if the loss of messages was caused by:
> 
> a) flood of suppressed loglevel messages
>    then printing at least some of those messages makes *a lot* of sense.
> 
> b) flood of visible loglevel messages
>    then may be those messages are not so important. there a whole logbuf of
>    them. per my experience, it is quite hard to overflow the logbuf with
>    really important, unique, sensible messages of 'visible' loglevel with
>    active loglevel filtering.

Just for record, I guess that the same is true also for the messages
with lower level. I mean that they are repeating as well. It would be
great to make it easier to throttle the same messages or do it a
generic way. But this a food for the future work.

> once the system is out of logbuf space it is impossible to clearly
> distinguish between 'important' and 'not so important' messages. all
> we know in console_unlock(), when we pick up next_idx message, is that
> there is an abnormal/unusual/weird/unexpected/sick/whatever amount of
> messages - 'suppressed' or 'visible' or both. and that's the problem.

It is true that lost messages is a "serious" problem because you might
miss message about a "really" serious problem. The normally important
messages are less useful because they are incomplete. It makes sense
to debug what causes the flood. The key is to ignore loglevel and
print what is being stored.

Your patch makes perfect sense from this point of view. Please,
mention such an explanation in the next iteration of the patch.


Ah, you will kill me. I still have one thing. The levels are defined
like this:

#define KERN_EMERG	KERN_SOH "0"	/* system is unusable */
#define KERN_ALERT	KERN_SOH "1"	/* action must be taken immediately */
#define KERN_CRIT	KERN_SOH "2"	/* critical conditions */
#define KERN_ERR	KERN_SOH "3"	/* error conditions */

The flood of messages usually means something pretty wrong. But
it might also be caused by too many or forgotten debug messages.

It think that lost messages belong to the level "2". Note that
the warning about lost NMI messages and recent printk recursion
were printed with loglevel '2' as well.

Would it make sense and be acceptable to ignore the log level
only when console_level allows to show KERN_CRIT messages?

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1558025

Hi,

On (01/11/17 17:50), Petr Mladek wrote:
> Hi Sergey,
> 
> first, thanks a lot for the detailed description. I have finally
> understood what was important on the "non-important" messages
> and how you used them. I am sorry that I was not able to get
> it earlier.

sure, no prob. I was mostly offline for the past few days for personal
reasons but now I'm back.

[..]
> > now, if the loss of messages was caused by:
> > 
> > a) flood of suppressed loglevel messages
> >    then printing at least some of those messages makes *a lot* of sense.
> > 
> > b) flood of visible loglevel messages
> >    then may be those messages are not so important. there a whole logbuf of
> >    them. per my experience, it is quite hard to overflow the logbuf with
> >    really important, unique, sensible messages of 'visible' loglevel with
> >    active loglevel filtering.
> 
> Just for record, I guess that the same is true also for the messages
> with lower level. I mean that they are repeating as well.

right. those are 100% reproducible, quick to spot and easy to fix, I
guess. a spontaneous explosion is a different/bigger problem. though
the end result is the same -- we lose messages, may be very important
ones. our best effort/goal is to print logbuf content. that's why we
are playing with nmi/safe printk; zap locks; ignore locks state in
some cases; and so on and on. but when we lose messages that were
meant to be printed even _before_ we try to print them out, then our
best effort is sort of void/undefined.


> It would be great to make it easier to throttle the same messages or
> do it a generic way. But this a food for the future work.

yes. syslog tracks "duplicate messages". but I kinda couldn't understand
how helpful it will be in vprintk_emit() /* because it's too late to track
duplicates in console_unlock(). duplicates should not be stored in multiple
instances in the first place */. backtraces are hard to suppress, besides we
shouldn't suppress backtraces I think. log_store() would have to strcmp() or
"hash+compare hashes" current message and the most recent logbuf message.
but bigger concern is -- do people see dropped messages that often to add
duplicate messages tracker to vprintk_emit()? I see dropped messages quite
a lot, but that's just my setup.


> #define KERN_EMERG	KERN_SOH "0"	/* system is unusable */
> #define KERN_ALERT	KERN_SOH "1"	/* action must be taken immediately */
> #define KERN_CRIT	KERN_SOH "2"	/* critical conditions */
> #define KERN_ERR	KERN_SOH "3"	/* error conditions */
> 
> The flood of messages usually means something pretty wrong. But
> it might also be caused by too many or forgotten debug messages.

well. it's still really a lot of forgotten messages. so much that
we have to drop other messages. so I'd say the root cause is less
important (if important at all) as long as the result is "lost messages".


> It think that lost messages belong to the level "2". Note that
> the warning about lost NMI messages and recent printk recursion
> were printed with loglevel '2' as well.
> 
> Would it make sense and be acceptable to ignore the log level
> only when console_level allows to show KERN_CRIT messages?

need to think. what will it improve?


// I'm catching up with the emails, it'll take some time.

	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web