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

[Sergey Senozhatsky]

On (01/04/17 16:26), Petr Mladek wrote:
> On Wed 2017-01-04 22:34:48, Sergey Senozhatsky wrote:
> > On (01/04/17 11:52), Petr Mladek wrote:
> > [..]
> > > > this is from the real serial logs I'm looking at right now. we attach
> > > > "bad news" to 'critical' messages only:
> > > > 
> > > > ...
> > > > [   32.941061] bc00: b65dc0d8 b65dc6d0 ae1fbc7c b65c11c5 b563c9c4 00000001 b65dc6d0 b0a62f74
> > > > ** 150 printk messages dropped ** [   32.941614] cee0: 00000081 ae1fcef0 00000038 00000000 b5369000 ae1fcf00 ae1fd0f0 00000000
> > > > ** 75 printk messages dropped ** [   32.941892] d860: 00056608 af203848 00000000 0004088c 000000d0 00000000 00000000 00000000
> > > > ** 12 printk messages dropped ** [   32.941940] ..
> > > > ** 2 printk messages dropped ** [   32.941951] ..
> > > > ** 10 printk messages dropped ** [   32.941992] ..
> > > > ** 1 printk messages dropped ** [   32.941999] ..
> > > > ...
> 
> OK, it is possible that I miss-interpreted the message. It looked like
> a random memory dump that did not make sense without a context.
> 
> 
> > > Do you see how useless the above messages are, please?
> > 
> > what... these lost messages were of extreme importance. I can't tell
> > the exactly the loglevel, but I'm sure it was at least pr_err() level.
> > these were like really important messages, unlike the ones that got
> > suppressed/filtered-out.
> 
> It means that you were lucky and you saw critical messages instead
> of some random debugging ones.

this is funny. ok... let me tell you my version.
I saw an incomplete serial log with lost important messages. the serial
log was nothing but garbage. zero value. I could simply `rm screenlog.0'
it. end of story.

and no matter what loglevel we attach the "printk messages dropped"
to we always will lose XYZ important messages in the given circumstances.
and that "let's print 1 out of thousands lost critical messages, so the
serial log will make sense" is a little bit far from being true. sorry,
it is what it is.


> > and the options here are
> > 	"print 1 random message out of XXX or XXXX lost messages"
> > vs
> > 	"print 1 random message out of XXX or XXXX lost messages"
> 
> And this is not fully correct and probably the root of
> the misunderstanding. The difference between your patch
> and mine patch is:
> 
> 	"always print '%u printk messages dropped'" +
> 	"print 1 random message out of XXX or XXXX lost messages"
> 
> vs
> 
> 	"always print '%u printk messages dropped'" +
> 	"print 1 random message with level under console_level
> 	 out of XXX or XXXX lost messages"
> 
> and that's it. I am sorry if I was not able to explain this
> a more clear way.


... I understand what your patch is doing. see the serial log atop of
this message, this is from the 'attach "printk messages dropped to a
visible loglevel"' approach. what I don't understand is why do you
claim that it produces significantly more meaningful/useful serial logs.
because it does not. it produces the 'rm screenlog.0' material. we
can't protect/save/take care of/whatever the logbuf messages once we
unlock the logbuf lock. and the point is - for a guy who reads the
incomplete serial log 'print 1 random message out of XXX or XXXX lost
messages' is pretty much the same as 'print 1 random message of visible
loglevel out of XXX or XXXX lost messages'. because the really important
part here is 'you see 1 message out of XXXX', and there is no way to
reconstruct those XXXX lost messages, no matter how small the XXXX is:

[   x.xxxx] Call Trace:
** 9 printk messages dropped ** [   x.xxxx] ---[ end trace ]---

	-ss