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

Groups > linux.kernel > #1550387 > 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 Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-01-04 03:50 +0100
    Re: [PATCH 2/2] printk: always report lost messages on serial console Petr Mladek <pmladek@suse.com> - 2017-01-04 12:00 +0100
      Re: [PATCH 2/2] printk: always report lost messages on serial console Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-01-04 14:40 +0100
        Re: [PATCH 2/2] printk: always report lost messages on serial console Petr Mladek <pmladek@suse.com> - 2017-01-04 16:30 +0100
          Re: [PATCH 2/2] printk: always report lost messages on serial console Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-01-05 03:40 +0100
            Re: [PATCH 2/2] printk: always report lost messages on serial console Petr Mladek <pmladek@suse.com> - 2017-01-05 12:20 +0100

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

On (01/03/17 17:53), Petr Mladek wrote:
> On Wed 2017-01-04 00:47:45, Sergey Senozhatsky wrote:
> > On (01/03/17 15:55), Petr Mladek wrote:
> > [..]
> > > This causes the opposite problem. We might print a message that was supposed
> > > to be suppressed.
> > 
> > so what? yes, we print a message that otherwise would have been suppressed.
> > not a big deal. at all. we are under high printk load and the best thing
> > we can do is to report "we are losing the messages" straight ahead. the
> > next 'visible' message may be seconds/minutes/forever away. think of a
> > printk() flood of messages with suppressed loglevel coming from CPUA-CPUX,
> > big enough to drain all 'visible' loglevel messages from CPUZ. we are
> > back to problem "a".
> > 
> > thus I want a simple bool flag and a simple rule: we see something - we say it.
> 
> So, you prefer to print some random debug message instead of an
> emergency one?

yep. because console_unlock() is not the right place to address printk()
abuse, and console_unlock() cannot address it. the only way to fix it is
to reduce the amount of printk() calls (well, there is one more thing
probably and may be but not really *).


> It will always drop a message because you always process only one
> and many new appear in the meantime. While with my solution,
> you should see:
> 
> ** 1324 printk messages dropped ** <alert: random message>
> ** 523 printk messages dropped ** <emerg: random message>
> ** 324 printk messages dropped ** <emerg: random message>
> ** 345 printk messages dropped ** <alert: random message>

once you started losing the messages because of printk() flood you will
lose them no matter what you do. console_unlock() cannot force printk() CPUs
to add less messages to the logbuf, so we magically can have enough time to
print the message on the consoles. any call to console drivers leads to lost
messages. there is no difference. 

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] ..
...

note how many critical messages I lost in consecutive console drivers calls
because console_unlock() was printing other critical messages.
no matter what we filter-out in console_unlock() we are still far-far-far
behind the CPUs that flood the printk buffer. and those CPUs will be happy
to drain any critical/visible message from the logbuf.




* may be can do something like this:

two logbuf buffers. one for `everything' -- both suppressed and visible
loglevels. this one is also used by dmesg. the other one if for messages
that won't be suppressed. we call_console_drivers() on that buffer.
so vprintk_emit() becomes

vprintk_emit()
{
	spin_lock logbuf_lock

	text = sprintf(...)

	log_store(logbuf)
	if (!suppress_message_printing(level))
		log_store(printing_lofbuf)

	spin_ulock logbuf_lock
}

and console_unlock() reads printing_logbuf only. but we still can lose
messages even from filtered printing_logbuf.

	-ss

[toc] | [next] | [standalone]

#1550655

On Wed 2017-01-04 11:46:50, Sergey Senozhatsky wrote:
> On (01/03/17 17:53), Petr Mladek wrote:
> > On Wed 2017-01-04 00:47:45, Sergey Senozhatsky wrote:
> > > On (01/03/17 15:55), Petr Mladek wrote:
> > > [..]
> > > > This causes the opposite problem. We might print a message that was supposed
> > > > to be suppressed.
> > > 
> > > so what? yes, we print a message that otherwise would have been suppressed.
> > > not a big deal. at all. we are under high printk load and the best thing
> > > we can do is to report "we are losing the messages" straight ahead. the
> > > next 'visible' message may be seconds/minutes/forever away. think of a
> > > printk() flood of messages with suppressed loglevel coming from CPUA-CPUX,
> > > big enough to drain all 'visible' loglevel messages from CPUZ. we are
> > > back to problem "a".
> > > 
> > > thus I want a simple bool flag and a simple rule: we see something - we say it.
> > 
> > So, you prefer to print some random debug message instead of an
> > emergency one?
> 
> yep. because console_unlock() is not the right place to address printk()
> abuse, and console_unlock() cannot address it. the only way to fix it is
> to reduce the amount of printk() calls (well, there is one more thing
> probably and may be but not really *).

Yes and no. Please note that writing into logbug is fast while
writing to the serial console is slow. This is why we have
console_level. It allows to filter only the critical messages
for the slow output.


> > It will always drop a message because you always process only one
> > and many new appear in the meantime. While with my solution,
> > you should see:
> > 
> > ** 1324 printk messages dropped ** <alert: random message>
> > ** 523 printk messages dropped ** <emerg: random message>
> > ** 324 printk messages dropped ** <emerg: random message>
> > ** 345 printk messages dropped ** <alert: random message>
> 
> once you started losing the messages because of printk() flood you will
> lose them no matter what you do. console_unlock() cannot force printk() CPUs
> to add less messages to the logbuf, so we magically can have enough time to
> print the message on the consoles. any call to console drivers leads to lost
 > messages. there is no difference.
> 
> 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] ..
> ...

Do you see how useless the above messages are, please?
Are they really printed with KERN_EMERG or KERN_ALERT prefix?

IMHO, the point of the log levels and console_level is
to have a chance to see the more informative messages
on the slow medium (serial console).

BTW: It is questionable if messages with LOGLEVEL_DEFAULT are
always printed but this is another story.


> note how many critical messages I lost in consecutive console drivers calls
> because console_unlock() was printing other critical messages.
> no matter what we filter-out in console_unlock() we are still far-far-far
> behind the CPUs that flood the printk buffer. and those CPUs will be happy
> to drain any critical/visible message from the logbuf.
> 
> * may be can do something like this:
> 
> two logbuf buffers. one for `everything' -- both suppressed and visible
> loglevels. this one is also used by dmesg. the other one if for messages
> that won't be suppressed. we call_console_drivers() on that buffer.
> so vprintk_emit() becomes
> 
> vprintk_emit()
> {
> 	spin_lock logbuf_lock
> 
> 	text = sprintf(...)
> 
> 	log_store(logbuf)
> 	if (!suppress_message_printing(level))
> 		log_store(printing_lofbuf)
> 
> 	spin_ulock logbuf_lock
> }
> 
> and console_unlock() reads printing_logbuf only. but we still can lose
> messages even from filtered printing_logbuf.

Please, do not do this. IMHO, it will not improve the situation much.
Let me repeat. Writing into logbuf and filtering messages is
relatively fast. The slow thing is printing to the serial console.

Also writing and filtering is done under logbuf_lock
which blocks other writers. This is a natural throttling of
other writers. On the other hand, the console handling is done
without logbuf_lock and other writers might do anything in the
meantime.

It might make sense to allow filtering messages that are
stored to the logbuffer. But this is orthogonal to the
console output filtering.

Also we should improve the API to make it easier to throotle
the same messages. Or allow to throotle all messages.

Anyway, your patch breaks console output filtering. This is
why I am against it and propose another solution.

Best Regards,
Petr

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

#1550775

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] ..
> > ...
> 
> 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.

along with these lost messages that were supposed to be printed, I have
regions of lost kernel messages (?) with no reports of lost messages from
console_unlock() (!). and that's the only thing I'm fixing here. and the
only thing we can fix. no permutation of console_unlock() lines will make
the buffer bigger or printk flooding CPUs nicer or serial console driver
faster.

once we unlocked the logbuf lock in console_unlock() we lost the race
against the printk() flooding CPUs. all, or some, of the remaining
messages, no matter how important and critical, will be drained. the
next time we lock the logbuf again the logbuf will not be the same.
the only meaningful thing we can print now is "XXX printk messages
dropped". we don't know what was in those messages and no one will ever
find out. it's gone.

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 that's really it. except that in the second case we shuffle
console_unlock() lines with no gain. and I'm not sure I understand
why we even discuss it. both options are absolutely equally terrible,
because the root cause of the problem is in completely different
place.

	-ss

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

#1550923

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.


> along with these lost messages that were supposed to be printed, I have
> regions of lost kernel messages (?) with no reports of lost messages from
> console_unlock() (!). and that's the only thing I'm fixing here.

My patch fixes it as well. But it also keeps the function of
console_level filtering.


> and the
> only thing we can fix. no permutation of console_unlock() lines will make
> the buffer bigger or printk flooding CPUs nicer or serial console driver
> faster.

We should stay on a constructive note. I never wrote that my patch
would make the buffer bigger or the serial console faster.


> once we unlocked the logbuf lock in console_unlock() we lost the race
> against the printk() flooding CPUs.

My patch did not have ambition to solve this problem.


> 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 think that we both should take a deep breath and calm down
a bit. I am afraid that I used some formulations that made
you angry and put us in an offensive mode. Maybe I was not
able to clearly describe my concerns and their severity.
Maybe you feel offended because I produced an alternative
patch and did not keep enough credits to you. I am sorry
for this. I will try better next time.

Best Regards,
Petr

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

#1551579

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

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

#1551897

On Thu 2017-01-05 11:30:47, Sergey Senozhatsky wrote:
> 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] ..
> > > > > ...

Please, be more explicit. What exactly was of extreme imporance
in the output above?

Was it the information about lost messages?

    ** XXX printk messages dropped **

Or was is some of the data?

    [   32.941614] cee0: 00000081 ae1fcef0 00000038 00000000 b5369000 ae1fcf00 ae1fd0f0 00000000
    [   32.941892] d860: 00056608 af203848 00000000 0004088c 000000d0 00000000 00000000 00000000


> > 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.
> 
> 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.

I never claimed that you would see more messages with my patch.
I claimed that you should see messages with the requested severity
level with my patch.

If you get better results with random messages than I see two
possibilities:

  + some/many messages have assigned wrong level

  + the message levels are useless in general


> > > 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.

atop? I am lost. There is only one real-life output atop of this
message and you claimed that it was of extreme importance. I thought
that you got it with your patch.


> 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:

If it does not matter what message we print then why do we have
the log levels in the first place?


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

This is unfortunate. This line does not include any useful
information but it is part of an important blob of lines.

A solution might be to proceed more lines of the same level
at once. One line usually is not enough. We will still get
only random blobs of lines but at least some of them should
be more usable than single random lines.

Best Regards,
Petr

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web