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

Groups > linux.kernel > #1547062 > unrolled thread

[PATCH 0/2] printk: always report dropped messages

Back to article view | Back to linux.kernel

Contents

  [PATCH 0/2] printk: always report dropped messages Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-12-24 15:20 +0100
    [PATCH 1/2] printk: drop call_console_drivers() unused param Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-12-24 15:20 +0100
      Re: [PATCH 1/2] printk: drop call_console_drivers() unused param Petr Mladek <pmladek@suse.com> - 2017-01-03 11:30 +0100
    [PATCH 2/2] printk: always report lost messages on serial console Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-12-24 15:20 +0100
      Re: [PATCH 2/2] printk: always report lost messages on serial console Petr Mladek <pmladek@suse.com> - 2017-01-03 16:00 +0100
        Re: [PATCH 2/2] printk: always report lost messages on serial console Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-01-03 16:50 +0100
          Re: [PATCH 2/2] printk: always report lost messages on serial console Petr Mladek <pmladek@suse.com> - 2017-01-03 18:20 +0100

#1547062 — [PATCH 0/2] printk: always report dropped messages

Hello,

	Two patches: trivial clean up and console_unlock() "fix".

The `printk messages dropped' report is printed as part of actual
kernel message, that's why we do 'text + len, sizeof(text) - len'
later in msg_print_text().

The problem here is that we may eventually skip the message, and
thus lose the 'printk messages dropped' report, if `console_loglevel'
check tells us to do so. Missing kernel messages in serial log
together with the missing 'printk messages dropped' can be quite
confusing.


There are two options to address it:
a) forbid suppress_message_printing() if we know that we must print
   `printk messages dropped'

b) print `printk messages dropped' as a standalone message.


Sergey Senozhatsky (2):
  printk: drop call_console_drivers() unused param
  printk: always report lost messages on serial console

 kernel/printk/printk.c | 15 +++++++--------
 1 file changed, 7 insertions(+), 8 deletions(-)

-- 
2.11.0

[toc] | [next] | [standalone]

#1547063 — [PATCH 1/2] printk: drop call_console_drivers() unused param

We do suppress_message_printing() check before we call
call_console_drivers() now, so `level' param is not needed
anymore.

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e2cdd87e7a63..11a9842a2f47 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1510,8 +1510,7 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
  * log_buf[start] to log_buf[end - 1].
  * The console_lock must be held.
  */
-static void call_console_drivers(int level,
-				 const char *ext_text, size_t ext_len,
+static void call_console_drivers(const char *ext_text, size_t ext_len,
 				 const char *text, size_t len)
 {
 	struct console *con;
@@ -1895,8 +1894,7 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
 static ssize_t msg_print_ext_body(char *buf, size_t size,
 				  char *dict, size_t dict_len,
 				  char *text, size_t text_len) { return 0; }
-static void call_console_drivers(int level,
-				 const char *ext_text, size_t ext_len,
+static void call_console_drivers(const char *ext_text, size_t ext_len,
 				 const char *text, size_t len) {}
 static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
@@ -2220,7 +2218,6 @@ void console_unlock(void)
 		struct printk_log *msg;
 		size_t ext_len = 0;
 		size_t len;
-		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
@@ -2243,8 +2240,7 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		level = msg->level;
-		if (suppress_message_printing(level)) {
+		if (suppress_message_printing(msg->level)) {
 			/*
 			 * Skip record we have buffered and already printed
 			 * directly to the console when we received it, and
@@ -2270,7 +2266,7 @@ void console_unlock(void)
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(level, ext_text, ext_len, text, len);
+		call_console_drivers(ext_text, ext_len, text, len);
 		start_critical_timings();
 		local_irq_restore(flags);
 
-- 
2.11.0

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

#1549677 — Re: [PATCH 1/2] printk: drop call_console_drivers() unused param

On Sat 2016-12-24 23:09:01, Sergey Senozhatsky wrote:
> We do suppress_message_printing() check before we call
> call_console_drivers() now, so `level' param is not needed
> anymore.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 12 ++++--------
>  1 file changed, 4 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e2cdd87e7a63..11a9842a2f47 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1510,8 +1510,7 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
>   * log_buf[start] to log_buf[end - 1].
>   * The console_lock must be held.
>   */
> -static void call_console_drivers(int level,
> -				 const char *ext_text, size_t ext_len,
> +static void call_console_drivers(const char *ext_text, size_t ext_len,
>  				 const char *text, size_t len)

Yup, this patch makes sense on its own. The level parameter is unused
since the commit cf7754441c563230ed7 ("printk: introduce
suppress_message_printing()").

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

Best Regards,
Petr

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

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

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.

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 11a9842a2f47..6a7ebcb0bb6e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2218,6 +2218,7 @@ void console_unlock(void)
 		struct printk_log *msg;
 		size_t ext_len = 0;
 		size_t len;
+		bool report_dropped_msg = false;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
@@ -2232,6 +2233,7 @@ void console_unlock(void)
 			/* messages are gone, move to first one */
 			console_seq = log_first_seq;
 			console_idx = log_first_idx;
+			report_dropped_msg = true;
 		} else {
 			len = 0;
 		}
@@ -2240,7 +2242,8 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (suppress_message_printing(msg->level)) {
+		if (!report_dropped_msg &&
+				suppress_message_printing(msg->level)) {
 			/*
 			 * Skip record we have buffered and already printed
 			 * directly to the console when we received it, and
-- 
2.11.0

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

#1549845 — 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.

Good catch!

> Disable suppress_message_printing() loglevel filtering if we
> must report "printk messages dropped" condition.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 11a9842a2f47..6a7ebcb0bb6e 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2218,6 +2218,7 @@ void console_unlock(void)
>  		struct printk_log *msg;
>  		size_t ext_len = 0;
>  		size_t len;
> +		bool report_dropped_msg = false;
>  
>  		raw_spin_lock_irqsave(&logbuf_lock, flags);
>  		if (seen_seq != log_next_seq) {
> @@ -2232,6 +2233,7 @@ void console_unlock(void)
>  			/* messages are gone, move to first one */
>  			console_seq = log_first_seq;
>  			console_idx = log_first_idx;
> +			report_dropped_msg = true;
>  		} else {
>  			len = 0;
>  		}
> @@ -2240,7 +2242,8 @@ void console_unlock(void)
>  			break;
>  
>  		msg = log_from_idx(console_idx);
> -		if (suppress_message_printing(msg->level)) {
> +		if (!report_dropped_msg &&
> +				suppress_message_printing(msg->level)) {
>  			/*
>  			 * Skip record we have buffered and already printed
>  			 * directly to the console when we received it, and

This causes the opposite problem. We might print a message that was supposed
to be suppressed. I think that it is not a good idea in this
situation. I played with it and cooked a patch, see below.

Please, do not feel offended. I do not want to take you credits
for finding the problem.

But the printk code is very twisted and console_unlock() is one
of the worst pieces. Solution based on my concerns could make
it even worse. I do not want to push you into clean ups and
tried it myself.

The result is not as good as I hoped. But it it is not worse, IMHO.
Which is good given the circumstances.

Feel free to provide even better one and use pieces from my patch.
I also think about spling it into two patches and make msg_print()
helper in a separate patch.



From 976073de3e0f3daa4f1d700ef605165d97533c9b Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Tue, 3 Jan 2017 14:32:04 +0100
Subject: [PATCH] printk: Always report lost messages on serial console

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.

A simple solution would be to ignore the level and always print
the warning with the next message.

But the situation suggests that we are under a high load and
could not afford printing less important messages.

Also we could not print only the warning because we might lose
even more messages in the meantime.

The best solution seems to be to print the warning with
the next visible message.

This patch tries to keep readability of the code. It puts
msg_print*() calls into a helper function. Also it hides there
the visibility check. As a result we could have only one copy of

	console_idx = log_next(console_idx);
	console_seq++;

Reported-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 61 ++++++++++++++++++++++++++++----------------------
 1 file changed, 34 insertions(+), 27 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0dbde4e7bb15..7cc2e7effdc3 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1234,6 +1234,28 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *bu
 	return len;
 }
 
+static bool console_check_and_print_msg(u32 console_idx,
+			     char *text, size_t size, size_t *len,
+			     char *ext_text, size_t ext_size, size_t *ext_len)
+{
+	struct printk_log *msg = log_from_idx(console_idx);
+
+	if (suppress_message_printing(msg->level))
+		return false;
+
+	*len += msg_print_text(msg, false, text, size);
+	if (nr_ext_console_drivers) {
+		*ext_len = msg_print_ext_header(ext_text, ext_size,
+						msg, console_seq);
+		*ext_len += msg_print_ext_body(ext_text + *ext_len,
+					       ext_size - *ext_len,
+					       log_dict(msg), msg->dict_len,
+					       log_text(msg), msg->text_len);
+	}
+
+	return true;
+}
+
 static int syslog_print(char __user *buf, int size)
 {
 	char *text;
@@ -2215,9 +2237,9 @@ void console_unlock(void)
 	}
 
 	for (;;) {
-		struct printk_log *msg;
+		bool printed_msg = false;
 		size_t ext_len = 0;
-		size_t len;
+		size_t len = 0;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
@@ -2232,37 +2254,22 @@ void console_unlock(void)
 			/* 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)
-			break;
 
-		msg = log_from_idx(console_idx);
-		if (suppress_message_printing(msg->level)) {
-			/*
-			 * Skip record we have buffered and already printed
-			 * directly to the console when we received it, and
-			 * record that has level above the console loglevel.
-			 */
+		/* Get the next message with a visible level */
+		while (console_seq < log_next_seq && !printed_msg) {
+			printed_msg = console_check_and_print_msg(console_seq,
+					text + len, sizeof(text) - len, &len,
+					ext_text, sizeof(ext_text), &ext_len);
+
 			console_idx = log_next(console_idx);
 			console_seq++;
-			goto skip;
 		}
 
-		len += msg_print_text(msg, false, text + len, sizeof(text) - len);
-		if (nr_ext_console_drivers) {
-			ext_len = msg_print_ext_header(ext_text,
-						sizeof(ext_text),
-						msg, console_seq);
-			ext_len += msg_print_ext_body(ext_text + ext_len,
-						sizeof(ext_text) - ext_len,
-						log_dict(msg), msg->dict_len,
-						log_text(msg), msg->text_len);
-		}
-		console_idx = log_next(console_idx);
-		console_seq++;
+		/* No warning and no visible message => done */
+		if (!len && !printed_msg)
+			break;
+
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-- 
1.8.5.6

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

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

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.


[..]
> The best solution seems to be to print the warning with
> the next visible message.

not sure.

	-ss

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

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

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? The console_level is there for a reason.

If there is a flood of messages, console_level = 1 and use your
solution, you might see:

** 1324 printk messages dropped ** <notice: random message>
** 4234 printk messages dropped ** <debug: random message>
** 3243 printk messages dropped ** <info: random message>
** 2343 printk messages dropped ** <debug: random message>

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>

You will see messages filtered by the console_level. Also
less number of messages should get dropped because you quickly
skip the less important ones.

The filtering might be the only way to see the important
messages. On the other hand, the fact that messages are
dropped might be quessed from the context.

Your patch fixes a bug by introducing another bug that is
probably even more serious.


I understand that my patch is much more complex. But is
the final code realy more complex?

console_unlock() is too long. The helper for the msg_print()
calls makes sense on its own. The rest is just reshufling
of the conditions.

It actually would make sense to hide also the increment
of console_idx/console_seq into the helper function.
Especially console_idx is related to the struct printk_log
that is no longer accessed in console_unlock() directly.

Here is v2:

From 82ff26726508c8a5a97409c7270d1f7abc7ed740 Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Tue, 3 Jan 2017 14:32:04 +0100
Subject: [PATCH v2] printk: Always report lost messages on serial console

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.

A simple solution would be to ignore the level and always print
the warning with the next message.

But the situation suggests that we are under a high load and
could not afford printing less important messages.

Also we could not print only the warning because we might lose
even more messages in the meantime.

The best solution seems to be to print the warning with
the next visible message.

This patch tries to keep readability of the code. It puts
msg_print*() calls into a helper function. Also it hides there
the visibility check and increment of console_idx/console_seq.

Reported-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 70 +++++++++++++++++++++++++++++---------------------
 1 file changed, 41 insertions(+), 29 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0dbde4e7bb15..ae80dc3284dc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2161,6 +2161,35 @@ static inline int can_use_console(void)
 	return cpu_online(raw_smp_processor_id()) || have_callable_console();
 }
 
+static bool console_check_and_print_next_msg(
+		char *text, size_t size, size_t *len,
+		char *ext_text, size_t ext_size, size_t *ext_len)
+{
+	struct printk_log *msg = log_from_idx(console_idx);
+	bool ret = true;
+
+	if (suppress_message_printing(msg->level)) {
+		ret = false;
+		goto out;
+	}
+
+	*len += msg_print_text(msg, false, text, size);
+	if (nr_ext_console_drivers) {
+		*ext_len = msg_print_ext_header(ext_text, ext_size,
+						msg, console_seq);
+		*ext_len += msg_print_ext_body(ext_text + *ext_len,
+					       ext_size - *ext_len,
+					       log_dict(msg), msg->dict_len,
+					       log_text(msg), msg->text_len);
+	}
+
+out:
+	console_idx = log_next(console_idx);
+	console_seq++;
+
+	return ret;
+}
+
 /**
  * console_unlock - unlock the console system
  *
@@ -2215,9 +2244,9 @@ void console_unlock(void)
 	}
 
 	for (;;) {
-		struct printk_log *msg;
+		bool visible_msg = false;
 		size_t ext_len = 0;
-		size_t len;
+		size_t len = 0;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
@@ -2232,37 +2261,20 @@ void console_unlock(void)
 			/* 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)
-			break;
 
-		msg = log_from_idx(console_idx);
-		if (suppress_message_printing(msg->level)) {
-			/*
-			 * Skip record we have buffered and already printed
-			 * directly to the console when we received it, and
-			 * record that has level above the console loglevel.
-			 */
-			console_idx = log_next(console_idx);
-			console_seq++;
-			goto skip;
-		}
+		/* Get the next message with a visible level */
+		while (console_seq < log_next_seq && !visible_msg) {
+			visible_msg = console_check_and_print_next_msg(
+					text + len, sizeof(text) - len, &len,
+					ext_text, sizeof(ext_text), &ext_len);
 
-		len += msg_print_text(msg, false, text + len, sizeof(text) - len);
-		if (nr_ext_console_drivers) {
-			ext_len = msg_print_ext_header(ext_text,
-						sizeof(ext_text),
-						msg, console_seq);
-			ext_len += msg_print_ext_body(ext_text + ext_len,
-						sizeof(ext_text) - ext_len,
-						log_dict(msg), msg->dict_len,
-						log_text(msg), msg->text_len);
 		}
-		console_idx = log_next(console_idx);
-		console_seq++;
+
+		/* No warning and no visible message => done */
+		if (!len && !visible_msg)
+			break;
+
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-- 
1.8.5.6

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web